apache log entries come after 30s sometime

diff --git a/mysql-slow-apache.pl b/mysql-slow-apache.pl
index dbce3ca..d8b5c61 100755 (executable)
--- a/mysql-slow-apache.pl
+++ b/mysql-slow-apache.pl
@@ -7,6 +7,7 @@ use POSIX qw(strftime);
 use Data::Dump qw(dump);
 
 $|=1;
+my $debug = $ENV{DEBUG} || 0;
 
 my $t;
 
@@ -14,6 +15,47 @@ sub t_iso {
        return strftime("%Y-%m-%d %H:%M:%S", localtime($_[0]));
 }
 
+
+open(my $log_fh, '<', "/var/log/apache2/other_vhosts_access.log");
+sub log_time {
+       my ( $t, $duration ) = @_;
+       my $tell = tell($log_fh);
+       print "XXX log_time $t ", t_iso($t) , " $tell\n" if $debug;
+       my $found = 0;
+       while(<$log_fh>) {
+               #warn "# $. $_";
+               if ( m/ \[(\d+[^\]]+)\] / ) {
+                       my $t_l = str2time($1);
+                       my $dt = $t_l - $t;
+                       print "XXX log line ",t_iso($t_l)," $dt tell ",tell($log_fh),$/ if abs($dt) < 5 && $debug;
+#                      if ( $dt > -2 && $dt < 3 ) {
+                       if ( abs( $dt ) <=  $duration ) {
+#                      if ( $t_l == $t or $t_l - $t < 2 ) { #abs( $t_l - $t ) < 2 ) {
+                               $found++;
+                               $tell = tell($log_fh) if $found == 1;
+                               if ( $debug ) {
+                                       print "\nFOUND $tell $dt ",t_iso( $t_l ), " ", t_iso($t), " ", $_;
+                               } else {
+                                       printf "FOUND %.1f %s", $dt, $_;
+                               }
+                       }
+                       if ( 
+                               (   $found && $t_l - $t > $duration * 3 ) ||
+                               ( ! $found && $t_l - $t > 40 ) # apache log entries come after 30s sometime
+                       ) {     # overshoot time since logs are not always in order
+                               print "STOP ", t_iso($t_l), " tell $tell\n" if $debug;
+                               seek($log_fh, $tell, 0);
+                               last;
+                       }
+               }
+       }
+       if ( ! $found ) {
+               print "SEEK $tell\n" if $debug;
+               seek($log_fh, $tell, 0);
+       }
+}
+
+
 open(my $slow_fh, '<', '/var/log/mysql/mysql-slow.log');
 while(<$slow_fh>) {
        print $_;
@@ -22,25 +64,9 @@ while(<$slow_fh>) {
        } elsif ( m/Query_time: (\S+)/ ) {
                my $d = $1;
                my $t_start = $t - $d;
-               print "XXX ",t_iso($t), " -> ", t_iso($t_start), $/;
-               my $test;
-               foreach ( $t , $t_start, $t_start - 0.5 ) {
-                       $test->{ strftime("%d/%b/%Y:%H:%M:%S", localtime($_)) }++; # apache
-               }
-               print "XXX test=",dump($test),$/;
-               my $patt = join('|', sort keys %$test);
-       
-               my $cmd = "grep -E '($patt)' /var/log/apache2/other_vhosts_access.log";
-               print "XXX $cmd\n";
-               system $cmd;
-=for xxx
-               my $date_log = "/var/log/apache2/other_vhosts_access.log-20$1";
-               if ( -e $date_log ) {
-                       system "grep $2 $date_log";
-               } else {
-                       system "grep $2 /var/log/apache2/other_vhosts_access.log";
-               }
-=cut
+               print "XXX ",t_iso($t), " -> ", t_iso($t_start), $/ if $debug;
+
+               log_time $t_start, $d;
        }
 }