1238106Sdes#!/usr/local/bin/perl -w 2238106Sdes# 3238106Sdes# Script to parse the output from the unbound namedaemon. 4238106Sdes# Unbound supports a threading model, and outputs a multiline log-blob for 5238106Sdes# every thread. 6238106Sdes# 7238106Sdes# This script should parse all threads of the once, and store it 8238106Sdes# in a local cached file for speedy results when queried lots. 9238106Sdes# 10238106Sdesuse strict; 11238106Sdesuse POSIX qw(SEEK_END); 12238106Sdesuse Storable; 13238106Sdesuse FileHandle; 14238106Sdesuse Carp qw(croak carp); 15238106Sdesuse constant UNBOUND_CACHE => "/var/tmp/unbound-cache.stor"; 16238106Sdes 17238106Sdesmy $run_from_cron = @ARGV && $ARGV[0] eq "--cron" && shift; 18238106Sdesmy $DEBUG = -t STDERR; 19238106Sdes 20238106Sdes# NB. VERY IMPORTANTES: set this when running this script. 21238106Sdesmy $numthreads = 4; 22238106Sdes 23238106Sdes### if cache exists, read it in. and is newer than 3 minutes 24238106Sdesif ( -r UNBOUND_CACHE ) { 25238106Sdes my $result = retrieve(UNBOUND_CACHE); 26238106Sdes if (-M _ < 3/24/60 && !$run_from_cron ) { 27238106Sdes print STDERR "Cached results:\n" if $DEBUG; 28238106Sdes print join("\n", @$result), "\n"; 29238106Sdes exit; 30238106Sdes } 31238106Sdes} 32238106Sdesmy $logfile = shift or die "Usage: parseunbound.pl --cron unboundlogfile"; 33238106Sdesmy $in = new FileHandle $logfile or die "Cannot open $logfile: $!\n"; 34238106Sdes 35238106Sdes# there is a special key 'thread' that indicates the thread. its not used, but returned anyway. 36238106Sdesmy @records = ('thread', 'queries', 'cachehits', 'recursions', 'recursionavg', 37238106Sdes 'outstandingmax', 'outstandingavg', 'outstandingexc', 38238106Sdes 'median25', 'median50', 'median75', 39238106Sdes 'us_0', 'us_1', 'us_2', 'us_4', 'us_8', 'us_16', 'us_32', 40238106Sdes 'us_64', 'us_128', 'us_256', 'us_512', 'us_1024', 'us_2048', 41238106Sdes 'us_4096', 'us_8192', 'us_16384', 'us_32768', 'us_65536', 42238106Sdes 'us_131072', 'us_262144', 'us_524288', 's_1', 's_2', 's_4', 43238106Sdes 's_8', 's_16', 's_32', 's_64', 's_128', 's_256', 's_512'); 44238106Sdes# Stats hash containing one or more keys. for every thread, 1 key. 45238106Sdesmy %allstats = (); # key="$threadid", stats={key => value} 46238106Sdesmy %startstats = (); # when we got a queries entry for this thread 47238106Sdesmy %donestats = (); # same, but only when we got a histogram entry for it 48238106Sdes# stats hash contains name/value pairs of the actual numbers for that thread. 49238106Sdesmy $offset = 0; 50238106Sdesmy $inthread=0; 51238106Sdesmy $inpid; 52238106Sdes 53238106Sdes# We should continue looping untill we meet these conditions: 54238106Sdes# a) more total queries than the previous run (which defaults to 0) AND 55238106Sdes# b) parsed all $numthreads threads in the log. 56238106Sdesmy $numqueries = $previousresult ? $previousresult->[1] : 0; 57238106Sdes 58238106Sdes# Main loop 59238106Sdeswhile ( scalar keys %startstats < $numthreads || scalar keys %donestats < $numthreads) { 60238106Sdes $offset += 10000; 61238106Sdes if ( $offset > -s $logfile or $offset > 10_000_000 ) { 62238106Sdes die "Cannot find stats in $logfile\n"; 63238106Sdes } 64238106Sdes $in->seek(-$offset, SEEK_END) or croak "cannot seek $logfile: $!\n"; 65238106Sdes 66238106Sdes for my $line ( <$in> ) { 67238106Sdes chomp($line); 68238106Sdes 69238106Sdes #[1208777234] unbound[6705:0] 70238106Sdes if ($line =~ m/^\[\d+\] unbound\[\d+:(\d+)\]/) { 71238106Sdes $inthread = $1; 72238106Sdes if ($inthread + 1 > $numthreads) { 73238106Sdes die "Hey. lazy. change \$numthreads in this script to ($inthread)\n"; 74238106Sdes } 75238106Sdes } 76238106Sdes # this line doesn't contain a pid:thread. skip. 77238106Sdes else { 78238106Sdes next; 79238106Sdes } 80238106Sdes 81238106Sdes if ( $line =~ m/info: server stats for thread \d+: (\d+) queries, (\d+) answers from cache, (\d+) recursions/ ) { 82238106Sdes $startstats{$inthread} = 1; 83238106Sdes $allstats{$inthread}->{thread} = $inthread; 84238106Sdes $allstats{$inthread}->{queries} = $1; 85238106Sdes $allstats{$inthread}->{cachehits} = $2; 86238106Sdes $allstats{$inthread}->{recursions} = $3; 87238106Sdes } 88238106Sdes elsif ( $line =~ m/info: server stats for thread (\d+): requestlist max (\d+) avg ([0-9\.]+) exceeded (\d+)/ ) { 89238106Sdes $allstats{$inthread}->{outstandingmax} = $2; 90238106Sdes $allstats{$inthread}->{outstandingavg} = int($3); # This is a float; rrdtool only handles ints. 91238106Sdes $allstats{$inthread}->{outstandingexc} = $4; 92238106Sdes } 93238106Sdes elsif ( $line =~ m/info: average recursion processing time ([0-9\.]+) sec/ ) { 94356345Scy $allstats{$inthread}->{recursionavg} = int($1 * 1000); # change sec to millisec. 95238106Sdes } 96238106Sdes elsif ( $line =~ m/info: histogram of recursion processing times/ ) { 97238106Sdes next; 98238106Sdes } 99238106Sdes elsif ( $line =~ m/info: \[25%\]=([0-9\.]+) median\[50%\]=([0-9\.]+) \[75%\]=([0-9\.]+)/ ) { 100238106Sdes $allstats{$inthread}->{median25} = int($1 * 1000000); # change seconds to usec 101238106Sdes $allstats{$inthread}->{median50} = int($2 * 1000000); 102238106Sdes $allstats{$inthread}->{median75} = int($3 * 1000000); 103238106Sdes } 104238106Sdes elsif ( $line =~ m/info: lower\(secs\) upper\(secs\) recursions/ ) { 105238106Sdes # since after this line we're unsure if we get these numbers 106356345Scy # at all, we should consider this marker as the end of the 107238106Sdes # block. Chances that we're parsing a file halfway written 108238106Sdes # at this stage are small. Bold statement. 109238106Sdes $donestats{$inthread} = 1; 110238106Sdes next; 111238106Sdes } 112238106Sdes elsif ( $line =~ m/info:\s+(\d+)\.(\d+)\s+(\d+)\.(\d+)\s+(\d+)/ ) { 113238106Sdes my ($froms, $fromus, $toms, $tous, $counter) = ($1, $2, $3, $4, $5); 114238106Sdes my $prefix = ''; 115238106Sdes if ($froms > 0) { 116238106Sdes $allstats{$inthread}->{'s_' . int($froms)} = $counter; 117238106Sdes } else { 118238106Sdes $allstats{$inthread}->{'us_' . int($fromus)} = $counter; 119238106Sdes } 120238106Sdes } 121238106Sdes } 122238106Sdes} 123238106Sdes 124238106Sdesmy @result; 125238106Sdes# loop on the records we want to store 126238106Sdesfor my $key ( @records ) { 127238106Sdes my $sum = 0; 128238106Sdes # these are the different threads parsed 129238106Sdes foreach my $thread ( 0 .. $numthreads - 1 ) { 130238106Sdes $sum += ($allstats{$thread}->{$key} || 0); 131238106Sdes } 132238106Sdes print STDERR "$key = " . $sum . "\n" if $DEBUG; 133238106Sdes push @result, $sum; 134238106Sdes} 135238106Sdesprint join("\n", @result), "\n"; 136238106Sdesstore \@result, UNBOUND_CACHE; 137238106Sdes 138238106Sdesif ($DEBUG) { 139238106Sdes print STDERR "Threads: " . (scalar keys %allstats) . "\n"; 140238106Sdes} 141