1#!/usr/local/bin/perl -w 2# 3# Script to parse the output from the unbound namedaemon. 4# Unbound supports a threading model, and outputs a multiline log-blob for 5# every thread. 6# 7# This script should parse all threads of the once, and store it 8# in a local cached file for speedy results when queried lots. 9# 10use strict; 11use POSIX qw(SEEK_END); 12use Storable; 13use FileHandle; 14use Carp qw(croak carp); 15use constant UNBOUND_CACHE => "/var/tmp/unbound-cache.stor"; 16 17my $run_from_cron = @ARGV && $ARGV[0] eq "--cron" && shift; 18my $DEBUG = -t STDERR; 19 20# NB. VERY IMPORTANTES: set this when running this script. 21my $numthreads = 4; 22 23### if cache exists, read it in. and is newer than 3 minutes 24if ( -r UNBOUND_CACHE ) { 25 my $result = retrieve(UNBOUND_CACHE); 26 if (-M _ < 3/24/60 && !$run_from_cron ) { 27 print STDERR "Cached results:\n" if $DEBUG; 28 print join("\n", @$result), "\n"; 29 exit; 30 } 31} 32my $logfile = shift or die "Usage: parseunbound.pl --cron unboundlogfile"; 33my $in = new FileHandle $logfile or die "Cannot open $logfile: $!\n"; 34 35# there is a special key 'thread' that indicates the thread. its not used, but returned anyway. 36my @records = ('thread', 'queries', 'cachehits', 'recursions', 'recursionavg', 37 'outstandingmax', 'outstandingavg', 'outstandingexc', 38 'median25', 'median50', 'median75', 39 'us_0', 'us_1', 'us_2', 'us_4', 'us_8', 'us_16', 'us_32', 40 'us_64', 'us_128', 'us_256', 'us_512', 'us_1024', 'us_2048', 41 'us_4096', 'us_8192', 'us_16384', 'us_32768', 'us_65536', 42 'us_131072', 'us_262144', 'us_524288', 's_1', 's_2', 's_4', 43 's_8', 's_16', 's_32', 's_64', 's_128', 's_256', 's_512'); 44# Stats hash containing one or more keys. for every thread, 1 key. 45my %allstats = (); # key="$threadid", stats={key => value} 46my %startstats = (); # when we got a queries entry for this thread 47my %donestats = (); # same, but only when we got a histogram entry for it 48# stats hash contains name/value pairs of the actual numbers for that thread. 49my $offset = 0; 50my $inthread=0; 51my $inpid; 52 53# We should continue looping untill we meet these conditions: 54# a) more total queries than the previous run (which defaults to 0) AND 55# b) parsed all $numthreads threads in the log. 56my $numqueries = $previousresult ? $previousresult->[1] : 0; 57 58# Main loop 59while ( scalar keys %startstats < $numthreads || scalar keys %donestats < $numthreads) { 60 $offset += 10000; 61 if ( $offset > -s $logfile or $offset > 10_000_000 ) { 62 die "Cannot find stats in $logfile\n"; 63 } 64 $in->seek(-$offset, SEEK_END) or croak "cannot seek $logfile: $!\n"; 65 66 for my $line ( <$in> ) { 67 chomp($line); 68 69 #[1208777234] unbound[6705:0] 70 if ($line =~ m/^\[\d+\] unbound\[\d+:(\d+)\]/) { 71 $inthread = $1; 72 if ($inthread + 1 > $numthreads) { 73 die "Hey. lazy. change \$numthreads in this script to ($inthread)\n"; 74 } 75 } 76 # this line doesn't contain a pid:thread. skip. 77 else { 78 next; 79 } 80 81 if ( $line =~ m/info: server stats for thread \d+: (\d+) queries, (\d+) answers from cache, (\d+) recursions/ ) { 82 $startstats{$inthread} = 1; 83 $allstats{$inthread}->{thread} = $inthread; 84 $allstats{$inthread}->{queries} = $1; 85 $allstats{$inthread}->{cachehits} = $2; 86 $allstats{$inthread}->{recursions} = $3; 87 } 88 elsif ( $line =~ m/info: server stats for thread (\d+): requestlist max (\d+) avg ([0-9\.]+) exceeded (\d+)/ ) { 89 $allstats{$inthread}->{outstandingmax} = $2; 90 $allstats{$inthread}->{outstandingavg} = int($3); # This is a float; rrdtool only handles ints. 91 $allstats{$inthread}->{outstandingexc} = $4; 92 } 93 elsif ( $line =~ m/info: average recursion processing time ([0-9\.]+) sec/ ) { 94 $allstats{$inthread}->{recursionavg} = int($1 * 1000); # change sec to millisec. 95 } 96 elsif ( $line =~ m/info: histogram of recursion processing times/ ) { 97 next; 98 } 99 elsif ( $line =~ m/info: \[25%\]=([0-9\.]+) median\[50%\]=([0-9\.]+) \[75%\]=([0-9\.]+)/ ) { 100 $allstats{$inthread}->{median25} = int($1 * 1000000); # change seconds to usec 101 $allstats{$inthread}->{median50} = int($2 * 1000000); 102 $allstats{$inthread}->{median75} = int($3 * 1000000); 103 } 104 elsif ( $line =~ m/info: lower\(secs\) upper\(secs\) recursions/ ) { 105 # since after this line we're unsure if we get these numbers 106 # at all, we should consider this marker as the end of the 107 # block. Chances that we're parsing a file halfway written 108 # at this stage are small. Bold statement. 109 $donestats{$inthread} = 1; 110 next; 111 } 112 elsif ( $line =~ m/info:\s+(\d+)\.(\d+)\s+(\d+)\.(\d+)\s+(\d+)/ ) { 113 my ($froms, $fromus, $toms, $tous, $counter) = ($1, $2, $3, $4, $5); 114 my $prefix = ''; 115 if ($froms > 0) { 116 $allstats{$inthread}->{'s_' . int($froms)} = $counter; 117 } else { 118 $allstats{$inthread}->{'us_' . int($fromus)} = $counter; 119 } 120 } 121 } 122} 123 124my @result; 125# loop on the records we want to store 126for my $key ( @records ) { 127 my $sum = 0; 128 # these are the different threads parsed 129 foreach my $thread ( 0 .. $numthreads - 1 ) { 130 $sum += ($allstats{$thread}->{$key} || 0); 131 } 132 print STDERR "$key = " . $sum . "\n" if $DEBUG; 133 push @result, $sum; 134} 135print join("\n", @result), "\n"; 136store \@result, UNBOUND_CACHE; 137 138if ($DEBUG) { 139 print STDERR "Threads: " . (scalar keys %allstats) . "\n"; 140} 141