From: Wouter Wijngaards Date: Wed, 23 Apr 2008 06:33:12 +0000 (+0000) Subject: Parse stats with threads, from Kai. X-Git-Tag: release-0.11~5 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=9b55215eb6b4b9cee0d9c9cd58e3ddef3f8b7792;p=thirdparty%2Funbound.git Parse stats with threads, from Kai. git-svn-id: file:///svn/unbound/trunk@1065 be551aaa-1e26-0410-a405-d3ace91eadb9 --- diff --git a/contrib/parseunbound.pl b/contrib/parseunbound.pl index cd4973938..6a6a76d6f 100644 --- a/contrib/parseunbound.pl +++ b/contrib/parseunbound.pl @@ -1,115 +1,140 @@ #!/usr/local/bin/perl -w # -# Script to gather statistical info from the unbound logfile. -# NB: this script does not support multiple threads. +# Script to parse the output from the unbound namedaemon. +# Unbound supports a threading model, and outputs a multiline log-blob for +# every thread. +# +# This script should parse all threads of the once, and store it +# in a local cached file for speedy results when queried lots. # - use strict; use POSIX qw(SEEK_END); use Storable; use FileHandle; -use Data::Dumper; use Carp qw(croak carp); use constant UNBOUND_CACHE => "/var/tmp/unbound-cache.stor"; my $run_from_cron = @ARGV && $ARGV[0] eq "--cron" && shift; my $DEBUG = -t STDERR; -### if cache exists and is newer than 3 minutes -if ( -r UNBOUND_CACHE && -M _ < 3/24/60 && !$run_from_cron ) { - print STDERR "Cached results:\n" if $DEBUG; - my $result = retrieve(UNBOUND_CACHE); - print join("\n", @$result), "\n"; - exit; -} +# NB. VERY IMPORTANTES: set this when running this script. +my $numthreads = 4; +### if cache exists, read it in. and is newer than 3 minutes +if ( -r UNBOUND_CACHE ) { + my $result = retrieve(UNBOUND_CACHE); + if (-M _ < 3/24/60 && !$run_from_cron ) { + print STDERR "Cached results:\n" if $DEBUG; + print join("\n", @$result), "\n"; + exit; + } +} my $logfile = shift or die "Usage: parseunbound.pl --cron unboundlogfile"; my $in = new FileHandle $logfile or die "Cannot open $logfile: $!\n"; -# Stats array containing 1 or more stats hashes. -my @totalstats = (); -# Each stats hash contains name/value pairs of the actual numbers for that thread. -# there is a special key 'thread' that indicates the thread. -my $stats = {}; -my $inblock = 0; +# there is a special key 'thread' that indicates the thread. its not used, but returned anyway. my @records = ('thread', 'queries', 'cachehits', 'recursions', 'recursionavg', - 'outstandingmax', 'outstandingavg', 'outstandingexc', - 'median25', 'median50', 'median75', - 'us_0', 'us_1', 'us_2', 'us_4', 'us_8', 'us_16', 'us_32', 'us_64', - 'us_128', 'us_256', 'us_512', 'us_1024', 'us_2048', 'us_4096', - 'us_8192', 'us_16384', 'us_32768', 'us_65536', 'us_131072', - 'us_262144', 'us_524288', 's_1', 's_2', 's_4', 's_8', 's_16', - 's_32', 's_64', 's_128', 's_256', 's_512'); - + 'outstandingmax', 'outstandingavg', 'outstandingexc', + 'median25', 'median50', 'median75', + 'us_0', 'us_1', 'us_2', 'us_4', 'us_8', 'us_16', 'us_32', + 'us_64', 'us_128', 'us_256', 'us_512', 'us_1024', 'us_2048', + 'us_4096', 'us_8192', 'us_16384', 'us_32768', 'us_65536', + 'us_131072', 'us_262144', 'us_524288', 's_1', 's_2', 's_4', + 's_8', 's_16', 's_32', 's_64', 's_128', 's_256', 's_512'); +# Stats hash containing one or more keys. for every thread, 1 key. +my %allstats = (); # key="$threadid", stats={key => value} +my %startstats = (); # when we got a queries entry for this thread +my %donestats = (); # same, but only when we got a histogram entry for it +# stats hash contains name/value pairs of the actual numbers for that thread. my $offset = 0; +my $inthread=0; +my $inpid; -while ( !%$stats ) { +# We should continue looping untill we meet these conditions: +# a) more total queries than the previous run (which defaults to 0) AND +# b) parsed all $numthreads threads in the log. +my $numqueries = $previousresult ? $previousresult->[1] : 0; - $offset += 2500; +# Main loop +while ( scalar keys %startstats < $numthreads || scalar keys %donestats < $numthreads) { + $offset += 10000; if ( $offset > -s $logfile or $offset > 10_000_000 ) { die "Cannot find stats in $logfile\n"; } $in->seek(-$offset, SEEK_END) or croak "cannot seek $logfile: $!\n"; + for my $line ( <$in> ) { - chomp($line); - #print ">> $line\n"; + chomp($line); + + #[1208777234] unbound[6705:0] + if ($line =~ m/^\[\d+\] unbound\[\d+:(\d+)\]/) { + $inthread = $1; + if ($inthread + 1 > $numthreads) { + die "Hey. lazy. change \$numthreads in this script to ($inthread)\n"; + } + } + # this line doesn't contain a pid:thread. skip. + else { + next; + } - if ( !$inblock && $line =~ m/info: server stats for thread (\d+): (\d+) queries, (\d+) answers from cache, (\d+) recursions/ ) { - $inblock = 1; - # NB: this clears the previous stats - $stats = { - thread => $1, - queries => $2, - cachehits => $3, - recursions => $4, - }; - #print STDERR "Parsing stats from thread " . $stats->{thread} . "\n"; - } - elsif ( $inblock && $line =~ m/info: server stats for thread (\d+): requestlist max (\d+) avg ([0-9\.]+) exceeded (\d+)/ ) { - $stats->{outstandingmax} = $2; - $stats->{outstandingavg} = int($3); # This is a float; rrdtool only handles ints. - $stats->{outstandingexc} = $4; - } - if ( $inblock && $line =~ m/info: average recursion processing time ([0-9\.]+) sec/ ) { - $stats->{recursionavg} = int($1 * 1000); # change sec to milisec. - } - if ( $inblock && $line =~ m/info: histogram of recursion processing times/ ) { - next; - } - if ( $inblock && $line =~ m/info: \[25%\]=([0-9\.]+) median\[50%\]=([0-9\.]+) \[75%\]=([0-9\.]+)/ ) { - $stats->{median25} = int($1 * 1000000); # change seconds to usec - $stats->{median50} = int($2 * 1000000); - $stats->{median75} = int($3 * 1000000); - } - if ( $inblock && $line =~ m/info: lower\(secs\) upper\(secs\) recursions/ ) { - next; - } - elsif ( $inblock && $line =~ m/info:\s+(\d+)\.(\d+)\s+(\d+)\.(\d+)\s+(\d+)/ ) { - my ($froms, $fromus, $toms, $tous, $counter) = ($1, $2, $3, $4, $5); - my $prefix = ''; - if ($froms > 0) { - $stats->{'s_' . int($froms)} = $counter; - } else { - $stats->{'us_' . int($fromus)} = $counter; - } - if ($froms == '512') { - $inblock = 0; - #push @totalstats, $stats; - # or print $stats. - } - } - else { - #print STDERR "Cannot parse line: $line (unexpected, inblock=$inblock)\n"; - } + if ( $line =~ m/info: server stats for thread \d+: (\d+) queries, (\d+) answers from cache, (\d+) recursions/ ) { + $startstats{$inthread} = 1; + $allstats{$inthread}->{thread} = $inthread; + $allstats{$inthread}->{queries} = $1; + $allstats{$inthread}->{cachehits} = $2; + $allstats{$inthread}->{recursions} = $3; + } + elsif ( $line =~ m/info: server stats for thread (\d+): requestlist max (\d+) avg ([0-9\.]+) exceeded (\d+)/ ) { + $allstats{$inthread}->{outstandingmax} = $2; + $allstats{$inthread}->{outstandingavg} = int($3); # This is a float; rrdtool only handles ints. + $allstats{$inthread}->{outstandingexc} = $4; + } + elsif ( $line =~ m/info: average recursion processing time ([0-9\.]+) sec/ ) { + $allstats{$inthread}->{recursionavg} = int($1 * 1000); # change sec to milisec. + } + elsif ( $line =~ m/info: histogram of recursion processing times/ ) { + next; + } + elsif ( $line =~ m/info: \[25%\]=([0-9\.]+) median\[50%\]=([0-9\.]+) \[75%\]=([0-9\.]+)/ ) { + $allstats{$inthread}->{median25} = int($1 * 1000000); # change seconds to usec + $allstats{$inthread}->{median50} = int($2 * 1000000); + $allstats{$inthread}->{median75} = int($3 * 1000000); + } + elsif ( $line =~ m/info: lower\(secs\) upper\(secs\) recursions/ ) { + # since after this line we're unsure if we get these numbers + # at all, we sould consider this marker as the end of the + # block. Chances that we're parsing a file halfway written + # at this stage are small. Bold statement. + $donestats{$inthread} = 1; + next; + } + elsif ( $line =~ m/info:\s+(\d+)\.(\d+)\s+(\d+)\.(\d+)\s+(\d+)/ ) { + my ($froms, $fromus, $toms, $tous, $counter) = ($1, $2, $3, $4, $5); + my $prefix = ''; + if ($froms > 0) { + $allstats{$inthread}->{'s_' . int($froms)} = $counter; + } else { + $allstats{$inthread}->{'us_' . int($fromus)} = $counter; + } + } } } my @result; +# loop on the records we want to store for my $key ( @records ) { - $stats->{$key} ||= 0; - print STDERR "$key = " . $stats->{$key} . "\n" if $DEBUG; - push @result, $stats->{$key}; + my $sum = 0; + # these are the different threads parsed + foreach my $thread ( 0 .. $numthreads - 1 ) { + $sum += ($allstats{$thread}->{$key} || 0); + } + print STDERR "$key = " . $sum . "\n" if $DEBUG; + push @result, $sum; } print join("\n", @result), "\n"; store \@result, UNBOUND_CACHE; +if ($DEBUG) { + print STDERR "Threads: " . (scalar keys %allstats) . "\n"; +} diff --git a/doc/Changelog b/doc/Changelog index b72027c3b..0d914c453 100644 --- a/doc/Changelog +++ b/doc/Changelog @@ -1,3 +1,6 @@ +23 April 2008: Wouter + - parseunbound.pl contrib update from Kai Storbeck for threads. + 22 April 2008: Wouter - ignore SIGPIPE. - unit test for SIGPIPE ignore.