<div dir="ltr"><div><div><div><div>Hello,<br><br></div>We have been migrating from a bind based DNS server to pdns-recursor over the last few months. As we have added additional clients we have noticed that the latency long tail on pdns is considerably higher (2 seconds+) than what we saw previously on bind (9.10.3 Ubuntu 16.04).<br><br></div>I have enabled tracing to try and help identify the root cause, however it has not been immediately clear to me what is actually happening to cause the delays. In tracing we see the first entries in the log that look like this.<br><br>Aug 30 05:03:14.529593 <hostname> pdns_recursor[5150]: Aug 30 05:03:14 2 [5714976/1] question for '<redacted-hostname>|A' from 10.64.2.20<br>Aug 30 05:03:14.531452 <hostname> pdns_recursor[5150]: Aug 30 05:03:14 2 [5714977/2] question for '<redacted-hostname>|AAAA' from 10.64.2.20<br><br></div>The A record completes very quickly and correctly. From the trace logs (via journalctl with --output=short-iso )<br><br>Aug 30 05:03:14.542610 <hostname> pdns_recursor[5150]: Aug 30 05:03:14 [5714976] <redacted-hostname>: status=got results, this level of recursion done<br><br></div>However we do not see anything relating to the AAAA lookup until over 1 second later.<br><br>Aug 30 05:03:16.079983 <hostname> pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Wants DNSSEC processing in query for AAAA<br>Aug 30 05:03:16.080159 <hostname> pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Looking for CNAME cache hit of '<redacted-hostname>|CNAME'<br>Aug 30 05:03:16.080288 <hostname> pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: No CNAME cache hit of '<redacted-hostname>|CNAME' found<br>Aug 30 05:03:16.080439 <hostname> pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Entire name '<redacted-hostname>' or type was negatively cached, but entry expired<br>Aug 30 05:03:16.079983 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Wants DNSSEC processing in query for AAAA<br>Aug 30 05:03:16.080159 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Looking for CNAME cache hit of '<redacted-hostname>|CNAME'<br>Aug 30 05:03:16.080288 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: No CNAME cache hit of '<redacted-hostname>|CNAME' found<br>Aug 30 05:03:16.080439 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Entire name '<redacted-hostname>' or type was negatively cached, but entry expired<br>Aug 30 05:03:16.080561 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: No cache hit for '<redacted-hostname>|AAAA', trying to find an appropriate NS record<br>Aug 30 05:03:16.080683 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Checking if we have NS in cache for '<redacted-hostname>'<br>Aug 30 05:03:16.080814 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: no valid/useful NS in cache for '<redacted-hostname>'<br>Aug 30 05:03:16.080939 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Checking if we have NS in cache for '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>'<br>Aug 30 05:03:16.081062 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: NS (with ip, or non-glue) in cache for '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' -> '<a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a>'<br>Aug 30 05:03:16.081186 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: within bailiwick: 0, not in cache / did not look at cache<br>Aug 30 05:03:16.081312 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: NS (with ip, or non-glue) in cache for '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' -> '<a href="http://ns-1693.awsdns-19.co.uk">ns-1693.awsdns-19.co.uk</a>'<br>Aug 30 05:03:16.081434 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: within bailiwick: 0, not in cache / did not look at cache<br>Aug 30 05:03:16.081557 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: NS (with ip, or non-glue) in cache for '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' -> '<a href="http://ns-29.awsdns-03.com">ns-29.awsdns-03.com</a>'<br>Aug 30 05:03:16.081683 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: within bailiwick: 0, not in cache / did not look at cache<br>Aug 30 05:03:16.081804 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: NS (with ip, or non-glue) in cache for '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' -> '<a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>'<br>Aug 30 05:03:16.081947 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: within bailiwick: 0, not in cache / did not look at cache<br>Aug 30 05:03:16.082068 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: We have NS in cache for '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' (flawedNSSet=0)<br>Aug 30 05:03:16.082193 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Cache consultations done, have 4 NS to contact<br>Aug 30 05:03:16.082338 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>.: Nameservers: ns-995.awsdns-60.net.(8.34ms), ns-1256.awsdns-29.org.(21.32ms), ns-29.awsdns-03.com.(23.94ms),<br>Aug 30 05:03:16.082459 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>.:              ns-1693.awsdns-19.co.uk.(29.00ms)<br>Aug 30 05:03:16.082581 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Trying to resolve NS '<a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>' (1/4)<br>Aug 30 05:03:16.082708 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977]    <a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>: Wants DNSSEC processing in query for A<br>Aug 30 05:03:16.082829 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977]    <a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>: Looking for CNAME cache hit of '<a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>|CNAME'<br>Aug 30 05:03:16.082955 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977]    <a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>: No CNAME cache hit of '<a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>|CNAME' found<br>Aug 30 05:03:16.083074 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977]    <a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>: Found cache hit for A: 205.251.195.227[ttl=170146]<br>Aug 30 05:03:16.083194 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Resolved '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' NS <a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a> to: 205.251.195.227<br>Aug 30 05:03:16.083314 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Trying IP <a href="http://205.251.195.227:53">205.251.195.227:53</a>, asking '<redacted-hostname>|AAAA'<br>Aug 30 05:03:16.083434 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: timeout resolving after 1521.4msec<br>Aug 30 05:03:16.083554 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Trying to resolve NS '<a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a>' (2/4)<br>Aug 30 05:03:16.083677 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977]    <a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a>: Wants DNSSEC processing in query for A<br>Aug 30 05:03:16.083821 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977]    <a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a>: Looking for CNAME cache hit of '<a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a>|CNAME'<br>Aug 30 05:03:16.083940 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977]    <a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a>: No CNAME cache hit of '<a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a>|CNAME' found<br>Aug 30 05:03:16.084058 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977]    <a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a>: Found cache hit for A: 205.251.196.232[ttl=170157]<br>Aug 30 05:03:16.084179 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Resolved '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' NS <a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a> to: 205.251.196.232<br>Aug 30 05:03:16.084298 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Trying IP <a href="http://205.251.196.232:53">205.251.196.232:53</a>, asking '<redacted-hostname>|AAAA'<br>Aug 30 05:03:16.084417 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: Got 2 answers from <a href="http://ns-1256.awsdns-29.org">ns-1256.awsdns-29.org</a> (205.251.196.232), rcode=0 (No Error), aa=1, in 26ms<br>Aug 30 05:03:16.084548 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: accept answer '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>|SOA|<a href="http://ns-995.awsdns-60.net">ns-995.awsdns-60.net</a>. <a href="http://awsdns-hostmaster.amazon.com">awsdns-hostmaster.amazon.com</a>. 1 7200 900 1209600 60' from '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' nameservers? 2 YES!<br>Aug 30 05:03:16.084669 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: OPT answer '.' from '<a href="http://us-west-2.staging.atl-paas.net">us-west-2.staging.atl-paas.net</a>' nameservers<br>Aug 30 05:03:16.084789 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: determining status after receiving this packet<br>Aug 30 05:03:16.084908 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: got negative caching indication for '<redacted-hostname>|AAAA'<br>Aug 30 05:03:16.085027 dns-0.usw2 pdns_recursor[5150]: Aug 30 05:03:16 [5714977] <redacted-hostname>: status=noerror, other types may exist, but we are done (have negative SOA) (have aa bit)<br><div><br></div><div>As far as we can tell the configuration is simple</div><div><br></div><div>config-dir=/etc/powerdns/<br>allow-from-file=/etc/powerdns/permit-queries-from.acl<br>forward-zones-file=/etc/powerdns/forwarders.conf<br><br>daemon=yes<br>setgid=pdns<br>setuid=pdns<br>socket-dir=/var/run<br><br>etc-hosts-file=/etc/hosts<br><br>local-address=0.0.0.0<br>query-local-address=0.0.0.0<br>local-port=53<br><br>quiet=yes<br>loglevel=4<br>log-common-errors=yes<br><br>max-cache-entries=500000<br>latency-statistic-size=30000<br><br>max-cache-ttl=172801<br>max-tcp-clients=128<br>network-timeout=1500<br><br>server-down-max-fails=32<br>server-down-throttle-time=120<br><br>serve-rfc1918=no<br>dont-query=<br><br><br>dnssec=process-no-validate<br><br>max-recursion-depth=40<br>max-qperq=50<br>client-tcp-timeout=5<br><br>reuseport=yes<br>threads=4<br>max-mthreads=2048<br>pdns-distributes-queries=true<br></div><div><br></div><div>We have seen this behavior on both 3.7.4 and 4.0.6. We are using the official packages from the repo listed here: <a href="https://repo.powerdns.com/">https://repo.powerdns.com/</a> we run pdns-recursor across 7 regions and all exhibit the same behavior whereas previously these same queries via bind did not show the same delays.<br></div><div><br></div><div>pdns_recursor --version<br>Aug 30 10:09:04 PowerDNS Recursor 4.0.6 (C) 2001-2016 PowerDNS.COM BV<br>Aug 30 10:09:04 Using 64-bits mode. Built using gcc 5.4.0 20160609 on Jul  4 2017 15:43:52 by root@5ee67e1ed1a4.<br>Aug 30 10:09:04 PowerDNS comes with ABSOLUTELY NO WARRANTY. This is free software, and you are welcome to redistribute it according to the terms of the GPL version 2.<br>Aug 30 10:09:04 Features: openssl lua<br>Aug 30 10:09:04 Configured with: " '--host=' '--build=' '--prefix=/usr' '--sysconfdir=/etc/powerdns' '--mandir=${prefix}/share/man' '--infodir=${prefix}/share/info' '--libdir=${prefix}/lib/' '--libexecdir=${prefix}/lib' '--with-lua' '--with-protobuf=yes' '--enable-systemd' '--with-systemd=/lib/systemd/system' 'build_alias=' 'host_alias=' 'CFLAGS=-g -O2 -fPIE -fstack-protector-strong -Wformat -Werror=format-security' 'LDFLAGS=-Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now' 'CPPFLAGS=-Wdate-time -D_FORTIFY_SOURCE=2' 'CXXFLAGS=-g -O2 -fPIE -fstack-protector-strong -Wformat -Werror=format-security'"</div><div><br></div><div>Any assistance or advice on further diagnosing this issue would be greatly appreciated.</div><div><br></div><div>Regards,</div><div><br></div><div>James<br></div><div><br></div></div>