I’m pricing out DNS providers and was asked what our current queries-per-second currently are. Sadly I had no idea. After lots of Googling I decided there was really no good way to get this information so I decided to parse the logfile myself. First, I turned on logging with timestamp in named.conf:

logging
{
...
        # Query logging 2010-12-07
        channel query-log {
                file "data/queries.log" versions 3 size 10m;
                print-time yes;
        };
        category queries { query-log; };
};
options
{
...
        # Query logging 2010-12-07
        querylog yes;

};

Then I restarted named and had to figure out how to parse the file. My first guess was Perl and it didn’t disappoint. Here’s the hideous mess of code:

parsebind.pl

#!/usr/bin/perl

#use Date::Parse; use Time::ParseDate;

my $line_num = 0; my $first_line = 0; my $oldest_record = 0; my $line = ‘’; my $date = 0;

my %query_counter = {}; my @abbr = qw( Jan Feb Mar Apr May Jun Jul Aug Sep Oct Nov Dec );

while () { chomp; $line = $_;

#my ($date, $time, $ip, $hostname, $in, $type, $crap) = $line =~ m/^([\d]{2}-[\w]{3}-[\d]{4}) ([\d]{2}:[\d]{2}:[\d]{2}.[\d]{3}) client ([\d.]+)#[\d]: [\w]+: ([\w\d.]+) ([\w]+) ([\w]+) ([.])/; if ($line =~ m/^([\d]{2}-[\w]{3}-[\d]{4}) ([\d]{2}:[\d]{2}:[\d]{2}.[\d]{3}) client ([\d.]+)#[\d]: [\w]+: ([\w\d.]+) ([\w]+) ([\w]+) ([.])/) { $date = parsedate("$1 $2");

print “$1 $2 => $date\n”;

if ($oldest_record == 0) { $oldest_record = $date; $first_line = $line_num; print “First line:\t$line_num\tdate\t”.localtime($date)."\n"; } my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime($date); $year += 1900; $mon += 1; my $key = $year . ‘-’ . sprintf(’%02d’,$mon) . ‘-’ . sprintf(’%02d’,$mday). ’ ‘.sprintf(’%02d’,$hour).’:00 to ‘.sprintf(’%02d’,$hour).’:59’ ;

if ($query_counter{$key}) { $query_counter{$key}++; } else { $query_counter{$key} = 1; } } $line_num++; }

print “Last line:\t$line_num\tdate\t”.localtime($date)."\n";

my $elapsed = $date - $oldest_record; my $net_records = $line_num - $first_line; my $rate = ($net_records * 1.0) / $elapsed;

print “Rate for $elapsed seconds: “.sprintf(’%0.2f’,$rate).” per second\n”; print “\n\n”;

foreach my $key (sort keys %query_counter) { $rate = ($query_counter{$key} * 1.0) / 3600; print “$key => $query_counter{$key}, rate “.sprintf(’%0.3f’,$rate).” queries/sec\n”; }

exit 0;

And the beautiful output:

[root@ns3 ~]# perl ~evan/parsebind.pl /var/named/chroot/var/named/data/queries.log
First line:	308	date	Tue Dec  7 17:56:02 2010
Last line:	41289	date	Tue Dec  7 22:44:01 2010
Rate for 17279 seconds: 2.37 per second

2010-12-07 17:00 to 17:59 => 533, rate 0.148 queries/sec 2010-12-07 18:00 to 18:59 => 9185, rate 2.551 queries/sec 2010-12-07 19:00 to 19:59 => 8618, rate 2.394 queries/sec 2010-12-07 20:00 to 20:59 => 8075, rate 2.243 queries/sec 2010-12-07 21:00 to 21:59 => 8762, rate 2.434 queries/sec 2010-12-07 22:00 to 22:59 => 5808, rate 1.613 queries/sec HASH(0x112382a0) => , rate 0.000 queries/sec [root@ns3 ~]#

Not pretty but good enough to get a sense of QPS. Hope it helps someone.

Edit: It occurred to me that you may have more than one domain on a single bind server, and you may want the stats for a single one (rather than all aggregated together, which the above script does). The below version includes the second-level domain in the hash key for the final report:

#!/usr/bin/perl

#use Date::Parse; use Time::ParseDate;

my $line_num = 0; my $first_line = 0; my $oldest_record = 0; my $line = ‘’; my $date = 0;

my %query_counter = {}; my @abbr = qw( Jan Feb Mar Apr May Jun Jul Aug Sep Oct Nov Dec );

while () { chomp; $line = $_;

#my ($date, $time, $ip, $hostname, $in, $type, $crap) = $line =~ m/^([\d]{2}-[\w]{3}-[\d]{4}) ([\d]{2}:[\d]{2}:[\d]{2}.[\d]{3}) client ([\d.]+)#[\d]: [\w]+: ([\w\d.]+) ([\w]+) ([\w]+) ([.])/; if ($line =~ m/^([\d]{2}-[\w]{3}-[\d]{4}) ([\d]{2}:[\d]{2}:[\d]{2}.[\d]{3}) client ([\d.]+)#[\d]: [\w]+: ([\w\d.]+) ([\w]+) ([\w]+) ([.])/) { $date = parsedate("$1 $2"); my ($domain) = ($4 =~ m/([\w\d-]+.[\w]+)$/); $domain = lc($domain);

print “$1 $2 => $date\n”;

if ($oldest_record == 0) { $oldest_record = $date; $first_line = $line_num; print “First line:\t$line_num\tdate\t”.localtime($date)."\n"; } my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime($date); $year += 1900; $mon += 1; my $key = $domain .’ ‘.$year . ‘-’ . sprintf(’%02d’,$mon) . ‘-’ . sprintf(’%02d’,$mday). ’ ‘.sprintf(’%02d’,$hour).’:00 to ‘.sprintf(’%02d’,$hour).’:59’ ;

if ($query_counter{$key}) { $query_counter{$key}++; } else { $query_counter{$key} = 1; } } $line_num++; }

print “Last line:\t$line_num\tdate\t”.localtime($date)."\n";

my $elapsed = $date - $oldest_record; my $net_records = $line_num - $first_line; my $rate = ($net_records * 1.0) / $elapsed;

print “Rate for $elapsed seconds: “.sprintf(’%0.2f’,$rate).” per second\n”; print “\n\n”;

foreach my $key (sort keys %query_counter) { $rate = ($query_counter{$key} * 1.0) / 3600; print “$key => $query_counter{$key}, rate “.sprintf(’%0.3f’,$rate).” queries/sec\n”; }

exit 0;

I suppose this doesn’t account for PTR (reverse DNS) lookups, but oh well.

Edit: I added some lame ASCII graphing functionality to the script, check it out in this post.