finddelays.pl

#!/usr/bin/perl 
# How it works: We're looking at 2 important pieces of information in this script. A thread id, and an event in the logs.
# For every log line, we update the correspending thread hash with a new start time. 
# When we see an "ARRAY" line, we calculate the thread sleep time based on the last "start" and the current log time. 
# This tells us how long asterisk was waiting on that query. The script can be modified to look for things other than "ARRAY".
use strict;
use warnings;
use Time::Piece;
use feature 'say';
use POSIX qw(strftime);
my $file = $ARGV[0];
open (MYFILE, '>>log.txt');
my $interval = 600;
if (not defined $file) {
  die "Need filename to process.\n";
}
if (defined $ARGV[1]) {
	if ($ARGV[1] eq "fetch" ) {
		my $date = strftime "%Y%m%d", localtime;
		my $fetch = "scp voiceaxis\@$ARGV[0]:/var/log/asterisk/full $ARGV[0]-$date";
		$file = $file."-".$date;
		`$fetch`;
	}
	if ($ARGV[1] > 0) {
		close(MYFILE);
		open (MYFILE, ">>log$ARGV[1].txt");
	}
}
open my $info,'< :raw', $file or die "Could not open $file: $!";
say ("Time, Queries, Slow Count, Slow Seconds, Average Time");
my ($time,$thread,$count,$totalseconds, $diff, $totalthreads);
$totalseconds = 0;
my ($atime, $atotalseconds, $atotalthreads, $acount, $around, $aavg);
my @array;
$atime = "04:00:00";#Set initial interval
$atotalseconds = 0;
$atotalthreads = 0;
$acount = 0;
#my %hashes = ();
	while( my $line = <$info>)  {    
		#This should match anything in a fulllog except for comments that are manually inserted. 
		if ($line =~ /.*([0-2][0-9]:[0-5][0-9]:[0-5][0-9]).*\[(\d+)\].*$/) {
			$time = $1;
			$thread = $2;
			#Check if we should advance to the next interval.
			if (Time::Piece->strptime($time, '%H:%M:%S')->epoch > Time::Piece->strptime($atime, '%H:%M:%S')->epoch + $interval) {
				if ($atotalseconds > 0) {$aavg = sprintf("%.3f", $atotalseconds / $atotalthreads)} else {$aavg = 0};
				say ("\"$atime\", $atotalthreads, $acount, $atotalseconds, $aavg");
				if ($aavg > .3) {
					print MYFILE "$file $atime $aavg\n";
				}
				$atotalseconds = 0; $atotalthreads = 0; $atime = 0; $acount =0;;
				$atime = substr($time, 0, -2)."00";
			}		
			if (index($line, "ARRAY(") != -1) {
					#We see something that looks like a query.
					if (exists $array[$thread]) {
						#If we already have a thread for that query, we check how long it's been since we've seen that thread.
						$diff = Time::Piece->strptime($time, '%H:%M:%S')->epoch - Time::Piece->strptime($array[$thread], '%H:%M:%S')->epoch;
						if ($diff > 0) {
							$count++;$totalseconds = $totalseconds + $diff;$atotalseconds = $atotalseconds + $diff;$acount++;
						}
						$array[$thread]=0;
						$totalthreads++;
						$atotalthreads++;
					}
			}
			else
			{
				#Set the value for thread to the time of the match on that thread. 
				$array[$thread] = $time;
			}
		}
}
#say $count." delays for total of $totalseconds seconds delay out of $totalthreads queries.";
close $info;