A script to get the time of each requests and verify how long it took.
Example
req | [0,1[ | [1,2] | ]2,3] | ]3,4] | ]4,5] | <=10 | <=15 | >15 | min | max | req/s | time | delta
81000 | 994 | 3 | 1 | 0 | 0 | 1 | 0 | 1 | 0.0000 | 53.9 | 1530 | 11:53:43 | 0.6532200000
82000 | 993 | 4 | 1 | 1 | 1 | 0 | 0 | 0 | 0.0000 | 4.9 | 1806 | 11:53:43 | 0.5536160000
The time is in seconds, every request that took longer then 15 seconds are logged to a file called back_repo.log
where you can find the URL | and time of the request
VALEU Nereu!
Here is the code:
#!/usr/bin/perl
# Analysis of varnishlog time and slow requests, time is in seconds
# Nereu - 12/11/2013
use Time::HiRes;
$max = 0;
$min = 1;
$requests=1000;
open(VARNISHSTAT,"/usr/bin/varnishlog -i ReqEnd,RxURL |") || die "Nao consegui executar varnishstat!";
open(LOG,">back_repo.log") || die "Nao consegui criar o log(back_repo.log)";
select(LOG);
$|=1;
select(STDOUT);
$|=1;
$begin = [ Time::HiRes::gettimeofday() ];
while ( <VARNISHSTAT> ) {
split;
if ( $_[1] eq "RxURL" ) { $url{$_[0]} = $_[3]; next; }
$t=$_[8];
$n++;
if ( $t < 1 ) {
$m_1++;
} elsif ( $t <= 2 ) {
$m_2++;
} elsif ( $t <= 3 ) {
$m_3++;
} elsif ( $t <= 4 ) {
$m_4++;
} elsif ( $t <= 5 ) {
$m_5++;
} elsif ( $t <= 10 ) {
$m_10++;
} elsif ( $t <= 15 ) {
$m_15++;
} else {
$m_inf++;
}
$min = $min > $t ? $t : $min;
$max = $max < $t ? $t : $max;
if ( $t >= 15 ) { printf( LOG "%s | %d\n",$url{$_[0]},$t); }
if ( ($n%$requests)==0 ) {
$delta=Time::HiRes::tv_interval($begin);
$delta = 1 if ( $delta == 0.0 ) ;
($s, $M, $H, $wd, $m, $d, $y, $isdst) = localtime(time());
if ( ($l++%20)==0 ) {
printf("%8s | %5s | %5s | %5s | %5s | %5s | %5s | %5s | %5s | %6s | %5s | %5s | %8s | %s\n",
"req","[0,1[", "[1,2]", "]2,3]", "]3,4]", "]4,5]", "<=10", "<=15", ">15", "min", "max", "req/s", "time", "delta" );
}
printf("%8d | %5d | %5d | %5d | %5d | %5d | %5d | %5d | %5d | %01.4f | %5.1f | %5d | %02d:%02d:%02d | %.10f\n",
$n,
$m_1,
$m_2,
$m_3,
$m_4,
$m_5,
$m_10,
$m_15,
$m_inf,
$min,
$max,
$requests/$delta,
$H,$M,$s,
$delta
);
$max=$m_1=$m_2=$m_3=$m_4=$m_5=$m_10=$m_15=$m_inf=0;
$min=1;
$begin = [ Time::HiRes::gettimeofday() ];
undef %url;
}
}
close(VARNISHSTAT);