[GRLUG] log line rate counter

[Michael Mol]

A few weeks ago, I started wondering what exactly the request rate
looked like on a server, and I was pondering various ways of observing
that.

Finally, I settled on moving averages of requests per unit time, where
the update was triggered by requests instead of by a timer; It's
simpler to code that way.  To keep things even simpler,

To keep things even simpler, it would merely count the rate at which
it was fed lines on stdin.  So, really, it can do rate tracking for
anything that writes whole lines to a text file.

Fed a tail -f of apache logs, my resulting script's output looks like this:

20r/33s 40r/50s 60r/62s
20r/34s 40r/51s 60r/62s
20r/34s 40r/51s 60r/62s
20r/34s 40r/50s 60r/59s
20r/33s 40r/49s 60r/59s
20r/33s 40r/48s 60r/59s
20r/33s 40r/48s 60r/58s
20r/29s 40r/48s 60r/54s
20r/29s 40r/48s 60r/54s
20r/30s 40r/49s 60r/55s
20r/30s 40r/49s 60r/53s
20r/19s 40r/47s 60r/54s
20r/19s 40r/46s 60r/54s
20r/19s 40r/46s 60r/54s
20r/18s 40r/42s 60r/54s
20r/17s 40r/42s 60r/54s
20r/16s 40r/37s 60r/54s
20r/3s  40r/36s 60r/53s
20r/3s  40r/36s 60r/53s
20r/3s  40r/36s 60r/53s
20r/9s  40r/43s 60r/60s
20r/10s 40r/44s 60r/61s
20r/17s 40r/51s 60r/68s
20r/17s 40r/51s 60r/67s
20r/17s 40r/50s 60r/66s
20r/18s 40r/51s 60r/66s
20r/19s 40r/52s 60r/67s


Now, each lines is printed whenever the script is fed a line on STDIN.
 The format is (number of lines)r/(number of seconds)s, where the
number of seconds is how much time passed for the last (number of
lines) lines to be seen. So, for 20r/3s, it took three seconds between
the time that piece of information was printed and the time the piece
of information twenty rows back was printed.

Yeah, moving averages start looking kinda funny when you look too
close under the hood.

You may have noticed there are three colums:

20r19s 40r52s 60r67s

Each one of those is a moving average for a different length,
calculated at the same time.  The first column is 20 rows long, the
second is forty rows long, the third is sixty rows long.  20r19s means
that it took 19 seconds for 20 rows to be seen (or a hair under 1 row
per second), 40r/52s means that it took 52 seconds for the last 40
rows to be seen (or about 1.25 rows per second).  60r67s means that it
took 67s for sixty rows to be seen (or a bit under 1 row per second).

I originally had the script actually do the division, but that
complicated the code slightly; Since I'm only checking UNIX
timestamps, it's pretty easy to have (number of rows) appear in less
than a second, which means checking for div/0, etc.  It also means
formatting floating-point numbers.  I can (and did) do both, but I
honestly think this format is slightly more informative.

There are a couple variables at the beginning of the script,
bufferlimit and pointcount.  Bufferlimit identifies the number of
lines tracked at any given moment (and the number of rows in the
largest moving average), while pointcount identifies how many moving
averages to track.  With 60 lines and three points, you get an length
set of 20/40/60.  Bump it up to 100 lines with four points, and you'll
get 25/50/75/100.  Make that 10 points, and you'll get
10/20/30/40/50/60/70/80/90/100.

This code is sloppily and hastily written, as-is, and I don't care
what you do with it:

#!/usr/bin/perl -w
my $bufferlimit = 60; # Maximum number line instance times buffered.
my $pointcount = 3; # Number of points to calculate running averages for.

my @buffer;
while( <> )
{
    if ((scalar @buffer) == $bufferlimit)
    {
        pop @buffer;
    }

    unshift @buffer, (time());

    my $pointWidthIncrement = ($bufferlimit / $pointcount);

    my @delay;
    for(my $idx = 0; ($idx < scalar @buffer); ++$idx)
    {
        my $rate = 0;
        $rate = ($idx + 1) . "r/" . ($buffer[0] - $buffer[$idx]) . "s";

        push @delay, ($rate)
            if(0 == (($idx+1) % $pointWidthIncrement) );
    }

    print join("\t", @delay) . "\n";
}

-- 
:wq