10Sduke#!/usr/local/bin/perl -w 23447Skvn# 30Sduke# Script to parse the output from the unbound namedaemon. 40Sduke# Unbound supports a threading model, and outputs a multiline log-blob for 50Sduke# every thread. 60Sduke# 70Sduke# This script should parse all threads of the once, and store it 80Sduke# in a local cached file for speedy results when queried lots. 90Sduke# 100Sdukeuse strict; 110Sdukeuse POSIX qw(SEEK_END); 120Sdukeuse Storable; 130Sdukeuse FileHandle; 140Sdukeuse Carp qw(croak carp); 150Sdukeuse constant UNBOUND_CACHE => "/var/tmp/unbound-cache.stor"; 160Sduke 170Sdukemy $run_from_cron = @ARGV && $ARGV[0] eq "--cron" && shift; 180Sdukemy $DEBUG = -t STDERR; 191472Strims 201472Strims# NB. VERY IMPORTANTES: set this when running this script. 211472Strimsmy $numthreads = 4; 220Sduke 230Sduke### if cache exists, read it in. and is newer than 3 minutes 240Sdukeif ( -r UNBOUND_CACHE ) { 250Sduke my $result = retrieve(UNBOUND_CACHE); 260Sduke if (-M _ < 3/24/60 && !$run_from_cron ) { 270Sduke print STDERR "Cached results:\n" if $DEBUG; 280Sduke print join("\n", @$result), "\n"; 290Sduke exit; 300Sduke } 310Sduke} 320Sdukemy $logfile = shift or die "Usage: parseunbound.pl --cron unboundlogfile"; 330Sdukemy $in = new FileHandle $logfile or die "Cannot open $logfile: $!\n"; 340Sduke 350Sduke# there is a special key 'thread' that indicates the thread. its not used, but returned anyway. 360Sdukemy @records = ('thread', 'queries', 'cachehits', 'recursions', 'recursionavg', 370Sduke 'outstandingmax', 'outstandingavg', 'outstandingexc', 380Sduke 'median25', 'median50', 'median75', 390Sduke 'us_0', 'us_1', 'us_2', 'us_4', 'us_8', 'us_16', 'us_32', 400Sduke 'us_64', 'us_128', 'us_256', 'us_512', 'us_1024', 'us_2048', 410Sduke 'us_4096', 'us_8192', 'us_16384', 'us_32768', 'us_65536', 420Sduke 'us_131072', 'us_262144', 'us_524288', 's_1', 's_2', 's_4', 430Sduke 's_8', 's_16', 's_32', 's_64', 's_128', 's_256', 's_512'); 440Sduke# Stats hash containing one or more keys. for every thread, 1 key. 450Sdukemy %allstats = (); # key="$threadid", stats={key => value} 460Sdukemy %startstats = (); # when we got a queries entry for this thread 470Sdukemy %donestats = (); # same, but only when we got a histogram entry for it 480Sduke# stats hash contains name/value pairs of the actual numbers for that thread. 490Sdukemy $offset = 0; 508187Szmajomy $inthread=0; 518187Szmajomy $inpid; 528187Szmajo 530Sduke# We should continue looping untill we meet these conditions: 548187Szmajo# a) more total queries than the previous run (which defaults to 0) AND 550Sduke# b) parsed all $numthreads threads in the log. 560Sdukemy $numqueries = $previousresult ? $previousresult->[1] : 0; 570Sduke 588187Szmajo# Main loop 598187Szmajowhile ( scalar keys %startstats < $numthreads || scalar keys %donestats < $numthreads) { 608187Szmajo $offset += 10000; 618187Szmajo if ( $offset > -s $logfile or $offset > 10_000_000 ) { 628187Szmajo die "Cannot find stats in $logfile\n"; 630Sduke } 640Sduke $in->seek(-$offset, SEEK_END) or croak "cannot seek $logfile: $!\n"; 650Sduke 660Sduke for my $line ( <$in> ) { 670Sduke chomp($line); 680Sduke 690Sduke #[1208777234] unbound[6705:0] 700Sduke if ($line =~ m/^\[\d+\] unbound\[\d+:(\d+)\]/) { 710Sduke $inthread = $1; 720Sduke if ($inthread + 1 > $numthreads) { 730Sduke die "Hey. lazy. change \$numthreads in this script to ($inthread)\n"; 740Sduke } 753447Skvn } 768187Szmajo # this line doesn't contain a pid:thread. skip. 778187Szmajo else { 788187Szmajo next; 790Sduke } 800Sduke 810Sduke if ( $line =~ m/info: server stats for thread \d+: (\d+) queries, (\d+) answers from cache, (\d+) recursions/ ) { 820Sduke $startstats{$inthread} = 1; 830Sduke $allstats{$inthread}->{thread} = $inthread; 840Sduke $allstats{$inthread}->{queries} = $1; 850Sduke $allstats{$inthread}->{cachehits} = $2; 860Sduke $allstats{$inthread}->{recursions} = $3; 870Sduke } 880Sduke elsif ( $line =~ m/info: server stats for thread (\d+): requestlist max (\d+) avg ([0-9\.]+) exceeded (\d+)/ ) { 890Sduke $allstats{$inthread}->{outstandingmax} = $2; 900Sduke $allstats{$inthread}->{outstandingavg} = int($3); # This is a float; rrdtool only handles ints. 910Sduke $allstats{$inthread}->{outstandingexc} = $4; 920Sduke } 930Sduke elsif ( $line =~ m/info: average recursion processing time ([0-9\.]+) sec/ ) { 940Sduke $allstats{$inthread}->{recursionavg} = int($1 * 1000); # change sec to millisec. 950Sduke } 960Sduke elsif ( $line =~ m/info: histogram of recursion processing times/ ) { 970Sduke next; 980Sduke } 990Sduke elsif ( $line =~ m/info: \[25%\]=([0-9\.]+) median\[50%\]=([0-9\.]+) \[75%\]=([0-9\.]+)/ ) { 1000Sduke $allstats{$inthread}->{median25} = int($1 * 1000000); # change seconds to usec 1010Sduke $allstats{$inthread}->{median50} = int($2 * 1000000); 1020Sduke $allstats{$inthread}->{median75} = int($3 * 1000000); 1030Sduke } 1040Sduke elsif ( $line =~ m/info: lower\(secs\) upper\(secs\) recursions/ ) { 1050Sduke # since after this line we're unsure if we get these numbers 1060Sduke # at all, we should consider this marker as the end of the 1070Sduke # block. Chances that we're parsing a file halfway written 1080Sduke # at this stage are small. Bold statement. 1090Sduke $donestats{$inthread} = 1; 1100Sduke next; 1110Sduke } 1120Sduke elsif ( $line =~ m/info:\s+(\d+)\.(\d+)\s+(\d+)\.(\d+)\s+(\d+)/ ) { 1130Sduke my ($froms, $fromus, $toms, $tous, $counter) = ($1, $2, $3, $4, $5); 1140Sduke my $prefix = ''; 1150Sduke if ($froms > 0) { 1160Sduke $allstats{$inthread}->{'s_' . int($froms)} = $counter; 1170Sduke } else { 1180Sduke $allstats{$inthread}->{'us_' . int($fromus)} = $counter; 1190Sduke } 1200Sduke } 1210Sduke } 1220Sduke} 1230Sduke 1240Sdukemy @result; 1250Sduke# loop on the records we want to store 1260Sdukefor my $key ( @records ) { 1270Sduke my $sum = 0; 1280Sduke # these are the different threads parsed 1290Sduke foreach my $thread ( 0 .. $numthreads - 1 ) { 1300Sduke $sum += ($allstats{$thread}->{$key} || 0); 1310Sduke } 1320Sduke print STDERR "$key = " . $sum . "\n" if $DEBUG; 1330Sduke push @result, $sum; 1340Sduke} 1350Sdukeprint join("\n", @result), "\n"; 1360Sdukestore \@result, UNBOUND_CACHE; 1370Sduke 1380Sdukeif ($DEBUG) { 1390Sduke print STDERR "Threads: " . (scalar keys %allstats) . "\n"; 1400Sduke} 1410Sduke