Unbound stops responding

Unbound
1

We’ve used Unbound for a few months for around 15 000 clients I our company.

We recently had an issue when our Internet provider had a big network error.

This meant that our three unbound resolvers couldn’t perform recursion.

But during the outage, they stopped responding to any queries and the CPU spiked.

This meant that we couldn’t resolve local names.

After the outage was resolved, they started responding as usual again.

Statistics before outage:

2013-08-14 11:40:21 unbound[1180:0] info: server stats for thread 0: 137441 queries, 107082 answers from cache, 30359 recursions, 0 prefetch

2013-08-14 11:40:21 unbound[1180:0] info: server stats for thread 0: requestlist max 38 avg 4.54215 exceeded 0 jostled 0

2013-08-14 11:40:21 unbound[1180:0] info: average recursion processing time 0.120068 sec

2013-08-14 11:40:21 unbound[1180:0] info: histogram of recursion processing times

2013-08-14 11:40:21 unbound[1180:0] info: [25%]=0.00974991 median[50%]=0.0314827 [75%]=0.162277

Statistics during outage:

2013-08-14 12:40:21 unbound[1180:0] info: server stats for thread 0: 717834 queries, 79368 answers from cache, 638466 recursions, 0 prefetch

2013-08-14 12:40:21 unbound[1180:0] info: server stats for thread 0: requestlist max 893 avg 649.479 exceeded 520726 jostled 90153

2013-08-14 12:40:21 unbound[1180:0] info: average recursion processing time 16.060234 sec

2013-08-14 12:40:21 unbound[1180:0] info: histogram of recursion processing times

2013-08-14 12:40:21 unbound[1180:0] info: [25%]=0.0128234 median[50%]=0.046963 [75%]=0.241531

What can I do to make sure that Unbound still responds to a local query when there is an outage?

We run Unbound on Windows Server 2012 x64 (because we have more competence using Windows)

Is it possible to overcome the 1024 limit for outgoing-range and num-queries-per-thread when running Windows and would it have helped?

I would really appreciate comments and suggestions!

Thanks!

2

Hi Petter,

On windows we currently have a 64 limit, not a 1024 limit. This is
because of a windows limit for its waitformultipleevents winsock
function. And we need to wait for 'locks' for inter-thread
communication. Windows does not implement unix-pipes that we use on Unix.

So, the machine is massively not able to keep up with the work.

When you have the issue, the number of cache hits is roughly the same
(this indicates it did respond to cache hits?). But the non-cache
is 600.000 (20x the normal number). This causes the CPU spike. And it
cannot answer any of these questions because it has no sockets, and the
upstream is unresponsive anyway.

I think the 20x traffic increase may be why it does not respond to cache
responses. It should have responded to cache responses, but if the
network stack is swamped with packets, unbound does not have a chance.

Or is the machine easily capable of 20x the network load? (note that
UDP load may be different from other load). Then we should look at
the performance under this denialofservice condition. Especially I am
worried because your num-queries-per-thread is a lot bigger than what
you have sockets for, which does not happen (usually) for unices.

Best regards,
   Wouter

3

Hi Petter,

Responding to your second question: how to keep up during such an outage.

Local queries should then not depend on the internet provider. Put a
stub definition in unbound.conf for your intranet name(s) and point it
at the IP-addresses of your local authoritative DNS server(s). In
this way, local lookups for unbound do not need to cross over the
internet and can be resolved normally even while the ISP is down.

Unbound can deal with the situation that a part of the queries
resolves normally, but another part does not resolve (at all) and
unbound is swamped with queries for the slow part. It should be able
to resolve the fast queries and slowly keep working on (a fraction of)
the slow queries.

For a capacity increase you would need to use Linux somehow (or
FreeBSD). On windows, increase the num-threads (even above number of
CPUs, because it gives another set of sockets for every thread).
num-thread: 10, and every thread about 50 sockets outgoing-range, and
a low num-queries-per-thread too, say 25, for 500 sockets instead of
64, and 250 num-queries in total. Does that work? It defines
num-queries smaller than the outgoing-range.

Best regards,
   Wouter

4

Thanks for your quick replies!

I'm not sure why we had such a spike in traffic but I'm quite sure it's because the outage triggered all the Windows clients to perform multiple queries during the outage.

We do have stub definitions in our config so it should have worked if it didn't stop responding under such heavy load.

