Stupid hack to track response times with b2g requests when NSPR_LOG_MODULES is enabled in this way.

gistfile1.pl

use strict;
$| = 1;

# Stupid hack to track response times with b2g requests.
# You need to set 'export NSPR_LOG_MODULES=timestamp,cookie:5,nsSocketTransport:5,nsHttp:5'
# in /system/bin/b2g.sh. See https://gist.github.com/4490638 (but probably will
# want to remove the busybox section, installed from /home/jrgm ;-) ).
#
# usage: `adb logcat | tee /tmp/raw.txt | perl thisfile.pl`

use Date::Parse qw(str2time);

my $trans = {};
my $curr_id;
my $in_request;
my $req_token;
my $THRESHOLD_TIME = 3.0;

# I/PRLog   (  480): 2013-01-08 22:25:15.260678 UTC - 1074390264[40404160]: nsHttpTransaction::Init [this=4779c6b0 caps=1]
# I/PRLog   (  480): 2013-01-08 22:25:29.268521 UTC - 26759120[40404470]: nsHttpTransaction::HandleContentStart [this=4779c6b0]

OUTER: while (<STDIN>) {
    if (/(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d+)\s+.*nsHttpTransaction::Init \[this=(\w+)\s/) {
        my ($time, $id) = ($1, $2);
        print;
        $curr_id = $id;
        $trans->{$id}->{starttime} = str2time($time);
        printf("[%s] Starting: %8s\n", $time, $id);
    }

    if (/(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d+)\s+.*nsHttpTransaction::HandleContentStart \[this=(\w+)\]/) {
        my ($time, $id) = ($1, $2);
        print;
        if ($trans->{$id} && $trans->{$id}->{starttime}) {
            my $duration = str2time($time) - $trans->{$id}->{starttime};
            my $stars = $duration > $THRESHOLD_TIME ? "*****" : "";
            my $request = $trans->{$id}->{request} || '';
            my $host = $trans->{$id}->{host} || '';
            printf("[%s] Duration: %6.3f %8s %5s (%s -> %s)\n",
                   $time, $duration, $id, $stars, $host, $request);
            delete $trans->{$id};
        }
    }

    next unless / http re/; # request or response
    $in_request = 1 if (/http request/);
    if (/\[(\S+)\]: http re/) {
        $req_token = $1;
    }
    print;

    while (<STDIN>) {
        # filter out non-http-header lines that can interleave; fragile but I
        # want the full log from logcat, so this is my hack.
        next unless /(\[$req_token\]|(?:HEAD|GET|POST))/;
        print;

        if ($in_request && /\]:\s+((?:HEAD|GET|POST)\s+[^\s]*)/) {
            $trans->{$curr_id}->{request} = $1;
        }
        if ($in_request && /\]:\s+host:\s+([^\s]*)/i) {
            $trans->{$curr_id}->{host} = $1;
        }
        if (/: ]/) {
            $in_request = 0;
            next OUTER;
        }
    }
}