flush_zone service impact
Rauno Tuul
raunz at hot.ee
Thu Apr 18 07:15:14 UTC 2019
Hi,
We're running several unbound 1.6.0 (debian9 stable) instances for public service and we are experiencing service impactions while executing flush_zone action. As the instances have 32GB of memory and 4 skylake vCPUs, we beefed up the cache size parameters.
Current config, which leads up to overall of 22GB memory usage by the unbound process:
so-reuseport: yes
num-threads: 4
msg-cache-slabs: 4
rrset-cache-slabs: 4
infra-cache-slabs: 4
key-cache-slabs: 4
rrset-cache-size: 8000m
msg-cache-size: 4000m
neg-cache-size: 200m
key-cache-size: 500m
outgoing-range: 8192
num-queries-per-thread: 4096
so-rcvbuf: 8m
so-sndbuf: 8m
unwanted-reply-threshold: 10000000
infra-cache-numhosts: 500000
The 'unbound-control flush_zone some.domain' execution takes on busier instance 12..15 seconds. During flush, the unbound doesn't send out any DNS reply packets and there is silence on the wire until flush completes. The IO graphs in attach will demonstrate, how the source udp53 packet rate drops from 20Kpps to 0 for the flush execution time. Flush in a prime-time on a busy node easily results in a loss of approx 500K requests.
Unbound process consumes up all CPU resources (4vCPU's flat out), while in normal operation the CPU usage is avg 20..30%.
I gathered unbound-control status and stats outputs to separate file in attachment.
There is a massive burst of reply packets after the flush operation has been completed (see attached wireshark IO graphs). It could be related to kernel receive queue, which buffers queries while flush is in action.
Our main concern is the services unresponsiveness during flush. To reduce impaction time, we could decrease buffers size for example to following values, but it sure doesn't look like a solution to service impact.
rrset-cache-size: 640m
msg-cache-size: 320m
neg-cache-size: 32m
key-cache-size: 32m
Could there be any enhancements regarding cache handling and flush_zone in current 1.9 release compared to 1.6? In the changelog I couldn't find anything related to flush performance/impact.
Has anyone else had the same problem and could share some wisdom, how to get around it?
With larger cache size, theres also a bit more need for the flush to be usable.
kind regards,
--
rauno
-------------- next part --------------
A non-text attachment was scrubbed...
Name: flush_io_graph_a_20190418.png
Type: image/png
Size: 81364 bytes
Desc: not available
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20190418/a19ef92d/attachment.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: flush_io_graph_k_20190418.png
Type: image/png
Size: 42137 bytes
Desc: not available
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20190418/a19ef92d/attachment-0001.png>
-------------- next part --------------
NODE A:
========================================================
$ unbound-control status
version: 1.6.0
verbosity: 1
threads: 4
modules: 2 [ validator iterator ]
uptime: 11439938 seconds
options: reuseport control(ssl)
unbound (pid 13826) is running...
$ unbound-control stats_noreset
thread0.num.queries=2693507676
thread0.num.cachehits=2681398222
thread0.num.cachemiss=12109454
thread0.num.prefetch=0
thread0.num.zero_ttl=0
thread0.num.recursivereplies=12109450
thread0.requestlist.avg=5.32046
thread0.requestlist.max=69
thread0.requestlist.overwritten=0
thread0.requestlist.exceeded=0
thread0.requestlist.current.all=4
thread0.requestlist.current.user=4
thread0.recursion.time.avg=1.618913
thread0.recursion.time.median=0.0385419
thread0.tcpusage=0
thread1.num.queries=2694993998
thread1.num.cachehits=2682934792
thread1.num.cachemiss=12059206
thread1.num.prefetch=0
thread1.num.zero_ttl=0
thread1.num.recursivereplies=12059202
thread1.requestlist.avg=5.0697
thread1.requestlist.max=77
thread1.requestlist.overwritten=0
thread1.requestlist.exceeded=0
thread1.requestlist.current.all=6
thread1.requestlist.current.user=4
thread1.recursion.time.avg=1.553610
thread1.recursion.time.median=0.0373833
thread1.tcpusage=0
thread2.num.queries=2677895260
thread2.num.cachehits=2665625879
thread2.num.cachemiss=12269381
thread2.num.prefetch=0
thread2.num.zero_ttl=0
thread2.num.recursivereplies=12269377
thread2.requestlist.avg=5.05975
thread2.requestlist.max=98
thread2.requestlist.overwritten=0
thread2.requestlist.exceeded=0
thread2.requestlist.current.all=4
thread2.requestlist.current.user=4
thread2.recursion.time.avg=1.519577
thread2.recursion.time.median=0.0375234
thread2.tcpusage=0
thread3.num.queries=2671598520
thread3.num.cachehits=2659182374
thread3.num.cachemiss=12416146
thread3.num.prefetch=0
thread3.num.zero_ttl=0
thread3.num.recursivereplies=12416145
thread3.requestlist.avg=5.14334
thread3.requestlist.max=74
thread3.requestlist.overwritten=0
thread3.requestlist.exceeded=0
thread3.requestlist.current.all=2
thread3.requestlist.current.user=1
thread3.recursion.time.avg=1.574968
thread3.recursion.time.median=0.0376013
thread3.tcpusage=0
total.num.queries=10737995454
total.num.cachehits=10689141267
total.num.cachemiss=48854187
total.num.prefetch=0
total.num.zero_ttl=0
total.num.recursivereplies=48854174
total.requestlist.avg=5.14807
total.requestlist.max=98
total.requestlist.overwritten=0
total.requestlist.exceeded=0
total.requestlist.current.all=16
total.requestlist.current.user=13
total.recursion.time.avg=1.566677
total.recursion.time.median=0.0377625
total.tcpusage=0
time.now=1555535711.738020
time.up=11439956.934803
time.elapsed=11439956.934803
mem.cache.rrset=1065599268
mem.cache.message=1627170967
mem.mod.iterator=16548
mem.mod.validator=159044509
histogram.000000.000000.to.000000.000001=6899888
histogram.000000.000001.to.000000.000002=2
histogram.000000.000002.to.000000.000004=86
histogram.000000.000004.to.000000.000008=75
histogram.000000.000008.to.000000.000016=208
histogram.000000.000016.to.000000.000032=244
histogram.000000.000032.to.000000.000064=506
histogram.000000.000064.to.000000.000128=1294
histogram.000000.000128.to.000000.000256=18804
histogram.000000.000256.to.000000.000512=134289
histogram.000000.000512.to.000000.001024=1499906
histogram.000000.001024.to.000000.002048=2570930
histogram.000000.002048.to.000000.004096=1249566
histogram.000000.004096.to.000000.008192=1423433
histogram.000000.008192.to.000000.016384=1624879
histogram.000000.016384.to.000000.032768=7161446
histogram.000000.032768.to.000000.065536=12084727
histogram.000000.065536.to.000000.131072=7496517
histogram.000000.131072.to.000000.262144=4000734
histogram.000000.262144.to.000000.524288=1262656
histogram.000000.524288.to.000001.000000=364574
histogram.000001.000000.to.000002.000000=270044
histogram.000002.000000.to.000004.000000=265902
histogram.000004.000000.to.000008.000000=106205
histogram.000008.000000.to.000016.000000=89130
histogram.000016.000000.to.000032.000000=54098
histogram.000032.000000.to.000064.000000=24707
histogram.000064.000000.to.000128.000000=51828
histogram.000128.000000.to.000256.000000=107283
histogram.000256.000000.to.000512.000000=63226
histogram.000512.000000.to.001024.000000=20657
histogram.001024.000000.to.002048.000000=5501
histogram.002048.000000.to.004096.000000=721
histogram.004096.000000.to.008192.000000=108
histogram.008192.000000.to.016384.000000=0
histogram.016384.000000.to.032768.000000=0
histogram.032768.000000.to.065536.000000=0
histogram.065536.000000.to.131072.000000=0
histogram.131072.000000.to.262144.000000=0
histogram.262144.000000.to.524288.000000=0
num.query.type.A=5338649859
num.query.type.NS=21546
num.query.type.CNAME=153071
num.query.type.SOA=397408
num.query.type.PTR=25365868
num.query.type.MX=72573
num.query.type.TXT=80129
num.query.type.AAAA=5372898672
num.query.type.SRV=240894
num.query.type.NAPTR=12
num.query.type.DNAME=389
num.query.type.DS=23
num.query.type.RRSIG=21
num.query.type.DNSKEY=5
num.query.type.ANY=114962
num.query.type.other=22
num.query.class.IN=10737995454
num.query.opcode.QUERY=10737995454
num.query.tcp=33667
num.query.tcpout=4981098
num.query.ipv6=1
num.query.flags.QR=0
num.query.flags.AA=0
num.query.flags.TC=0
num.query.flags.RD=10737994853
num.query.flags.RA=0
num.query.flags.Z=0
num.query.flags.AD=122
num.query.flags.CD=1637
num.query.edns.present=139668054
num.query.edns.DO=45902401
num.answer.rcode.NOERROR=10481725151
num.answer.rcode.FORMERR=0
num.answer.rcode.SERVFAIL=2118833
num.answer.rcode.NXDOMAIN=254150856
num.answer.rcode.NOTIMPL=0
num.answer.rcode.REFUSED=601
num.answer.rcode.nodata=5211578831
num.answer.secure=10666307
num.answer.bogus=4061
num.rrset.bogus=0
unwanted.queries=0
unwanted.replies=30050
msg.cache.count=4573902
rrset.cache.count=2764363
infra.cache.count=495307
key.cache.count=421379
$ date; time unbound-control flush_zone example.com; date
Wed Apr 17 21:16:13 UTC 2019
ok removed 4 rrsets, 6 messages and 0 key entries
real 0m2.616s
user 0m0.007s
sys 0m0.000s
Wed Apr 17 21:16:15 UTC 2019
NODE K:
========================================================
Normal operation 'top'
KiB Mem : 32944704 total, 9958712 free, 22279468 used, 706524 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 9942408 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
31591 unbound 20 0 21.179g 0.021t 6392 S 20.3 67.0 41726:12 unbound
$ unbound-control status
version: 1.6.0
verbosity: 1
threads: 4
modules: 2 [ validator iterator ]
uptime: 11439734 seconds
options: reuseport control(ssl)
unbound (pid 31591) is running...
$ unbound-control stats_noreset
thread0.num.queries=14055029997
thread0.num.cachehits=13191953884
thread0.num.cachemiss=863076113
thread0.num.prefetch=0
thread0.num.zero_ttl=0
thread0.num.recursivereplies=863076084
thread0.requestlist.avg=40.5627
thread0.requestlist.max=529
thread0.requestlist.overwritten=0
thread0.requestlist.exceeded=0
thread0.requestlist.current.all=23
thread0.requestlist.current.user=18
thread0.recursion.time.avg=0.452814
thread0.recursion.time.median=0.0347267
thread0.tcpusage=0
thread1.num.queries=15315499427
thread1.num.cachehits=14442871806
thread1.num.cachemiss=872627621
thread1.num.prefetch=0
thread1.num.zero_ttl=0
thread1.num.recursivereplies=871549205
thread1.requestlist.avg=40.9508
thread1.requestlist.max=655
thread1.requestlist.overwritten=0
thread1.requestlist.exceeded=1078373
thread1.requestlist.current.all=34
thread1.requestlist.current.user=15
thread1.recursion.time.avg=0.463556
thread1.recursion.time.median=0.033659
thread1.tcpusage=0
thread2.num.queries=14014310064
thread2.num.cachehits=13145724629
thread2.num.cachemiss=868585435
thread2.num.prefetch=0
thread2.num.zero_ttl=0
thread2.num.recursivereplies=868585385
thread2.requestlist.avg=40.5867
thread2.requestlist.max=656
thread2.requestlist.overwritten=0
thread2.requestlist.exceeded=0
thread2.requestlist.current.all=47
thread2.requestlist.current.user=20
thread2.recursion.time.avg=0.448045
thread2.recursion.time.median=0.0337312
thread2.tcpusage=0
thread3.num.queries=14052755562
thread3.num.cachehits=13181901122
thread3.num.cachemiss=870854440
thread3.num.prefetch=0
thread3.num.zero_ttl=0
thread3.num.recursivereplies=870854353
thread3.requestlist.avg=42.0318
thread3.requestlist.max=460
thread3.requestlist.overwritten=0
thread3.requestlist.exceeded=0
thread3.requestlist.current.all=27
thread3.requestlist.current.user=20
thread3.recursion.time.avg=0.494273
thread3.recursion.time.median=0.0338163
thread3.tcpusage=0
total.num.queries=57437595050
total.num.cachehits=53962451441
total.num.cachemiss=3475143609
total.num.prefetch=0
total.num.zero_ttl=0
total.num.recursivereplies=3474065027
total.requestlist.avg=41.0343
total.requestlist.max=656
total.requestlist.overwritten=0
total.requestlist.exceeded=1078373
total.requestlist.current.all=131
total.requestlist.current.user=73
total.recursion.time.avg=0.464709
total.recursion.time.median=0.0339833
total.tcpusage=0
time.now=1555536034.884367
time.up=11439745.824328
time.elapsed=11439745.824328
mem.cache.rrset=8925478339
mem.cache.message=4462739507
mem.mod.iterator=16548
mem.mod.validator=801111194
histogram.000000.000000.to.000000.000001=513533284
histogram.000000.000001.to.000000.000002=2259
histogram.000000.000002.to.000000.000004=19799
histogram.000000.000004.to.000000.000008=26715
histogram.000000.000008.to.000000.000016=18961
histogram.000000.000016.to.000000.000032=59451
histogram.000000.000032.to.000000.000064=170966
histogram.000000.000064.to.000000.000128=303778
histogram.000000.000128.to.000000.000256=683326
histogram.000000.000256.to.000000.000512=1662747
histogram.000000.000512.to.000000.001024=26915408
histogram.000000.001024.to.000000.002048=145635743
histogram.000000.002048.to.000000.004096=88955128
histogram.000000.004096.to.000000.008192=181401955
histogram.000000.008192.to.000000.016384=231570600
histogram.000000.016384.to.000000.032768=503204278
histogram.000000.032768.to.000000.065536=1157489691
histogram.000000.065536.to.000000.131072=294521100
histogram.000000.131072.to.000000.262144=210093888
histogram.000000.262144.to.000000.524288=72263629
histogram.000000.524288.to.000001.000000=18265945
histogram.000001.000000.to.000002.000000=8428482
histogram.000002.000000.to.000004.000000=4914870
histogram.000004.000000.to.000008.000000=2706399
histogram.000008.000000.to.000016.000000=2568149
histogram.000016.000000.to.000032.000000=2101213
histogram.000032.000000.to.000064.000000=1308537
histogram.000064.000000.to.000128.000000=2020530
histogram.000128.000000.to.000256.000000=1857074
histogram.000256.000000.to.000512.000000=919617
histogram.000512.000000.to.001024.000000=287035
histogram.001024.000000.to.002048.000000=134612
histogram.002048.000000.to.004096.000000=18491
histogram.004096.000000.to.008192.000000=1238
histogram.008192.000000.to.016384.000000=65
histogram.016384.000000.to.032768.000000=37
histogram.032768.000000.to.065536.000000=27
histogram.065536.000000.to.131072.000000=0
histogram.131072.000000.to.262144.000000=0
histogram.262144.000000.to.524288.000000=0
num.query.type.TYPE0=1335376
num.query.type.A=40938148300
num.query.type.NS=22061613
num.query.type.CNAME=571551
num.query.type.SOA=70729720
num.query.type.NULL=27757
num.query.type.WKS=8
num.query.type.PTR=835097459
num.query.type.HINFO=85
num.query.type.MX=9247887
num.query.type.TXT=144889551
num.query.type.RP=2
num.query.type.AFSDB=2
num.query.type.X25=3707
num.query.type.ISDN=1
num.query.type.NSAP=1
num.query.type.SIG=1
num.query.type.KEY=3
num.query.type.AAAA=14257519577
num.query.type.LOC=2
num.query.type.SRV=1133532197
num.query.type.NAPTR=8122419
num.query.type.KX=1
num.query.type.CERT=2
num.query.type.A6=383299
num.query.type.DNAME=1
num.query.type.APL=1
num.query.type.DS=2378612
num.query.type.SSHFP=95354
num.query.type.IPSECKEY=2
num.query.type.RRSIG=4403
num.query.type.NSEC=2
num.query.type.DNSKEY=719142
num.query.type.DHCID=1
num.query.type.NSEC3=2
num.query.type.NSEC3PARAM=1
num.query.type.SPF=213358
num.query.type.TKEY=39
num.query.type.AXFR=48
num.query.type.MAILB=10
num.query.type.ANY=9897645
num.query.type.other=2608533
num.query.class.CLASS0=8
num.query.class.IN=57433913171
num.query.class.CH=122521
num.query.class.CLASS6=34700
num.query.class.ANY=19247
num.query.class.other=3497980
num.query.opcode.QUERY=57437587627
num.query.tcp=5514646
num.query.tcpout=77520551
num.query.ipv6=8846753360
num.query.flags.QR=0
num.query.flags.AA=53370
num.query.flags.TC=0
num.query.flags.RD=57435310852
num.query.flags.RA=6488675
num.query.flags.Z=0
num.query.flags.AD=5698965
num.query.flags.CD=17910004
num.query.edns.present=317235468
num.query.edns.DO=177990670
num.answer.rcode.NOERROR=53577429262
num.answer.rcode.FORMERR=7160
num.answer.rcode.SERVFAIL=277136239
num.answer.rcode.NXDOMAIN=3576144768
num.answer.rcode.NOTIMPL=0
num.answer.rcode.REFUSED=5798824
num.answer.rcode.nodata=3676365108
num.answer.secure=1554585577
num.answer.bogus=78027379
num.rrset.bogus=0
unwanted.queries=0
unwanted.replies=270579
msg.cache.count=14065106
rrset.cache.count=22339745
infra.cache.count=495625
key.cache.count=2506160
$ date; time unbound-control flush_zone example.com; date
Wed Apr 17 21:21:23 UTC 2019
ok removed 997 rrsets, 3109 messages and 0 key entries
real 0m12.678s
user 0m0.007s
sys 0m0.000s
Wed Apr 17 21:21:35 UTC 2019
'top' during flush:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
31591 unbound 20 0 21.179g 0.021t 6392 R 399.0 67.0 41727:34 unbound
Another flush with the same domain:
$ date; time unbound-control flush_zone example.com; date
Wed Apr 17 21:22:33 UTC 2019
ok removed 290 rrsets, 599 messages and 1 key entries
real 0m13.287s
user 0m0.004s
sys 0m0.004s
Wed Apr 17 21:22:47 UTC 2019
More information about the Unbound-users
mailing list