I wasn't aware of the 64 limit on Windows
I will change the num-thread, outgoing-range, num-queries-per-thread as you suggested.

Do you think this will be enough or should we consider to switch to Linux or FreeBSD?

Regards,

Petter Lindgren

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Petter,

Responding to your second question: how to keep up during such an outage.

Local queries should then not depend on the internet provider. Put a stub definition in unbound.conf for your intranet name(s) and point it at the IP-addresses of your local authoritative DNS server(s). In this way, local lookups for unbound do not need to cross over the internet and can be resolved normally even while the ISP is down.

Unbound can deal with the situation that a part of the queries resolves normally, but another part does not resolve (at all) and unbound is swamped with queries for the slow part. It should be able to resolve the fast queries and slowly keep working on (a fraction of) the slow queries.

For a capacity increase you would need to use Linux somehow (or FreeBSD). On windows, increase the num-threads (even above number of CPUs, because it gives another set of sockets for every thread).
num-thread: 10, and every thread about 50 sockets outgoing-range, and a low num-queries-per-thread too, say 25, for 500 sockets instead of 64, and 250 num-queries in total. Does that work? It defines num-queries smaller than the outgoing-range.

Best regards,
   Wouter

5

I've now implemented the values you suggested and Unbound seems to work well with 10 threads except for the logging.
After the config change; unbound started to write gibberish in the logfile.
It does the same on all three servers:

My optimization options:

num-threads: 10

msg-cache-slabs: 8
rrset-cache-slabs: 8
infra-cache-slabs: 8
key-cache-slabs: 8

rrset-cache-size: 512m
msg-cache-size: 256m
key-cache-size: 64m

outgoing-range: 50
num-queries-per-thread: 25

My logfile after the change:

