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+[^\]]+)\] \S+ (\S+)/ ) {
  28                         my $t_l = str2time($1);
  29                         my $url = $2;
  30                         my $dt = $t_l - $t;
  31                         print "XXX log line ",t_iso($t_l)," $dt tell ",tell($log_fh),$/ if abs($dt) < 5 && $debug;
  32                         if ( abs( $dt ) <=  $duration && $url =~ m/cgi/ ) {
  33                                 $found++;
  34                                 $tell = tell($log_fh) if $found == 1;
  35                                 if ( $debug ) {
  36                                         print "\nFOUND $tell $dt ",t_iso( $t_l ), " ", t_iso($t), " ", $_;
  37                                 } else {
  38                                         printf "FOUND %4.1f %s", $dt, $_;
  39                                 }
  40                         }
  41                         if (
  42                                 (   $found && $t_l - $t > $duration * 3 ) ||
  43                                 ( ! $found && $t_l - $t > 90 ) # apache log entries come after more than 60s sometime
  44                         ) {     # overshoot time since logs are not always in order
  45                                 print "STOP ", t_iso($t_l), " tell $tell\n" if $debug;
  46                                 seek($log_fh, $tell, 0);
  47                                 last;
  48                         }
  49                 }
  50         }
  51         if ( ! $found ) {
  52                 print "SEEK $tell\n" if $debug;
  53                 seek($log_fh, $tell, 0);
  54         }
  55 }
  56
  57
  58 my $sql;
  59 my $sql_count = 0;
  60 my $in_sql = 0;
  61
  62 open(my $slow_fh, '<', '/var/log/mysql/mysql-slow.log');
  63 while(<$slow_fh>) {
  64         print $_;
  65         if ( m/Time:\s+(\S+)\s+(\S+)/ ) {
  66                 $t = str2time("20$1 $2");
  67         } elsif ( m/Query_time: (\S+)/ ) {
  68                 my $d = $1;
  69                 my $t_start = $t - $d;
  70                 print "XXX ",t_iso($t), " -> ", t_iso($t_start), $/ if $debug;
  71
  72                 log_time $t_start, $d;
  73         } elsif ( m/SET timestamp=(\d+);/ ) {
  74                 $in_sql = $1;
  75         } elsif ( $in_sql ) {
  76                 $sql .= $_;
  77                 if ( m/;/ ) {
  78                         $in_sql = 0;
  79                         open(my $sql_fh, '>', t_iso($t) . "-$in_sql-$sql_count.sql");
  80                         print $sql_fh $sql;
  81                         close $sql_fh;
  82                         $sql_count++;
  83                         $sql = '';
  84                 }
  85         }
  86 }
  87