Maintained by: NLnet Labs

[Unbound-users] Resolving Timeouts/Issues

Dave Ellis
Thu Oct 9 16:04:04 CEST 2008


I don't believe the other threads are crashing, when I enable
statistics-interval I get 8 threads printed to the log. I went ahead and
enabled statistics-interval, with a 3 minute timer. You can see them
below, it does look like thread0 is taking most of the queries, but not
100% of them.

I also changed the config:
outgoing-range: 16384
num-queries-per-thread: 16384

----

# ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
max nice                        (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) unlimited
max locked memory       (kbytes, -l) unlimited
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) unlimited
max rt priority                 (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) unlimited
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

I'm running Debian.
# uname -a
Linux cache-ns2 2.6.18-6-686 #1 SMP Mon Aug 18 08:42:39 UTC 2008 i686
GNU/Linux


And the threads...

[1223538883] unbound[24801:2] info: server stats for thread 2: 1912
queries, 348 answers from cache, 1564 recursions
[1223538883] unbound[24801:2] info: server stats for thread 2:
requestlist max 162 avg 92.7954 exceeded 0
[1223538883] unbound[24801:2] info: average recursion processing time
1.926451 sec
[1223538883] unbound[24801:2] info: histogram of recursion processing
times
[1223538883] unbound[24801:2] info: [25%]=0.0282996
median[50%]=0.0227951 [75%]=0.126217
[1223538883] unbound[24801:2] info: lower(secs) upper(secs) recursions
[1223538883] unbound[24801:2] info:    0.000000    0.000001 51
[1223538883] unbound[24801:2] info:    0.001024    0.002048 26
[1223538883] unbound[24801:2] info:    0.002048    0.004096 12
[1223538883] unbound[24801:2] info:    0.004096    0.008192 5
[1223538883] unbound[24801:2] info:    0.008192    0.016384 10
[1223538883] unbound[24801:2] info:    0.016384    0.032768 38
[1223538883] unbound[24801:2] info:    0.032768    0.065536 242
[1223538883] unbound[24801:2] info:    0.065536    0.131072 266
[1223538883] unbound[24801:2] info:    0.131072    0.262144 299
[1223538883] unbound[24801:2] info:    0.262144    0.524288 216
[1223538883] unbound[24801:2] info:    0.524288    1.000000 109
[1223538883] unbound[24801:2] info:    1.000000    2.000000 31
[1223538883] unbound[24801:2] info:    2.000000    4.000000 10
[1223538883] unbound[24801:2] info:    4.000000    8.000000 26
[1223538883] unbound[24801:2] info:    8.000000   16.000000 38
[1223538883] unbound[24801:2] info:   16.000000   32.000000 3
[1223538883] unbound[24801:2] info:   32.000000   64.000000 6
[1223538883] unbound[24801:2] info:   64.000000  128.000000 16
[1223538883] unbound[24800:1] info: server stats for thread 1: 1976
queries, 308 answers from cache, 1668 recursions
[1223538883] unbound[24800:1] info: server stats for thread 1:
requestlist max 170 avg 96.6511 exceeded 0
[1223538883] unbound[24800:1] info: average recursion processing time
1.762582 sec
[1223538883] unbound[24800:1] info: histogram of recursion processing
times
[1223538883] unbound[24800:1] info: [25%]=0.0284219
median[50%]=0.0323609 [75%]=0.125551
[1223538883] unbound[24800:1] info: lower(secs) upper(secs) recursions
[1223538883] unbound[24800:1] info:    0.000000    0.000001 52
[1223538883] unbound[24800:1] info:    0.000512    0.001024 1
[1223538883] unbound[24800:1] info:    0.001024    0.002048 22
[1223538883] unbound[24800:1] info:    0.002048    0.004096 17
[1223538883] unbound[24800:1] info:    0.004096    0.008192 12
[1223538883] unbound[24800:1] info:    0.008192    0.016384 7
[1223538883] unbound[24800:1] info:    0.016384    0.032768 35
[1223538883] unbound[24800:1] info:    0.032768    0.065536 262
[1223538883] unbound[24800:1] info:    0.065536    0.131072 259
[1223538883] unbound[24800:1] info:    0.131072    0.262144 322
[1223538883] unbound[24800:1] info:    0.262144    0.524288 273
[1223538883] unbound[24800:1] info:    0.524288    1.000000 98
[1223538883] unbound[24800:1] info:    1.000000    2.000000 34
[1223538883] unbound[24800:1] info:    2.000000    4.000000 10
[1223538883] unbound[24800:1] info:    4.000000    8.000000 22
[1223538883] unbound[24800:1] info:    8.000000   16.000000 41
[1223538883] unbound[24800:1] info:   16.000000   32.000000 7
[1223538883] unbound[24800:1] info:   32.000000   64.000000 3
[1223538883] unbound[24800:1] info:   64.000000  128.000000 16
[1223538883] unbound[24803:4] info: server stats for thread 4: 2575
queries, 491 answers from cache, 2084 recursions
[1223538883] unbound[24803:4] info: server stats for thread 4:
requestlist max 237 avg 117.37 exceeded 0
[1223538883] unbound[24803:4] info: average recursion processing time
1.496501 sec
[1223538883] unbound[24803:4] info: histogram of recursion processing
times
[1223538883] unbound[24803:4] info: [25%]=0.0251532
median[50%]=0.0165019 [75%]=0.0889742
[1223538883] unbound[24803:4] info: lower(secs) upper(secs) recursions
[1223538883] unbound[24803:4] info:    0.000000    0.000001 55
[1223538883] unbound[24803:4] info:    0.000512    0.001024 1
[1223538883] unbound[24803:4] info:    0.001024    0.002048 25
[1223538883] unbound[24803:4] info:    0.002048    0.004096 26
[1223538883] unbound[24803:4] info:    0.004096    0.008192 20
[1223538883] unbound[24803:4] info:    0.008192    0.016384 14
[1223538883] unbound[24803:4] info:    0.016384    0.032768 38
[1223538883] unbound[24803:4] info:    0.032768    0.065536 369
[1223538883] unbound[24803:4] info:    0.065536    0.131072 324
[1223538883] unbound[24803:4] info:    0.131072    0.262144 417
[1223538883] unbound[24803:4] info:    0.262144    0.524288 288
[1223538883] unbound[24803:4] info:    0.524288    1.000000 127
[1223538883] unbound[24803:4] info:    1.000000    2.000000 36
[1223538883] unbound[24803:4] info:    2.000000    4.000000 13
[1223538883] unbound[24803:4] info:    4.000000    8.000000 22
[1223538883] unbound[24803:4] info:    8.000000   16.000000 41
[1223538883] unbound[24803:4] info:   16.000000   32.000000 12
[1223538883] unbound[24803:4] info:   32.000000   64.000000 6
[1223538883] unbound[24803:4] info:   64.000000  128.000000 15
[1223538883] unbound[24802:3] info: server stats for thread 3: 2003
queries, 366 answers from cache, 1637 recursions
[1223538883] unbound[24802:3] info: server stats for thread 3:
requestlist max 183 avg 102.059 exceeded 0
[1223538883] unbound[24802:3] info: average recursion processing time
1.823104 sec
[1223538883] unbound[24802:3] info: histogram of recursion processing
times
[1223538883] unbound[24802:3] info: [25%]=0.0254264
median[50%]=0.0645595 [75%]=0.10051
[1223538883] unbound[24802:3] info: lower(secs) upper(secs) recursions
[1223538883] unbound[24802:3] info:    0.000000    0.000001 53
[1223538883] unbound[24802:3] info:    0.001024    0.002048 24
[1223538883] unbound[24802:3] info:    0.002048    0.004096 13
[1223538883] unbound[24802:3] info:    0.004096    0.008192 15
[1223538883] unbound[24802:3] info:    0.008192    0.016384 3
[1223538883] unbound[24802:3] info:    0.016384    0.032768 30
[1223538883] unbound[24802:3] info:    0.032768    0.065536 289
[1223538883] unbound[24802:3] info:    0.065536    0.131072 302
[1223538883] unbound[24802:3] info:    0.131072    0.262144 278
[1223538883] unbound[24802:3] info:    0.262144    0.524288 208
[1223538883] unbound[24802:3] info:    0.524288    1.000000 99
[1223538883] unbound[24802:3] info:    1.000000    2.000000 36
[1223538883] unbound[24802:3] info:    2.000000    4.000000 11
[1223538883] unbound[24802:3] info:    4.000000    8.000000 20
[1223538883] unbound[24802:3] info:    8.000000   16.000000 44
[1223538883] unbound[24802:3] info:   16.000000   32.000000 7
[1223538883] unbound[24802:3] info:   64.000000  128.000000 17
[1223538883] unbound[24804:5] info: server stats for thread 5: 2051
queries, 349 answers from cache, 1702 recursions
[1223538883] unbound[24804:5] info: server stats for thread 5:
requestlist max 218 avg 114.461 exceeded 0
[1223538883] unbound[24804:5] info: average recursion processing time
2.092130 sec
[1223538883] unbound[24804:5] info: histogram of recursion processing
times
[1223538883] unbound[24804:5] info: [25%]=0.0286565
median[50%]=0.0282341 [75%]=0.135833
[1223538883] unbound[24804:5] info: lower(secs) upper(secs) recursions
[1223538883] unbound[24804:5] info:    0.000000    0.000001 42
[1223538883] unbound[24804:5] info:    0.001024    0.002048 15
[1223538883] unbound[24804:5] info:    0.002048    0.004096 20
[1223538883] unbound[24804:5] info:    0.004096    0.008192 13
[1223538883] unbound[24804:5] info:    0.008192    0.016384 13
[1223538883] unbound[24804:5] info:    0.016384    0.032768 36
[1223538883] unbound[24804:5] info:    0.032768    0.065536 265
[1223538883] unbound[24804:5] info:    0.065536    0.131072 269
[1223538883] unbound[24804:5] info:    0.131072    0.262144 318
[1223538883] unbound[24804:5] info:    0.262144    0.524288 234
[1223538883] unbound[24804:5] info:    0.524288    1.000000 126
[1223538883] unbound[24804:5] info:    1.000000    2.000000 41
[1223538883] unbound[24804:5] info:    2.000000    4.000000 6
[1223538883] unbound[24804:5] info:    4.000000    8.000000 22
[1223538883] unbound[24804:5] info:    8.000000   16.000000 34
[1223538883] unbound[24804:5] info:   16.000000   32.000000 5
[1223538883] unbound[24804:5] info:   32.000000   64.000000 3
[1223538883] unbound[24804:5] info:   64.000000  128.000000 20
[1223538883] unbound[24804:5] info:  128.000000  256.000000 1
[1223538883] unbound[24805:6] info: server stats for thread 6: 2003
queries, 415 answers from cache, 1588 recursions
[1223538883] unbound[24805:6] info: server stats for thread 6:
requestlist max 168 avg 91.5101 exceeded 0
[1223538883] unbound[24805:6] info: average recursion processing time
1.727755 sec
[1223538883] unbound[24805:6] info: histogram of recursion processing
times
[1223538883] unbound[24805:6] info: [25%]=0.0261211
median[50%]=0.0204539 [75%]=0.107455
[1223538883] unbound[24805:6] info: lower(secs) upper(secs) recursions
[1223538883] unbound[24805:6] info:    0.000000    0.000001 48
[1223538883] unbound[24805:6] info:    0.001024    0.002048 19
[1223538883] unbound[24805:6] info:    0.002048    0.004096 9
[1223538883] unbound[24805:6] info:    0.004096    0.008192 15
[1223538883] unbound[24805:6] info:    0.008192    0.016384 6
[1223538883] unbound[24805:6] info:    0.016384    0.032768 35
[1223538883] unbound[24805:6] info:    0.032768    0.065536 281
[1223538883] unbound[24805:6] info:    0.065536    0.131072 250
[1223538883] unbound[24805:6] info:    0.131072    0.262144 314
[1223538883] unbound[24805:6] info:    0.262144    0.524288 222
[1223538883] unbound[24805:6] info:    0.524288    1.000000 99
[1223538883] unbound[24805:6] info:    1.000000    2.000000 44
[1223538883] unbound[24805:6] info:    2.000000    4.000000 10
[1223538883] unbound[24805:6] info:    4.000000    8.000000 11
[1223538883] unbound[24805:6] info:    8.000000   16.000000 39
[1223538883] unbound[24805:6] info:   16.000000   32.000000 4
[1223538883] unbound[24805:6] info:   32.000000   64.000000 4
[1223538883] unbound[24805:6] info:   64.000000  128.000000 13
[1223538883] unbound[24805:6] info:  128.000000  256.000000 1
[1223538883] unbound[24806:7] info: server stats for thread 7: 3719
queries, 638 answers from cache, 3081 recursions
[1223538883] unbound[24806:7] info: server stats for thread 7:
requestlist max 283 avg 153.266 exceeded 0
[1223538883] unbound[24806:7] info: average recursion processing time
1.377575 sec
[1223538883] unbound[24806:7] info: histogram of recursion processing
times
[1223538883] unbound[24806:7] info: [25%]=0.0170918
median[50%]=0.0433889 [75%]=0.127535
[1223538883] unbound[24806:7] info: lower(secs) upper(secs) recursions
[1223538883] unbound[24806:7] info:    0.000000    0.000001 71
[1223538883] unbound[24806:7] info:    0.000512    0.001024 2
[1223538883] unbound[24806:7] info:    0.001024    0.002048 70
[1223538883] unbound[24806:7] info:    0.002048    0.004096 47
[1223538883] unbound[24806:7] info:    0.004096    0.008192 30
[1223538883] unbound[24806:7] info:    0.008192    0.016384 25
[1223538883] unbound[24806:7] info:    0.016384    0.032768 84
[1223538883] unbound[24806:7] info:    0.032768    0.065536 706
[1223538883] unbound[24806:7] info:    0.065536    0.131072 543
[1223538883] unbound[24806:7] info:    0.131072    0.262144 528
[1223538883] unbound[24806:7] info:    0.262144    0.524288 376
[1223538883] unbound[24806:7] info:    0.524288    1.000000 137
[1223538883] unbound[24806:7] info:    1.000000    2.000000 50
[1223538883] unbound[24806:7] info:    2.000000    4.000000 14
[1223538883] unbound[24806:7] info:    4.000000    8.000000 24
[1223538883] unbound[24806:7] info:    8.000000   16.000000 43
[1223538883] unbound[24806:7] info:   16.000000   32.000000 9
[1223538883] unbound[24806:7] info:   32.000000   64.000000 7
[1223538883] unbound[24806:7] info:   64.000000  128.000000 20
[1223538883] unbound[24806:7] info:  128.000000  256.000000 3
[1223538883] unbound[24799:0] info: server stats for thread 0: 75846
queries, 25599 answers from cache, 50247 recursions
[1223538883] unbound[24799:0] info: server stats for thread 0:
requestlist max 4135 avg 2140.02 exceeded 0
[1223538883] unbound[24799:0] info: average recursion processing time
2.091655 sec
[1223538883] unbound[24799:0] info: histogram of recursion processing
times
[1223538883] unbound[24799:0] info: [25%]=0.00760635
median[50%]=0.0253189 [75%]=0.109338
[1223538883] unbound[24799:0] info: lower(secs) upper(secs) recursions
[1223538883] unbound[24799:0] info:    0.000000    0.000001 3984
[1223538883] unbound[24799:0] info:    0.000256    0.000512 3
[1223538883] unbound[24799:0] info:    0.000512    0.001024 86
[1223538883] unbound[24799:0] info:    0.001024    0.002048 1781
[1223538883] unbound[24799:0] info:    0.002048    0.004096 477
[1223538883] unbound[24799:0] info:    0.004096    0.008192 444
[1223538883] unbound[24799:0] info:    0.008192    0.016384 283
[1223538883] unbound[24799:0] info:    0.016384    0.032768 1246
[1223538883] unbound[24799:0] info:    0.032768    0.065536 10323
[1223538883] unbound[24799:0] info:    0.065536    0.131072 7179
[1223538883] unbound[24799:0] info:    0.131072    0.262144 7546
[1223538883] unbound[24799:0] info:    0.262144    0.524288 4821
[1223538883] unbound[24799:0] info:    0.524288    1.000000 1464
[1223538883] unbound[24799:0] info:    1.000000    2.000000 634
[1223538883] unbound[24799:0] info:    2.000000    4.000000 266
[1223538883] unbound[24799:0] info:    4.000000    8.000000 332
[1223538883] unbound[24799:0] info:    8.000000   16.000000 386
[1223538883] unbound[24799:0] info:   16.000000   32.000000 283
[1223538883] unbound[24799:0] info:   32.000000   64.000000 605
[1223538883] unbound[24799:0] info:   64.000000  128.000000 568
[1223538883] unbound[24799:0] info:  128.000000  256.000000 90