2013-08-20 12:31:23 unbound[1272:5] info: server stats for thread 5: 244009 queries, 199923 answers from cache, 44086 recursions, 0 prefetch
2013-08-20 12:31:23 unbound[1272:5] info: server stats for thread 5: requestlist max 26 avg 2.80531 exceeded 1 jostled 0
2013-08-20 12:31:23 unbound[1272:5] info: average recursion processing time 2.004875 sec
2013-08-20 12:31:23 unbound[1272:5] info: histogram of recursion processing times
2013-08-20 12:31:23 unbound[1272:5] info: [25%]=8.67612e-007 median[50%]=0.0263988 [75%]=0.101194
2013-08-20 12:31:23 unbound[1272:5] info: lower(secs) upper(secs) recursions
2013-08-20 12:31:23 unbound[1272:5] info: 0.000000 0.000001 12758
2013-08-20 12:31:23 unbound[1272:5] info: 0.008192 0.016384 6306
2013-08-20 12:31:23 unbound[1272:5] info: 0.016384 0.032768 5029
2013-08-20 12:31:23 unbound[1272:5] info: 0.032768 0.065536 7103
2013-08-20 12:31:23 unbound[1272:5] info: 0.065536 0.131072 3696
2013-08-20 12:31:23 unbound[1272:5] info: 0.131072 0.262144 5122
2013-08-20 12:31:23 unbound[1272:5] info: 0.262144 0.524288 2391
2013-08-20 12:31:23 unbound[1272:5] info: 0.524288 1.000000 519
2013-08-20 12:31:23 unbound[1272:5] info: 1.000000 2.000000 166
2013-08-20 12:31:23 unbound[1272:5] info: 2.000000 4.000000 73
2013-08-20 12:31:23 unbound[1272:5] info: 4.000000 8.000000 39
2013-08-20 12:31:23 unbound[1272:5] info: 8.000000 16.000000 50
2013-08-20 12:31:23 unbound[1272:5] info: 16.000000 32.000000 117
2013-08-20 12:31:23 unbound[1272:5] info: 32.000000 64.000000 185
2013-08-20 12:31:23 unbound[1272:5] info: 64.000000 128.000000 361
2013-08-20 12:31:23 unbound[1272:5] info: 128.000000 256.000000 341
2013-08-20 12:31:23 unbound[1272:5] info: 256.000000 512.000000 17
2013-08-20 12:31:23 unbound[1272:5] info: 512.000000 1024.000000 3
2013-08-20 12:31:23 unbound[1272:8] info: server stats for thread 8: 48 queries, 47 answers from cache, 1 recursions, 0 prefetch
2013-08-20 12:31:23 unbound[1272:8] info: server stats for thread 8: requestlist max 0 avg 0 exceeded 0 jostled 0
2013-08-20 12:31:23 unbound[1272:8] info: average recursion processing time 0.249601 sec
2013-08-20 12:31:23 unbound[1272:8] info: histogram of recursion processing times
2013-08-20 12:31:23 unbound[1272:8] info: [25%]=0 median[50%]=0 [75%]=0
2013-08-20 12:31:23 unbound[1272:8] info: lower(secs) upper(secs) recursions
2013-08-20 12:31:23 unbound[1272:8] info: 0.131072 0.262144 1
20220113-0830-2-00 81-1220: 3311-08:22:-321:0 424 1 220u1:3nbouunnd[-12720b3o81:-2:462u ]u i0n ndf[no1b:122 7:32o1u::nsde2[49r] 12u7i2n:fnovb0eoru n:s ds[et1]ar2v7ert s2s :tfoa7tr]s i fn ofroi tt: hsnherrfrveeeo:ard 6 :asde rs t9:0 vqeua t0s e rfqourerr iseit setsa,th, 0s0r e afd oaanrs ns tw7weeh:r rsr0es a ffdrq o0mr cu:a eomcr 0he cquaeirciee,sh es, 00 00 reaacurrescinonunssswwrese,rrss i fo r0o pfmr ncerfosmea tccah,
c0ch hpeer,e, 00 f reetccuhr
rsi2o020n1133s-,- 008 -0p82-r200 e1 21:f23e:t311::2c2h44
u nuboneucnbduor[un1ds2io7n2[:1s267]2 2i0n:f9]o,: 0in1 3pfo:r e-ssefe0e8t-r2rc0vvehe rr 1s 2tsatt
ast: sf ofro3 r tt1hh:rr2eea4d a6: requestlidu ns9b2:0t r1oue3mq-anx0d[u1 8e207 s2-:27]0 t lai1v2gist :0 3nmaefxxc 1ee:o0:d e24ad vsg e ur v0neb0 oer juoxnstcdasettle[dseed1d 2f o7r2 0t0: 0
hjr]o easdi t7lnefdo :0: r
seerver sqtuaetstsl isfto rm axt h0r aevga 0d e x0ce:e derd e0q ujoesstlteld i0s
t max 0 avg 0 exceeded 0 jostled 0
202210310-1330-8--02808--22000 112:31:21242: 3:unbo13:1u2:4n2 4d [u1un2b7no2b:ou2un]n didn[f1o2:72[ :1s1e]2 7river 2n:sta3ts ffoo]: ri ns erver tfosth:atr esasd e r2v:e rf0 o sqtraut estrhir efeosar, t0d ahn1s:r w0e erqsu efardir o3me s:c ,ach e, 000 a nqswreuceruse rfrorms ciaoinescsh, 00 e, p0 arreecfuerstiocnhs
nwse,r s0 fprroemf ectacchh
e2,0 103 -r0e8c-u2r0s i1o2n:s3,1 :02 4p ruenfbetoc2hu0
nd1[31-20782-:220] 1i2n:f3o1:: 2s4e ruvnebro usntda[ts1 2f72o02r1 3:t1-] info0:h8r-e2 a0ds e r122v:e3:r 1rs:e2qt4ua eutsstlni sfort tbhroemuad 1: axnrequ 0 aedvgstl [i0s1t m2ax 0e avg7 02x e:c3e]e dxceeidneedd f0 joo :st ls0 ejdo es0tl
edr v0e
r stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
2013-08-20 12:31:24 unbound[1272:4] info: server stats for thread 4: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
2013-08-20 12:31:24 unbound[1272:4] info: server stats for thread 4: requestlist max 0 avg 0 exceeded 0 jostled 0

Regards

6

Hi Petter,

This is because of windows, it does not implement line buffering.
The posix: setvbuf(f, NULL, (int)_IOLBF, 0);
does not work, and it does not print whole lines to the file. The
threads are intermixing the log output.

You should turn down the log level, by the way, also for performance
reasons. To, perhaps, 1. At this level, either the logfile is fine
with lots of threads, or you can disable logging to file and log to
'syslog' which is the windows application event log on windows. And
that is likely to be threadsafe.

Another fix could be to open different files (logfile.0, logfile.1...)
for different threads on windows, but that would need code to support it.

Best regards,
   Wouter