process-nginx-timing

#!/usr/bin/perl -w
#
# 10.136.123.58 - 112.120.89.159 - [29/Apr/2013:08:42:58 +0000] "POST /v1/command/push HTTP/1.1" 200 upstream 0.026 request 0.026 [for api-dev.env.local via 127.0.0.1:25000]
# 10.136.123.58 - 112.120.89.159 - [29/Apr/2013:08:42:59 +0000] "POST /v1/command/fetch HTTP/1.1" 200 upstream 0.016 request 0.016 [for api-dev.env.local via 127.0.0.1:25000]
#
# process-nginx-timing log/nginx/upstream-command.log
#
use strict;

use Data::Dumper ;
use Time::Local qw{timegm};
use Text::CSV_XS;

my $snap = 5 ;
my $last = 0;
my $count = 0;
my $total_count = 0;
my $unfinished = 0 ;
my %completed ;
my $min_time = 0;
my $max_time = 0;
my $time = 0;
my %flags = ();
my $flag ;
my @fields = qw{ counter error other
u_max_ms u_min_ms u_tot_ms u_median u_mean u_var u_std
r_max_ms r_min_ms r_tot_ms r_median r_mean r_var r_std
} ;
my %status_codes = ();
my %months = (
    'Jan' => 0,
    'Feb' => 1,
    'Mar' => 2,
    'Apr' => 3,
    'May' => 4,
    'Jun' => 5,
    'Jul' => 6,
    'Aug' => 7,
    'Sep' => 8,
    'Oct' => 9,
    'Nov' => 10,
    'Dec' => 11,
);
while (<>) {
    chomp ;

    next if /==> / ;  #  ==> /var/log/nginx/upstream-root.log <==
    next if /^$/ ;
    # YMD HMS
    my ($y,$m,$d,$h,$i,$s) ;
    if (/^(\d{4})\/(\d{2})\/(\d{2}) (\d{2}):(\d{2}):(\d{2})/) {
        ($y,$m,$d,$h,$i,$s) = ($1, $2, $3, $4, $5, $6) ;
        $m -- ;
    } elsif (/(\d{2})\/(\w{3})\/(\d{4}):(\d{2}):(\d{2}):(\d{2})/) {
        ($y,$m,$d,$h,$i,$s) = ($3, $months{$2}, $1, $4, $5, $6) ;
    } else {
        printf("debug: unknown date: %s\n", $_);
        next;
    }

    # ($sec,$min,$hour,$mday,$mon,$year)
    $time = timegm($s,$i,$h,$d,$m,$y);

    $time = int($time  / $snap) * $snap;

    if ($time > $max_time) {
        $max_time = $time;
    }
    if ($min_time == 0) {
        $min_time = $time;
    }

    $completed{$time}{counter} ++  ;

    # "POST /v1/command/fetch HTTP/1.1" 200 upstream 0.213 request 7.616
    if (/"(?:POST|GET|PUT) ([^\?]+)(?:\?.*)? \S+" (\d+) upstream ([\d\.]+) request ([\d\.]+)/) {
        $url = $1;
        $code = $2;

        # in seconds, convert to ms
        $up_ms = $3 * 1000;
        $r_ms = $4 * 1000;

        $completed{ $time }{'u_max_ms'} = $ms if ($ms > $completed{ $time }{'u_max_ms'}) ;
        $completed{ $time }{'u_min_ms'} = $ms if ($ms < $completed{ $time }{'u_min_ms'}) ;
        $completed{ $time }{'u_tot_ms'} += $ms ;

        # See Knuth TAOCP vol 2, 3rd edition pg 232
        my $old_M = $completed{ $time }{'uM'} ;
        $completed{ $time }{'uM'} = $completed{ $time }{'uM'} + ($ms - $completed{ $time }{'uM'}) / $completed{ $time }{'hits'};
        $completed{ $time }{'uS'} = $completed{ $time }{'uS'} + ($ms - $old_M) * ($ms - $completed{ $time }{'uM'}) ;

        push @{ $completed{ $time }{'u_median_arr'} }, $ms ;

        $completed{ $time }{'r_max_ms'} = $ms if ($ms > $completed{ $time }{'r_max_ms'}) ;
        $completed{ $time }{'r_min_ms'} = $ms if ($ms < $completed{ $time }{'r_min_ms'}) ;
        $completed{ $time }{'r_tot_ms'} += $ms ;

        # See Knuth TAOCP vol 2, 3rd edition pg 232
        my $old_M = $completed{ $time }{'uM'} ;
        $completed{ $time }{'rM'} = $completed{ $time }{'rM'} + ($ms - $completed{ $time }{'rM'}) / $completed{ $time }{'hits'};
        $completed{ $time }{'rS'} = $completed{ $time }{'rS'} + ($ms - $old_M) * ($ms - $completed{ $time }{'rM'}) ;

        push @{ $completed{ $time }{'r_median_arr'} }, $ms ;


    } else {
        $completed{$time}{'other'} ++ ;
    }




    $total_count ++
}

my $tab = Text::CSV_XS->new({ binary => 1, eol => "\n" });

$tab->print(\*STDOUT, ['time','date', @fields, sort keys %status_codes]);

for (my $idx = $min_time ; $idx < $max_time + $snap; $idx = $idx + $snap) {

    if (!exists($completed{$idx})) {
        $tab->print(\*STDOUT, [$idx, scalar gmtime($idx), map { 0 } @fields, map { 0 } keys %status_codes]);
        next;
    }

    my $rec = $completed{$idx} ;

    my $counter = $completed{$idx}{'counter'};

    my @fresults = ($idx, scalar gmtime($idx));
    foreach my $field (@fields) {
        push @fresults, $completed{$idx}{$field} || 0;
    }
    foreach my $field (sort keys %status_codes) {
        push @fresults, $completed{$idx}{$field} || 0;
    }

    $tab->print(\*STDOUT, \@fresults) ;

}