Understanding DNS caching performance (goes up after 30 seconds)

Luis_Johnstone · April 28, 2023, 4:51pm

Hi there, apologies if this has been raised already but I'm a bit confused by the performance of DNS resolution I'm seeing for the pihole.

Expected Behaviour:

Environment:
Raspberry Pi 4B 4GB
Ubuntu 22.10
Pi-hole version is v5.16.2 (Latest: v5.16.2)
AdminLTE version is v5.19 (Latest: v5.19)
FTL version is v5.22 (Latest: v5.22)
Using cloudflared tunnel and DoH; upstream is not cloudflare, though.

I expect that the latency for a DNS request to the pihole should be faster than going to the internet when a response is cached

Actual Behaviour:

If I compare the performance using dig I can see that if I make a query such as:

❯ dig -u -t A ubuntu.com @ns1

; <<>> DiG 9.18.12-0ubuntu0.22.10.1-Ubuntu <<>> -u -t A ubuntu.com @ns1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 54018
;; flags: qr rd ra; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;ubuntu.com.                    IN      A

;; ANSWER SECTION:
ubuntu.com.             59      IN      A       185.125.190.29
ubuntu.com.             59      IN      A       185.125.190.20
ubuntu.com.             59      IN      A       185.125.190.21

;; Query time: 4026 usec
;; SERVER: 192.168.178.50#53(ns1) (UDP)
;; WHEN: Fri Apr 28 17:34:55 BST 2023
;; MSG SIZE  rcvd: 87

After one or (often) two executions the query time settles down to about 4ms (I was using nanoseconds above as I was comparing to the 1.1.1.1 resolver).
I have tried re-running the command at n-seconds after the first execution:
10 seconds = same
20 seconds = same
30 seconds = 15-20ms

The web admin UI indicates that no cache evictions are happening.

When I look at the query log in the web UI I can see that two record types are being resolved for, say, ubuntu.com in the UNCACHED state: A and DS

The DS record is forwarded to my router (not sure why??) on port 53 and returns NODATA in 14.2ms
The A record is forwarded to localhost#5053 and returns IP in 28.8ms

In the cached scenario I see only the A record returned and it's from the cache.

Debug Token:

https://tricorder.pi-hole.net/xrBFvL2R/

Bucking_Horn · April 28, 2023, 5:27pm

Could you please provide an example dig output for 1.1.1.1 that you are using for comparison?

Luis_Johnstone · April 28, 2023, 6:00pm

Thanks for the reply. I'll provide it below but I'm not sure whether it matters much because the issue is why the latency of the DNS request to the pihole goes up after 30 seconds.

As requested:

❯ dig -u -t A ubuntu.com @1.1.1.1

; <<>> DiG 9.18.12-0ubuntu0.22.10.1-Ubuntu <<>> -u -t A ubuntu.com @1.1.1.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 10182
;; flags: qr rd ra; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;ubuntu.com.                    IN      A

;; ANSWER SECTION:
ubuntu.com.             59      IN      A       185.125.190.29
ubuntu.com.             59      IN      A       185.125.190.20
ubuntu.com.             59      IN      A       185.125.190.21

;; Query time: 11262 usec
;; SERVER: 1.1.1.1#53(1.1.1.1) (UDP)
;; WHEN: Fri Apr 28 18:54:31 BST 2023
;; MSG SIZE  rcvd: 87

and here's the output if I don't query the pihole for 30 seconds:

❯ dig -u -t A ubuntu.com @ns1

; <<>> DiG 9.18.12-0ubuntu0.22.10.1-Ubuntu <<>> -u -t A ubuntu.com @ns1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 45008
;; flags: qr rd ra; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
; COOKIE: d2effdec651e3d63 (echoed)
;; QUESTION SECTION:
;ubuntu.com.                    IN      A

;; ANSWER SECTION:
ubuntu.com.             60      IN      A       185.125.190.29
ubuntu.com.             60      IN      A       185.125.190.21
ubuntu.com.             60      IN      A       185.125.190.20

