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.