public
Last active

Real-time top-like requests-per-second average for httpd request logs - similar to apachetop

  • Download Gist
apache-logtop-README
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101
DESCRIPTION
 
logstat.pl and logtop.pl
 
These scripts show current and average request-per-second counts based on
apache access logs in real-time.
 
You can see the total requests-per-second as well as a breakdown by:
* vhost
* URL
* user agent
* or referrer.
 
You can sort by:
* number of requests in the last second
* time of last stats update
* average requests-per-second over the last one, five or fifteen minutes
 
The output shows:
* the date of the last stats update
* the last second's hits per second (hps)
* the one, five and fifteen minute hps average
* the seconds since last request
* an asterisk to mark requests hit in the last 5 seconds
* and the request's vhost, URL, user agent or referrer.
 
See also the apachetop tool - http://freshmeat.net/projects/apachetop/ and
http://packages.debian.org/search?keywords=apachetop . This script is not
based on or intended to mimic apachetop, but the functionality is broadly
similar.
 
SYNOPSIS
 
To use:
 
In one screen, run the log parser. It writes out a stats file which the
other scripts use.
 
$ cd /dev/shm # use shared memory
$ tail -F /var/log/httpd/access.log | ~/logstat.pl # centralized logging helps here
 
In another screen, view your stats:
 
$ cd /dev/shm # use shared memory
 
# defaults to vhosts sorted by five minute average
$ watch -n 5 -- ~/logtop.pl
 
or
 
# URLs sorted by five minute average, ignoring images, JS and CSS
$ watch -n 5 -- '~/logtop.pl urls \
--skip '\''\.(jpg|png|gif|js|css)$|^\S+\s(/robots\.txt$|/favicon\.ico$)'\'''
 
or
 
# user agents sorted by requests in the last second
$ watch -n 5 -- ~/logtop.pl ua --sort hps
 
or
 
# referrers sorted by one minute average
$ watch -n 5 -- ~/logtop.pl referrer --sort one
 
or
 
# URLs sorted by last stats update
$ watch -n 5 -- ~/logtop.pl urls --sort time
 
etc.
 
EXAMPLE
 
Every 5.0s: ~/logtop.pl Fri Jun 24 03:31:59 2011
 
Fri Jun 24 03:31:58 2011 hps: 2, average: 5.35, 4.45, 2.37, 0 seconds ago, total
vhosts sorted by five
Fri Jun 24 03:31:52 2011 hps: 0, average: 0.41, 0.59, 0.35, 6 seconds ago, example.com
Fri Jun 24 03:31:54 2011 hps: 1, average: 1.17, 0.58, 0.23, 4 seconds ago, * example.net
Fri Jun 24 03:31:34 2011 hps: 2, average: 0.99, 0.33, 0.12, 24 seconds ago, example.org
...
 
NOTES
 
* The script's tally sub is properly abstracted so this script could be
quite easily modified to tally and report averages on anything you can count
(not just httpd logs)
 
* The log parsing regex matches the "v-combined" log format (combined with
* the virtual host at the front)
 
* The logtop script accepts "match" and/or "skip" arguments to only show
events that match (or do not match) a given regex.
 
TODO
 
* Persist historical data and reload on restart (this can be done
* asynchronously with another client script)
 
* Persist position in log file (using ftell) to recover from where we left
off on restart (this should account for log file rotation)
logstat.pl
Perl
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266
#!/usr/bin/perl -w
 
use strict;
use warnings;
 
use Time::HiRes 'time';
use List::Util qw/sum/;
use Storable;
use Digest::MD5 'md5_hex';
#use Data::Dumper;
 
my %data; # internal (server-only) data
my %shared; # data shared with clients
my %keys; # keys to data shared with clients
 
sub init
{
my $data = $_[0];
my $shared = $_[1];
$data->{count} = 0;
$data->{counts} = [0];
$shared->{hps} = 0;
$shared->{one} = 0;
$shared->{five} = 0;
$shared->{fifteen} = 0;
init_time($data, $shared, $_[2]);
return;
}
 
sub init_time
{
# mode 0 == init all
# mode 1 == init time and second only
# mode 2 == init minute only
my $data = $_[0];
my $shared = $_[1];
my $mode = $_[3] || 0;
unless ($mode == 2) {
$shared->{time} = $_[2] || time();
}
return if $mode == 1;
$data->{minute} = $shared->{time} + 60;
return;
}
 
my $prune_every = 60 * 20; # prune every 20 minutes
my $prune_time = time() + $prune_every;
my $last_prune_took = "prune hasn't happened yet";
 
# TODO: read previous data from persistant store on restart
# (have a seprate client that persists data)
 
my $stotal = 0; # FIXME debug
 
# update this when adding new categories
my @data = qw/vhosts urls ua referrer/;
 
foreach my $key (@data) {
mkdir $key;
}
 