;; Query time: 18222 usec
;; SERVER: 192.168.178.50#53(ns1) (UDP)
;; WHEN: Fri Apr 28 19:00:21 BST 2023
;; MSG SIZE  rcvd: 129

Bucking_Horn · April 28, 2023, 6:26pm

Thank you.

There are several factors that may have an influence on your observation.

Faster compared to what, exactly?

Depending on your answer, you may want to adjust your comparison statements, and probably your expectations as well.

Your debug log shows that you've configured an encrypting upstream (cloudflared) for Pi-hole, and you also have DNSSEC enabled.

Both of those options have performance implications (e.g. additional DNS lookups -like the delegation signer records you mention- to get the keys and signatures from the authoritative nameservers for validation) that would not affect a plain DNS lookup via 1.1.1.1.

To get an idea about the additional burden of encryption, you could consider to run your dig via cloudflared directly.
In a similar fashion, you could disable DNSSEC in Pi-hole or adjust your dig statement to request DNSSEC validation (and just to prevent misunderstandings, dig's -u option triggers microseconds instead of milliseconds output, not nanoseconds).

Cache evictions would only happen if pihole-FTL would try to commit a new entry to the cache when all available slots would be used.

If you see no evictions, that doesn't mean that an entry wouldn't have expired already.
A domain owner controls for how long at most a requester should cache a DNS record, via the DNS record's TTL.
For ubuntu.com, that would be 60 seconds currently.
dig shows the remaining TTL in the answer section:

When taking all above considerations into account, your observation may well be expected: There is a good chance that the ~25ms jump in latency after 30 seconds is prompted by an expired cache entry.
EDIT: Also, your cloudflared upstream may have to renegotiate its encryption session from time to time.

Probably unrelated, but your debug log also shows that you are running netdata on the same machine as Pi-hole.
Depending on its configuration, certain netdata plug-in collectors may trigger high-frequency probing of DNS, which may or may not impact DNS resolution at times.

That is unexpected - it doesn't happen on my machine.

Could you provide the respective lines from Pi-hole's log:

sudo grep DS.*ubuntu.com /var/log/pihole/pihole.log

Luis_Johnstone · April 28, 2023, 9:33pm

Thanks again for the thorough and prompt reply. It is most appreciated.
You are correct on your points. Serves me right for picking a record with such a low TTL!

The mystery now makes sense! I've tried with some other domains and now see a behaviour I'd expect. I just didn't expect that DNS records would (or even could) be set as low as 30 seconds. Good to learn something!

Apr 28 21:26:04 dnsmasq[1181236]: dnssec-query[DS] ubuntu.com to 127.0.0.1#5053
Apr 28 21:56:46 dnsmasq[1195123]: dnssec-query[DS] ubuntu.com to 127.0.0.1#5053

and the web UI shows:

I did a little more testing and thinking about how it wasn't really a good test because the comparison is hard to make: after all, the pihole DNS entry for a domain like that is likely to expire naturally and end up with a cache-miss penalty, so to speak; but the upstream resolvers are unlikely to suffer such a penalty. I can prove it but not quantify it; after all, querying directly against 1.1.1.1, the response time hardly seems to vary over a 30-60 second period (hard to quantify because I cannot know how many DNS requests per second they receive for a given name and so my test could easily miss the first request after a cache expiry).

You are correct about Netdata and that's actually how this got started
I have it setup to monitor DNS performance against a number of hosts, and permutations of IPv4 vs. IPv6:

Another good lesson from this is that I need to choose my target domain names more carefully so that if/when I see spikes in DNS latency I can know whether it's due to normal TTL expiry (which I don't care about) or due to some other sort of issue (which I do care about).

I have some questions for another thread but will hopefully be better informed

Bucking_Horn · April 29, 2023, 6:13am

I am not familiar with that specific netdata collector you are showing, but you want to be careful about the number and frequency of DNS requests it is sending to Pi-hole, in order to avoid triggering Pi-hole's rate-limiting and/or saturating its concurrent connection pool at times. You also want to keep an eye on log and database sizes.

