Long recursion times

Unbound
1

Hi,

I was wondering if anyone can help me picture what sort of scenario
could result in hour-long recursion times. For example,

[1224870602] unbound[22560:0] info: server stats for thread 0: 1376
queries, 108 answers from cache, 1268 recursions
[1224870602] unbound[22560:0] info: server stats for thread 0:
requestlist max 55 avg 23.2926 exceeded 0
[1224870602] unbound[22560:0] info: average recursion processing time
58.964890 sec
[1224870602] unbound[22560:0] info: histogram of recursion processing times
[1224870602] unbound[22560:0] info: [25%]=0.0458265 median[50%]=0.116073
[75%]=0.237329
[1224870602] unbound[22560:0] info: lower(secs) upper(secs) recursions
[1224870602] unbound[22560:0] info: 0.000000 0.000001 79
[1224870602] unbound[22560:0] info: 0.004096 0.008192 2
[1224870602] unbound[22560:0] info: 0.016384 0.032768 56
[1224870602] unbound[22560:0] info: 0.032768 0.065536 34
[1224870602] unbound[22560:0] info: 0.065536 0.131072 202
[1224870602] unbound[22560:0] info: 0.131072 0.262144 284
[1224870602] unbound[22560:0] info: 0.262144 0.524288 309
[1224870602] unbound[22560:0] info: 0.524288 1.000000 69
[1224870602] unbound[22560:0] info: 1.000000 2.000000 17
[1224870602] unbound[22560:0] info: 2.000000 4.000000 7
[1224870602] unbound[22560:0] info: 4.000000 8.000000 7
[1224870602] unbound[22560:0] info: 8.000000 16.000000 5
[1224870602] unbound[22560:0] info: 16.000000 32.000000 7
[1224870602] unbound[22560:0] info: 32.000000 64.000000 8
[1224870602] unbound[22560:0] info: 64.000000 128.000000 64
[1224870602] unbound[22560:0] info: 128.000000 256.000000 53
[1224870602] unbound[22560:0] info: 256.000000 512.000000 9
[1224870602] unbound[22560:0] info: 512.000000 1024.000000 16
[1224870602] unbound[22560:0] info: 1024.000000 2048.000000 14
[1224870602] unbound[22560:0] info: 2048.000000 4096.000000 7

As you can see by the last few lines, some queries are taking a *long* time.

I run unbound on several low-traffic resolvers, all of them configured
the same, but I see times greater than 256 secs only on one of them.

I'm having trouble imagining how a query could last an hour. Just trying
to get a big-picture idea of what might be going on. Any thoughts?

2

* Pete:

I'm having trouble imagining how a query could last an hour. Just trying
to get a big-picture idea of what might be going on. Any thoughts?

Are you running NTP on those resolvers? Has the clock been reset
while these statistics were gathered?

3

Pete wrote:

As you can see by the last few lines, some queries are taking a *long* time.

I run unbound on several low-traffic resolvers, all of them configured
the same, but I see times greater than 256 secs only on one of them.

I'm having trouble imagining how a query could last an hour. Just trying
to get a big-picture idea of what might be going on. Any thoughts?

If you run unbound with high verbosity (4), then it prints out the
recursion time when the query is done. You could (conceivably) check
your logs and find out what those queries were. You might need a perl
script to find very long times or so.
  debug: query took 0.236723 sec

Best regards,
   Wouter