git.rot13.org Git - log-merge/blob - mysql-slow-apache.pl

   1 #!/usr/bin/perl
   2 use warnings;
   3 use strict;
   4 use autodie;
   5 use HTTP::Date;
   6 use POSIX qw(strftime);
   7 use Data::Dump qw(dump);
   8
   9 $|=1;
  10 my $debug = $ENV{DEBUG} || 0;
  11
  12 my $t;
  13
  14 sub t_iso {
  15         return strftime("%Y-%m-%d %H:%M:%S", localtime($_[0]));
  16 }
  17
  18
  19 open(my $log_fh, '<', "/var/log/apache2/other_vhosts_access.log");
  20 sub log_time {
  21         my ( $t, $duration ) = @_;
  22         my $tell = tell($log_fh);
  23         print "XXX log_time $t ", t_iso($t) , " $tell\n" if $debug;
  24         my $found = 0;
  25         while(<$log_fh>) {
  26                 #warn "# $. $_";
  27                 if ( m/ \[(\d+[^\]]+)\] / ) {
  28                         my $t_l = str2time($1);
  29                         my $dt = $t_l - $t;
  30                         print "XXX log line ",t_iso($t_l)," $dt tell ",tell($log_fh),$/ if abs($dt) < 5 && $debug;
  31 #                       if ( $dt > -2 && $dt < 3 ) {
  32                         if ( abs( $dt ) <=  $duration ) {
  33 #                       if ( $t_l == $t or $t_l - $t < 2 ) { #abs( $t_l - $t ) < 2 ) {
  34                                 $found++;
  35                                 $tell = tell($log_fh) if $found == 1;
  36                                 if ( $debug ) {
  37                                         print "\nFOUND $tell $dt ",t_iso( $t_l ), " ", t_iso($t), " ", $_;
  38                                 } else {
  39                                         printf "FOUND %.1f %s", $dt, $_;
  40                                 }
  41                         }
  42                         if (
  43                                 (   $found && $t_l - $t > $duration * 3 ) ||
  44                                 ( ! $found && $t_l - $t > 40 ) # apache log entries come after 30s sometime
  45                         ) {     # overshoot time since logs are not always in order
  46                                 print "STOP ", t_iso($t_l), " tell $tell\n" if $debug;
  47                                 seek($log_fh, $tell, 0);
  48                                 last;
  49                         }
  50                 }
  51         }
  52         if ( ! $found ) {
  53                 print "SEEK $tell\n" if $debug;
  54                 seek($log_fh, $tell, 0);
  55         }
  56 }
  57
  58
  59 open(my $slow_fh, '<', '/var/log/mysql/mysql-slow.log');
  60 while(<$slow_fh>) {
  61         print $_;
  62         if ( m/Time:\s+(\S+)\s+(\S+)/ ) {
  63                 $t = str2time("20$1 $2");
  64         } elsif ( m/Query_time: (\S+)/ ) {
  65                 my $d = $1;
  66                 my $t_start = $t - $d;
  67                 print "XXX ",t_iso($t), " -> ", t_iso($t_start), $/ if $debug;
  68
  69                 log_time $t_start, $d;
  70         }
  71 }
  72
  73 __END__
  74 #!/bin/sh -xe
  75
  76 stdbuf -o L cat /var/log/mysql/mysql-slow.log \
  77 | stdbuf -e L tee /dev/stderr \
  78 | stdbuf -o L grep Time: \
  79 | stdbuf -o L awk '{ print "grep --line-buffered " $4 " /var/log/apache2/other_vhosts_access.log-20"$3 ; fflush(stdout); }' | sh
  80
  81 exit 0
  82
  83 zgrep Query_time /var/log/mysql/mysql-slow.log*
  84
  85 exit 0
  86
  87 grep -E '(Query_time|Time)' /var/log/mysql/mysql-slow.log