Thank you for providing the logs as well as the UI for that DS lookup.
As the log shows the request to be forwarded to your local cloudflared at 127.0.0.1#5053, this seems to be an UI glitch.
I can confirm that this is also happening with my Pi-hole - thank you for the heads-up.

Luis_Johnstone · April 30, 2023, 10:59pm

Yes, I disable query logging; but that's mainly because I have devices spamming a DNS request every second when they do their NTP check (non-configurable, sadly).
Sometimes I re-open my browsers with so many tabs and I get my client auto-banned. Would be a nice-to-have if some clients could be exempted.

Current db size is 1.6GB. Is that expected?

Is there a metric that I can monitor for the concurrent connection pool; to get it's max value and its current state of use?

Bucking_Horn · May 2, 2023, 9:27am

I am not aware of any observable metrics.

The concurrent connection pool can be exhausted by an excessively large number of DNS requests (which quite likely would trigger a rate limit warning well before), or by slow or inresponsive upstream DNS servers, which would have Pi-hole starve on upstream answers.
Either of those could be used as early warning indicators.

Perhaps.
There's really too little information to answer that, as the size would be directly related to the number of DNS requests and to the database retention period.
That said, 1.6GB is rather large.

Would it be possible to enable a caching stub resolver on those devices themselves?
That could lower the count of requests considerably.

DL6ER · May 2, 2023, 10:33am

There are none. We go through a linked-list of backlog storage to see if there is an empty seat. If we find one, we use it. If we find none, the warning Maximum number of concurrent DNS queries reached (max: XXX) is triggered. Note that this warning is logged at most once every 5 seconds regardless of how often it is actually triggered.

The maximum number can be set using the option dns-forward-max=... in some *.conf file in /etc/dnsmasq.d. The default value is 150. This parameter actually controls the number of concurrent queries per server group, where a server group is the set of server(s) associated with a single domain. So if a domain has it's own server via server=/example.com/1.2.3.4 and 1.2.3.4 is not responding, but queries for *.example.com cannot go elsewhere, then other queries will not be affected. On configurations with many such server groups and tight resources, this value may need to be reduced.

Luis_Johnstone · May 2, 2023, 2:04pm

The concurrent connection pool can be exhausted by an excessively large number of DNS requests (which quite likely would trigger a rate limit warning well before), or by slow or inresponsive upstream DNS servers, which would have Pi-hole starve on upstream answers.
Either of those could be used as early warning indicators.

Would I be correct in thinking that the rate-limiting indicator would be seeing "RATE_LIMIT" in the pihole's FTL.log or do I need to enable query-logging?

Perhaps.
There's really too little information to answer that, as the size would be directly related to the number of DNS requests and to the database retention period.
That said, 1.6GB is rather large.

After some reading, I suspect that changing the MAXDBDAYS value to something smaller potentially would alleviate that (all things being equal, of course)? Is there any relationship between db size and performance for pihole? I ask because while it's only a 32GB SD-card, I'm have 19GB free and I am happy to dedicate it as the machine pretty much only runs pihole.

Would it be possible to enable a caching stub resolver on those devices themselves?
That could lower the count of requests considerably.

Unfortunately not; they are mostly networking devices. If necessary, I could setup an on-site NTP server and point them to it's static IP address; however, running an NTP server and using static IP addresses feels like a bit too much heavy-lifting.

Obviously, it'd require a change that you guys think is worth it, but it might be worthwhile to think about whether rate-limiting thresholds should apply to both cached or non-cached equally. Obviously, you want rate-limiting in both scenarios but it seems to me that having a higher threshold for rate-limiting of cached-responses might be a useful bit of flexibility and scalability.

Luis_Johnstone · May 2, 2023, 2:12pm

Can I configure that logging rate-limit? I ask as I could monitor the frequency of occurrences using netdata etc.

Slightly off-topic but, in the context of this discussion so far, what options (if any) are there for scaling pihole? If I do all that I can but still hit the aforementioned limits, what can I do? Happy to go look through dnsmasq docs BTW, but you guys might be able to set me on the right path

