From: Dobrica Pavlinusic <dpavlin@rot13.org>
Date: Mon, 20 Nov 2023 16:03:18 +0000 (+0100)
Subject: apache log entries come after 30s sometime
X-Git-Url: http://git.rot13.org/?a=commitdiff_plain;h=7ccfceff804974c8732251a57cca29cd898db047;p=log-merge

apache log entries come after 30s sometime
---

diff --git a/mysql-slow-apache.pl b/mysql-slow-apache.pl
index dbce3ca..d8b5c61 100755
--- 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;
 	}
 }