From a201f7de01db7824dfbb7a5883fbc3719c0dc33b Mon Sep 17 00:00:00 2001 From: Aditya Nugraha Date: Mon, 3 Aug 2026 10:57:25 +0700 Subject: [PATCH 1/6] dnsforward: fix misreported upstream response times The dashboard's upstream response times were wrong in four independent ways: inflated by roughly 2-4x whenever optimistic caching was enabled, far higher than the actual network latency to the upstream servers, shown against a headline figure that measured something else entirely, and averaged over time incorrectly. 1. The response times were taken from the per-request proxy.DNSContext.QueryStatistics, and the entries marked as served from the cache were skipped. An optimistic cache hit is answered from the cache right away while dnsproxy refreshes the expired entry in a background goroutine that uses a cloned DNSContext, whose statistics are discarded. Popular domain names are therefore never sampled at all, and the average ends up being based on cache misses alone, which are skewed towards the rare domain names that upstreams resolve slower. Collect the response times from a *statsUpstream decorator wrapping every upstream.Upstream instead. It sits below dnsproxy, so it observes every exchange, foreground and background alike, and it becomes the single source of truth: stats.Entry.UpstreamStats is removed so that nothing is counted twice. The decorator is applied to the general, private-rDNS, fallback, and per-client custom upstream configurations. 2. A plain DNS upstream retries once when an attempt times out, for example when a UDP datagram is lost, and the retried exchange succeeds. Its duration is then at least the whole upstream timeout, which defaults to ten seconds, even though the successful attempt itself took about a millisecond. Averaged in as an ordinary response, a single such sample outweighs a hundred normal ones several times over, which is what made the reported times bear no relation to the round-trip time. Skip the exchanges whose duration reaches the timeout, since a single attempt cannot take that long, so their duration describes the retry policy and the configured timeout rather than the speed of the upstream. 3. The "Average upstream response time" panel showed avg_processing_time as its headline, which is the time AdGuard Home itself takes and covers every request, including the ones answered from the cache or blocked by a filter. Those take almost no time, so the headline was typically an order of magnitude lower than every upstream listed right below it. Add an avg_upstream_response_time property to GET /control/stats, averaged over the responses of the upstream servers, and show that instead. 4. The average processing time was the unweighted mean of the per-hour means, so an hour with a handful of requests weighed as much as an hour with tens of thousands of them. Weight it by the number of requests, the way the upstream response times already were. Two things constrain the implementation: - The wrapping is done in place on s.conf.UpstreamConfig rather than on a copy handed to the proxy, because several tests assign mock upstreams to it after Prepare and rely on the proxy sharing that pointer. - The decorator must not acquire Server.serverLock. Server.Resolve holds it for reading while driving the internal proxy over the same upstreams, so a nested RLock would deadlock whenever a writer queues between the two. Hence Server.upstreamStats, which is set once in NewServer and never reset. Note that the metric now also counts the internal proxy's lookups (client rDNS, updater) and DNS64 sub-queries, and that the statistics "ignored clients" list no longer applies to upstream timings, since a background refresh has no client to attribute it to. The ignored *domains* list is still honoured. Closes #8435. Closes #8457. --- CHANGELOG.md | 29 ++ client_v2/src/api/model/stats.ts | 2 + .../src/components/Dashboard/Dashboard.tsx | 2 +- .../UpstreamAvgTime/UpstreamAvgTime.tsx | 4 +- client_v2/src/stores/stats.ts | 3 + internal/client/upstreammanager.go | 19 +- internal/dnsforward/dnsforward.go | 32 +- internal/dnsforward/stats.go | 11 +- internal/dnsforward/stats_internal_test.go | 30 +- internal/dnsforward/upstreamstats.go | 165 +++++++++ .../dnsforward/upstreamstats_internal_test.go | 315 ++++++++++++++++++ internal/stats/http.go | 9 + internal/stats/stats.go | 46 +++ internal/stats/stats_test.go | 24 +- internal/stats/unit.go | 97 ++++-- internal/stats/unit_internal_test.go | 33 ++ openapi/CHANGELOG.md | 4 + openapi/openapi.yaml | 13 +- 18 files changed, 785 insertions(+), 53 deletions(-) create mode 100644 internal/dnsforward/upstreamstats.go create mode 100644 internal/dnsforward/upstreamstats_internal_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 4f0a676a578..d90533f3616 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -46,8 +46,37 @@ NOTE: Add new changes BELOW THIS COMMENT. - Blocked requests without an EDNS(0) OPT record ([#8183]). +- Inflated average upstream response time on the dashboard when optimistic caching is enabled + ([#8435]). An optimistic cache hit is answered from the cache right away and the expired entry + is refreshed by a background query, and those background queries used to be left out of the + statistics. The average was therefore based on cache misses alone, which are skewed towards + rare domain names that the upstream itself resolves slower. Every exchange with an upstream + server is now counted, including the background ones. + +- Upstream response times on the dashboard being far higher than the actual network latency to + the upstream servers ([#8457]). A plain DNS upstream retries once when an attempt times out, + for example when a UDP datagram is lost, so a retried exchange takes at least the whole + `upstream_timeout`, ten seconds by default, even though the successful attempt itself took a + millisecond. Such an exchange used to be averaged in as an ordinary response, where a single + one of them outweighed a hundred normal ones several times over. Exchanges that had to retry + after a timeout are no longer counted, since their duration describes the retry policy and the + configured timeout rather than the speed of the upstream. + +- The "Average upstream response time" panel on the dashboard showed the average *processing* + time next to the list of per-upstream response times. Processing time covers every request, + including the ones answered from the cache or blocked by a filter, which take almost no time, + so the panel's headline was typically an order of magnitude lower than every upstream listed + below it. It now shows the new `avg_upstream_response_time` property of `GET /control/stats`, + which is averaged over the responses of the upstream servers. + +- The average processing time was the unweighted mean of the hourly means, which gave an hour + with a handful of requests the same weight as an hour with tens of thousands of them. It is + now weighted by the number of requests, the same way the upstream response times already were. + [#7514]: https://github.com/AdguardTeam/AdGuardHome/issues/7514 [#8183]: https://github.com/AdguardTeam/AdGuardHome/issues/8183 +[#8435]: https://github.com/AdguardTeam/AdGuardHome/issues/8435 +[#8457]: https://github.com/AdguardTeam/AdGuardHome/issues/8457