Bucking_Horn · May 2, 2023, 2:33pm

I wouldn't change that (or any other setting), unless you find reason to do so.

If that 1.6GB size would cover a year of DNS request for a busy network, it could just be as large as you'd want it.

If that's only a day's worth with a few clients, then there's likely something wrong in your network, and you should probably adress that underlying issue first.

Are you perhaps able to edit their /etc/hosts for NTP server domains then?

Also, some routers can be configured to serve as NTP server for their network, so that may be an option if available on yours.

And you may want to check TTLs of those NTP server domain your clients request, especially if it's always the same domain. Do clients honor the TTL, or do they just mindlessly repeat their requests?
You may also try to shadow those domain names in Pi-hole and see if that would have an effect.

If none of that can be made work, you could also consider to have those misbehaving clients by-pass Pi-hole.

By far, more often than not, there is an underlying issue that would trigger Pi-hole's rate limit or exhaust its concurrent connections (frequently, a DNS loop of sorts).
It seldlomly would matter what threshhold you'd use in those scenarios - things may just break a few seconds or fractions of a second later.
Fast fail would seem more desirable here, and you should always investigate and address the root cause before starting to consider reconfiguring Pi-hole's default limits.

DL6ER · May 2, 2023, 5:25pm

Rate limiting will show up in FTL.log as something like Rate-limiting <clientIP> for at least XXX second(s). Looking for "Rate-limiting" should be enough. Concerning exhaustion of concurrent DNS requests would be shown in pihole.log instead. Query-logging isn't required for the former, I don't think it is for the latter but I'm not 100% sure off the top of my head.

No, it is hard-coded in dnsmasq, the DNS server we use at the heart of Pi-hole's FTL. See here:

github.com/pi-hole/FTL

src/dnsmasq/forward.c

eb1978910


      
                target->forward_delay = daemon->fast_retry_time;
              }
            
            return target;
          }
          
          static void query_full(time_t now, char *domain)
          {
            static time_t last_log = 0;
            
            if ((int)difftime(now, last_log) > 5)
              {
                last_log = now;
                if (!domain || strlen(domain) == 0)
          	my_syslog(LOG_WARNING, _("Maximum number of concurrent DNS queries reached (max: %d)"), daemon->ftabsize);
                else
          	my_syslog(LOG_WARNING, _("Maximum number of concurrent DNS queries to %s reached (max: %d)"), domain, daemon->ftabsize);
              }
          }

If you'd want this adjustable, this request would need to be sent upstream to the dnsmasq project at mailto:dnsmasq-discuss@lists.thekelleys.org.uk as we keep Pi-hole related changes at the absolute minimum to avoid incompatibilities when importing updates over time.

I concur with @Bucking_Horn. Not that I don't want to make changes (we can always change things when there are good reasons to), but because every time rate-limiting appeared to be the issue in the past two years, we actually came to a final conclusion that the problem was to be solved elsewhere and rate-limiting merely revealed some off behavior. Personally, I don't think cached and forwarded queries need different rate-limits as this was originally implemented more as a kind of DoS "protection" for your Pi-hole (not by malicious attacks but by malfunctioning devices) and this is still its main purpose IMO.

So you are referring to dns-forward-max here? While we don't know anything about our user base we do actually have gotten feedback for (small) ISPs including, e.g., university-scale deployments with roughly 100,000 active clients on a daily basis. They are using Pi-hole with disabled logging and web interface (also no database), but else than that they did not mention to need any other special configuration they had to do. On the contrary, they all did tell us how surprised they were about scaling of Pi-hole at large-scales.

You mentioned above that a DNS lookup to 1.1.1. took more than 11 seconds. This is of course very extreme and not something that is acceptable and definitely worth investigation and, in the end, fixing. When queries arrive within reasonable times (on average considerably less than 100 msec), then you should not come close to 150 concurrent DNS at any point.

system · May 25, 2023, 1:20pm

This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.