Hi,
one of my users made me aware of this rather unexpected behaviour
in our recursors running BIND 9.10.5-P3 on NetBSD/amd64:
It seems that every 10s, "on the clock", BIND will temporarily
increase the query response time rather drastically for a short while,
only to settle down to normal behaviour until the next 10s event.
A test I did to replicate the result was to run a shell loop with
a small sub-second sleep (yes, nonstandard):
while sleep .1; do
date +%s
dig @$recursor $query A +noadd +noauth
done > /tmp/out
Do this with a query for a name which exists and is in-cache.
Let it run for a while. Then do:
awk '/Query time:/ { qt=$4 } /^1/ { print $1 " " qt }' /tmp/out > /tmp/qt
Plot the result and see a rather wide variation in response time.
Next do
awk '{ print $1 % 10 " " $2 }' /tmp/qt > /tmp/bins
and put the result through a small perl script (attached) to give
some basic statistics, and in my case I see:
Ix mean stddev median min max
0 0.083303 0.555366 0.000000 0 16
1 0.071531 0.353116 0.000000 0 11
2 0.130875 3.170423 0.000000 0 166
3 0.075922 0.467403 0.000000 0 18
4 0.167146 3.928216 0.000000 0 167
5 0.069928 0.357949 0.000000 0 11
6 0.148990 3.536247 0.000000 0 183
7 0.090478 1.786360 0.000000 0 92
8 47.902799 109.998464 0.000000 0 479
9 0.080216 0.373228 0.000000 0 12
This I find rather surprising!
This measurement is based on some 27k samples, measured against a BIND
which processes 6-800 qps, so not overly busy, but similar behaviour
is also observed with BINDs which process only 50-150 qps, so the
query load does not appear to affect this significantly -- the result
for the two other BIND installations I've looked at were (based on 24k
and 20k samples):
Ix mean stddev median min max
0 15.031710 0.736819 15.000000 14 46
1 15.041801 1.359741 15.000000 14 77
2 15.003519 0.248714 15.000000 14 20
3 15.008326 0.258005 15.000000 14 19
4 15.018990 0.447535 15.000000 14 30
5 15.007415 0.289008 15.000000 14 20
6 31.504860 42.598276 15.000000 14 307
7 15.128158 3.613397 15.000000 14 133
8 15.055274 2.329867 15.000000 14 123
9 15.011628 0.305681 15.000000 14 20
and
Ix mean stddev median min max
0 9.015588 2.394387 9.000000 8 121
1 8.994696 2.334736 9.000000 8 124
2 8.966915 0.985907 9.000000 8 55
3 8.998417 2.259316 9.000000 8 122
4 24.782942 42.980507 9.000000 8 265
5 8.961137 0.363112 9.000000 8 17
6 8.947259 0.225413 9.000000 8 10
7 9.048827 3.174344 9.000000 8 128
8 9.004134 2.429312 9.000000 8 128
9 9.010314 2.294347 9.000000 8 121
Any idea what might be causing this? Anything I can do to remedy
the behaviour?
Best regards,
- Håvard
#! /usr/bin/perl
use strict;
use Statistics::Descriptive;
our(@d);
while(<>) {
chomp;
@_ = split;
my($i) = $_[0];
my($v) = $_[1];
if (!defined($d[$i])) {
$d[$i] = ();
}
push(@{ $d[$i] }, $v);
}
printf("Ix mean stddev median min max\n");
foreach my $i (0 .. $#d) {
my $stat = Statistics::Descriptive::Full->new();
$stat->add_data(@{ $d[$i] });
my $mean = $stat->mean;
my $stddev = $stat->standard_deviation;
my $median = $stat->median;
my $min = $stat->min;
my $max = $stat->max;
printf("%d %f %f %f %d %d\n", $i, $mean, $stddev, $median, $min, $max);
}
_______________________________________________
Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe
from this list
bind-users mailing list
bind-users@lists.isc.org
https://lists.isc.org/mailman/listinfo/bind-users