while (<>) {
my $nt = time();
my ($vhost, $date, $method, $url, $protocol, $alt_url, $code, $bytes,
$referrer, $ua) = (m/
^(\S+)\s # vhost
\S+\s # IP
\S+\s+ # remote logname
(?:\S+\s+)+ # remote user
\[([^]]+)\]\s # date
"(\S*)\s? # method
(?:((?:[^"]*(?:\\")?)*)\s # URL
([^"]*)"\s| # protocol
((?:[^"]*(?:\\")?)*)"\s) # or, possibly URL with no protocol
(\S+)\s # status code
(\S+)\s # bytes
"((?:[^"]*(?:\\")?)*)"\s # referrer
"(.*)"$ # user agent
/x);
die "Couldn't match $_" unless $vhost;
$alt_url ||= '';
$url ||= $alt_url;
 
# vhost counts
$data{vhosts}{$vhost} ||= $shared{vhosts}{$vhost} ||= {};
tally($data{vhosts}{$vhost}, $shared{vhosts}{$vhost}, $nt,
'vhosts', $vhost);
 
# url counts
my $vhost_url = "$vhost $url";
$data{urls}{$vhost_url} ||= $shared{urls}{$vhost_url} ||= {};
tally($data{urls}{$vhost_url}, $shared{urls}{$vhost_url}, $nt,
'urls', $vhost_url);
 
# user agent counts
$data{ua}{$ua} ||= $shared{ua}{$ua} ||= {};
tally($data{ua}{$ua}, $shared{ua}{$ua}, $nt, 'ua', $ua);
 
# referrer counts
$data{referrer}{$referrer} ||= $shared{referrer}{$referrer} ||= {};
tally($data{referrer}{$referrer}, $shared{referrer}{$referrer}, $nt,
'referrer', $referrer);
 
# TODO: status codes? bytes? (bytes would require some additional work to
# be useful)
 
# total hit count
print '.'; # FIXME debug
next unless tally(\%data, \%shared, $nt);
 
# show the last line we parsed; this can be used to confirm we're parsing
# data in real-time (and that we're parsing the log correctly)
# NOTE: the date from the apache log is the date the HTTP request
# started, but apache writes the request to the log when the request
# finishes. This means if the request took a long time to serve (e.g.
# due to a slow network) the date may be seconds or even minutes in the
# past, even though the line was actually written to the log much more
# recently than that (i.e. just now)
print "\n\nlast line parsed: [$vhost] [$date] [$method] [$url] " .
"[$protocol] [$alt_url] [$code] [$bytes] [$referrer] [$ua]\n\n";
 
# show the last second's total hits-per-second and the historical average
# and the result of the last prune
my $pt = $prune_time - $nt;
show(\%shared, sprintf(
" total\nnext prune in %.0f seconds; " .
"last $last_prune_took\n", $pt));
 
# store the total and keys to the categorized data for clients to read.
# NOTE: change the working directory to /dev/shm before starting these
# scripts to use shared memory; this can be considerably faster than
# writing the shared data to local disk
# NOTE: rename is used to atomically update the data file so clients do
# not try to read the data while we're writing it
my $nst = time(); # FIXME debug
$keys{total} = {
hps => $shared{hps},
one => $shared{one},
five => $shared{five},
fifteen => $shared{fifteen},
time => $shared{time},
};
my $entry_count = 0;
foreach my $key (@data) {
my $count = keys %{ $keys{$key} };
$entry_count += $count;
print "$count $key; ";
}
store(\%keys, 'logstats.keys.tmp');
rename('logstats.keys.tmp', 'logstats.keys');
$stotal += time() - $nst; # FIXME debug
printf "$entry_count total entries; store took %.3f seconds\n\n", $stotal;
$stotal = 0;
 
# prune old data to prevent using too much memory
# NOTE: this does block (for a hopefully short amount of time); we
# should catch back up quickly, though
next unless $pt <= 0;
$pt = time();
print "pruning data...\n";
$entry_count = 0;
my $prune_count = 0;
$prune_time = $nt + $prune_every;
foreach my $k (keys %data) {
my $v = $data{$k};
next unless (ref($v) || '') eq 'HASH';
foreach my $key (keys %$v) {
my $val = $shared{$k}{$key};
$entry_count++;
next unless (ref($val) || '') eq 'HASH'
and $nt - $val->{time} > $prune_every;
unlink("$k/" . $keys{$k}{$key});
delete $keys{$k}{$key};
delete $v->{$key};
delete $shared{$k}{$key};
$prune_count++;
}
}
my $elapsed = time() - $pt;
$last_prune_took =
sprintf "pruned $prune_count stale out of $entry_count total entries in %.3f seconds.", $elapsed;
print "$last_prune_took\n\n";
}
 
sub tally
{
my $nt = $_[2] || time();
my $init = defined $_[0]->{count};
init($_[0], $_[1], $nt) unless $init;
 
# count the event
$_[0]->{count}++;
 
# save data if this is the first time we've seen this event
save($_[0], $_[1], $_[3], $_[4]) if $_[3] && !$init;
 
# add $count to per-minute count and reset $count every second
my $diff = $nt - $_[1]->{time};
return 0 unless $diff >= 1;
 
my $data = $_[0];
my $shared = $_[1];
 
init_time($data, $shared, $nt, 1);
$shared->{hps} = $data->{count} / $diff;
$data->{count} = 0;
$data->{counts}[0] += $shared->{hps};
 
# add per-minute count to 15-minute historical data set and reset
# per-minute count every minute
$diff = $nt - $data->{minute};
if ($diff >= 0) {
init_time($data, $shared, $nt, 2);
 
# log "0" counts to historical data set if this is an infrequent stat
splice(@{$data->{counts}}, 1, 0, (0) x int($diff / 60));
 
# FIXME: reduce value of per-minute count by remainder if it's been
# over a minute (that is, add a fractional "0" count)
 
# compute historical average
unshift @{$data->{counts}}, 0;
no warnings qw/uninitialized misc/;
splice @{$data->{counts}}, 16;
$shared->{one} = $data->{counts}[1] / 60;
$shared->{five} = sum(@{$data->{counts}}[1..5]) / 5 / 60;
$shared->{fifteen} = sum(@{$data->{counts}}[1..15]) / 15 / 60;
save($data, $shared, $_[3], $_[4]) if $_[3];
return 1;
}
 
# if it hasn't been a minute yet, extrapolate a running historical average
my $count = $data->{counts}[0];
# this gets more accurate as the minute progresses,
# but it does tend to over-estimate infrequent events
$count *= 60 / ($diff + 60);
# egregious HACK - but this only matters for the first minute(s)
# after we start up
defined($data->{counts}[1]) or $data->{counts}[1] = $count;
$shared->{one} = sum($count, $data->{counts}[1]) / 2 / 60;
no warnings 'uninitialized';
$shared->{five} = sum($count, @{$data->{counts}}[1..5]) / 6 / 60;
$shared->{fifteen} = sum($count, @{$data->{counts}}[1..15]) / 16 / 60;
save($data, $shared, $_[3], $_[4]) if $_[3];
return 1;
}
 
sub show
{
my $shared = $_[0];
print scalar localtime($shared->{time});
printf " hps: %6.0f, average: %.2f, %.2f, %.2f, ",
$shared->{hps}, $shared->{one}, $shared->{five}, $shared->{fifteen};
print $_[1] || "\n";
return;
}
 
sub save
{
my $nst = time(); # FIXME debug
my $file = $_[2] . '/' . ($keys{$_[2]}{$_[3]} ||= md5_hex($_[3]));
store($_[1], "$file.tmp");
rename("$file.tmp", $file);
$stotal += time() - $nst; # FIXME debug
return;
}
logtop.pl
Perl
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82
#!/usr/bin/perl -w
 
use strict;
use warnings;
 
use Time::HiRes 'time';
use Storable;
 
use Getopt::Long;
my ($match, $skip, $match_re, $skip_re, $sort);
GetOptions(
'match=s' => \$match,
'skip=s' => \$skip,
'sort=s' => \$sort,
);
 
# time, hps, one, five or fifteen
$sort ||= 'five';
 
# vhosts, urls, ua or referrer
my $type = shift() || 'vhosts';
 
$match_re = qr/$match/i if $match;
$skip_re = qr/$skip/i if $skip;
 
# load data
my $rt = time();
my $datakeys = retrieve('logstats.keys');
 
my $data = $datakeys->{total};
foreach my $key (keys %{ $datakeys->{$type} }) {
my $md5 = $datakeys->{$type}{$key};
my $d;
# file may have been pruned; skip if we can't read it
eval { $d = retrieve("$type/$md5") };
next if $@;
$data->{$type}{$key} = $d;
}
 
my $now = time();
show($data, " total\n", $now - $data->{time});
 
printf "loaded data in %.3f seconds - $type sorted by $sort\n", $now - $rt;
 
my @stale;
foreach my $event (sort
{ $data->{$type}{$b}{$sort} <=> $data->{$type}{$a}{$sort} }
keys %{ $data->{$type} }) {
next if $skip and $event =~ m/$skip_re/;
next if $match and $event !~ m/$match_re/;
my $d = $data->{$type}{$event};
my $t = $now - $d->{time};
if ($t > 60) {
push @stale, $event;
next;
}
my $text = ' ';
if ($now - $d->{time} < 6) {
$text = " * ";
}
show($d, "$text $event\n", $t);
}
 
print "\nstale:\n" if @stale;
 
my $i = 0;
foreach my $event (@stale) {
my $d = $data->{$type}{$event};
my $t = $now - $d->{time};
show($d, " $event\n", $t);
last if ++$i > 100;
}
 
sub show
{
my $data = $_[0];
print scalar localtime($data->{time});
my $s = "s";
$s = " " if sprintf("%.0f", $_[2]) eq '1';
printf " hps: %6.0f, average: %.2f, %.2f, %.2f, %2.0f second$s ago, ", $data->{hps}, $data->{one}, $data->{five}, $data->{fifteen}, $_[2];
print $_[1] || "\n";
}

Please sign in to comment on this gist.

Something went wrong with that request. Please try again.