root/branches/release-33/tools/report-slow-request @ 1706

#!/usr/bin/perl -w

# Movable Type (r) Open Source (C) 2001-2008 Six Apart, Ltd.
# This program is distributed under the terms of the
# GNU General Public License, version 2.
#
# $Id$

use strict;

use lib "./lib";

use Getopt::Long qw/:config no_ignore_case/;
use List::Util qw( min );
use Time::HiRes qw( time );
use MT;
use MT::Util::LogProcessor;
use Data::Dumper;

GetOptions(
    'day=s'    => \my ($arg_day),
    'logdir=s' => \my ($arg_logdir),
    'sample=i' => \my ($arg_sample),
    'slow=i'   => \my ($arg_slow),
    'debug'    => \my ($arg_debug),
    'dump'     => \my ($arg_dump),
);

$arg_slow ||= 2;

my $proc = MT::Util::LogProcessor->new(
    {
        debug        => $arg_debug,
        logdir       => $arg_logdir || '.',
        sample       => $arg_sample,
        day          => $arg_day || 'yesterday',
        file_pattern => 'pl-\d{8}.log',
    }
);

my %stash = ( today => $proc->day );
my ( $total_records, $elapsed ) = $proc->process_log_files(
    sub {
        my ($rec) = @_;

        my $secs = int $rec->{time_total};

        my $bucket = $secs > 10 ? 10 : $secs;
        $stash{by_seconds}[$bucket]++;

        $stash{total_requests}++;

        if ( $secs > $arg_slow - 1 ) {
            push @{ $stash{slow} }, $rec;
        }
    }
);

printf "Processed %d records in %.02f seconds; speed: %.02f recs/sec\n",
  $total_records, $elapsed, $total_records / ( $elapsed || 1 )
  if $arg_debug;

for my $bucket ( 0 .. $#{ $stash{by_seconds} } ) {
    my $count = $stash{by_seconds}[$bucket] || 0;
    $stash{restime_histogram}[$bucket] = {
        count => $count,
        range => $bucket == 10
        ? '10+ sec'
        : $bucket . '-' . ( $bucket + 1 ) . 's',
        percent => int( $count / $stash{total_requests} * 100 ) || 1,
    };
}

$stash{slow} =
  [ sort { $b->{time_total} <=> $a->{time_total} } @{ $stash{slow} || [] } ];

report( \%stash );

sub report {
    my ($stash) = @_;

    print "Response time histogram:\n";
    for my $row ( @{ $stash->{restime_histogram} } ) {
        printf "%s: %s (%s%%)\n", $row->{range}, $row->{count}, $row->{percent};
    }

    print "Slowest requests:\n";
    for my $row ( @{ $stash->{slow} } ) {
        printf "%s\n", $row->{url};
        for my $key ( keys %$row ) {
            next if $key !~ /^time_/;
            my $secs = $row->{$key};
            next
              if $key eq 'time_mem_start'
              || $key eq 'time_mem_end'
              || $key eq 'time_total'
              || $secs < 0.01;
            printf "%s: %s\n", $key, $secs;
        }
    }
}