dnsforward: fix misreported upstream response times

CHANGELOG.md

@@ -46,8 +46,41 @@ 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.  Those refreshes are now counted
+  as well, through the new `OnOptimisticRefresh` callback of the DNS proxy.
+
+- 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.
+
+- Clearing the DNS cache gave no feedback at all once the confirmation dialog was accepted, so
+  there was no way to tell whether it had worked.  It now shows a notification on success, the
+  way the previous user interface did; failures were already reported.
+
 [#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
 
 <!--
 NOTE: Add new changes ABOVE THIS COMMENT.

client_v2/src/__locales/en.json

@@ -214,6 +214,7 @@
   "dns_bootstrap_dns_placeholder": "IP addresses",
   "dns_bootstrap_dns_title": "Bootstrap DNS servers",
   "dns_bootstrap_servers": "Bootstrap DNS servers",
+  "dns_cache_cleared": "DNS cache cleared",
   "dns_cache_desc": "Stores DNS responses locally",
   "dns_cache_size": "Cache size",
   "dns_cache_size_desc": "Sets the DNS cache size",

client_v2/src/api/model/stats.ts

@@ -19,6 +19,8 @@ export interface Stats {
     num_replaced_parental?: number;
     /** Average time in seconds on processing a DNS request */
     avg_processing_time?: number;
+    /** Average time in seconds that the upstream DNS servers took to respond */
+    avg_upstream_response_time?: number;
     top_queried_domains?: TopArrayEntry[];
     top_clients?: TopArrayEntry[];
     top_blocked_domains?: TopArrayEntry[];

client_v2/src/components/Dashboard/Dashboard.tsx

@@ -189,7 +189,7 @@ export const Dashboard = () => {
 
                             <UpstreamAvgTime
                                 topUpstreamsAvgTime={statsState.topUpstreamsAvgTime}
-                                avgProcessingTime={statsState.avgProcessingTime}
+                                avgUpstreamResponseTime={statsState.avgUpstreamResponseTime}
                             />
                         </div>
                     </Show>

client_v2/src/components/Dashboard/blocks/UpstreamAvgTime/UpstreamAvgTime.tsx

@@ -18,7 +18,7 @@ type UpstreamInfo = {
 
 type Props = {
     topUpstreamsAvgTime: UpstreamInfo[];
-    avgProcessingTime: number;
+    avgUpstreamResponseTime: number;
 };
 
 export const UpstreamAvgTime = (props: Props) => {
@@ -44,7 +44,7 @@ export const UpstreamAvgTime = (props: Props) => {
 
                 <Show when={hasStats()}>
                     <div class={cn(theme.text.t3, s.cardSubtitle)}>
-                        {(props.avgProcessingTime ?? 0).toFixed(0)}{' '}
+                        {(props.avgUpstreamResponseTime ?? 0).toFixed(0)}{' '}
                         {intl.getMessage('milliseconds_abbreviation')}
                     </div>
                 </Show>

client_v2/src/stores/dnsConfig.ts

@@ -95,6 +95,7 @@ export const getDnsConfig = async () => {
 export const clearDnsCache = async () => {
     try {
         await cacheClear();
+        addSuccessToast(intl.getMessage('dns_cache_cleared'));
     } catch (error) {
         addErrorToast({ error });
     }

client_v2/src/stores/stats.ts

@@ -44,6 +44,7 @@ type StatsState = {
     numReplacedSafebrowsing: number;
     numReplacedSafesearch: number;
     avgProcessingTime: number;
+    avgUpstreamResponseTime: number;
     timeUnits: string;
     enabled: boolean;
     topUpstreamsAvgTime: { name: string; count: number }[];
@@ -73,6 +74,7 @@ const initialState: StatsState = {
     numReplacedSafebrowsing: 0,
     numReplacedSafesearch: 0,
     avgProcessingTime: 0,
+    avgUpstreamResponseTime: 0,
     timeUnits: TIME_UNITS?.HOURS || 'hours',
     enabled: true,
     topUpstreamsAvgTime: [],
@@ -108,6 +110,7 @@ export const getStats = async (period?: number) => {
             numReplacedSafebrowsing: data.num_replaced_safebrowsing || 0,
             numReplacedSafesearch: data.num_replaced_safesearch || 0,
             avgProcessingTime: secondsToMilliseconds(data.avg_processing_time),
+            avgUpstreamResponseTime: secondsToMilliseconds(data.avg_upstream_response_time),
             timeUnits: data.time_units || initialState.timeUnits,
             topUpstreamsAvgTime: normalizeTopStats(data.top_upstreams_avg_time || []).map(
                 (item: { name: string; count: number }) => ({

internal/dnsforward/config.go

@@ -354,6 +354,7 @@ func (s *Server) newProxyConfig(ctx context.Context) (conf *proxy.Config, err er
 		UpstreamConfig:            srvConf.UpstreamConfig,
 		PrivateRDNSUpstreamConfig: srvConf.PrivateRDNSUpstreamConfig,
 		RequestHandler:            ratelimitMw.Wrap(logMw.Wrap(s.Wrap(s))),
+		OnOptimisticRefresh:       s.handleOptimisticRefresh,
 		EnableEDNSClientSubnet:    srvConf.EDNSClientSubnet.Enabled,
 		MaxGoroutines:             srvConf.MaxGoroutines,
 		UseDNS64:                  srvConf.UseDNS64,

internal/dnsforward/stats.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"log/slog"
 	"net"
+	"net/netip"
 	"time"
 
 	"github.com/AdguardTeam/AdGuardHome/internal/aghnet"
@@ -139,15 +140,100 @@ func (s *Server) logQuery(dctx *dnsContext, ip net.IP, processingTime time.Durat
 	s.queryLog.Add(p)
 }
 
+// retryThreshold returns the duration at or above which a successful exchange
+// must have retried after an attempt that timed out, since a single attempt
+// cannot outlast the timeout it was made with.  pctx must not be nil.
+//
+// s.serverLock is expected to be locked.
+func (s *Server) retryThreshold(pctx *proxy.DNSContext) (d time.Duration) {
+	if pctx.RequestedPrivateRDNS != (netip.Prefix{}) {
+		// The private rDNS upstreams are constructed with a timeout of their
+		// own, see prepareLocalResolvers.
+		return defaultLocalTimeout
+	}
+
+	return s.conf.UpstreamTimeout
+}
+
+// appendCountedUpstreams appends those of us that should be counted in the
+// statistics to stats.
+//
+// A plain DNS upstream retries once when an attempt times out, for example
+// when a UDP datagram is lost, and reports the retried exchange as an ordinary
+// success.  Its duration is then at least the whole timeout, ten seconds by
+// default, even though the successful attempt itself took a millisecond.
+// Averaging such a sample in makes the reported response time an order of
+// magnitude higher than the actual one, so leave it out: it describes the retry
+// policy and the configured timeout rather than the speed of the upstream.
+//
+// See https://github.com/AdguardTeam/AdGuardHome/issues/8457.
+func appendCountedUpstreams(
+	stats []*proxy.UpstreamStatistics,
+	us []*proxy.UpstreamStatistics,
+	threshold time.Duration,
+) (appended []*proxy.UpstreamStatistics) {
+	for _, u := range us {
+		if threshold > 0 && u.Error == nil && u.QueryDuration >= threshold {
+			continue
+		}
+
+		stats = append(stats, u)
+	}
+
+	return stats
+}
+
+// handleOptimisticRefresh records the response times of an optimistic cache
+// refresh.  It implements [proxy.Config.OnOptimisticRefresh].  dctx must not be
+// nil.
+//
+// Such a refresh is performed in the background once an expired entry has
+// already been answered from the cache, so it reaches no request handler and
+// belongs to no client.  Without it the response times would only ever be
+// sampled from cache misses, and with the optimistic cache enabled the popular
+// names, which are exactly the ones kept warm, would never be sampled at all.
+//
+// See https://github.com/AdguardTeam/AdGuardHome/issues/8435.
+func (s *Server) handleOptimisticRefresh(dctx *proxy.DNSContext) {
+	qs := dctx.QueryStatistics()
+	if qs == nil || dctx.Req == nil || len(dctx.Req.Question) == 0 {
+		return
+	}
+
+	domain := aghnet.NormalizeDomain(dctx.Req.Question[0].Name)
+
+	// Synchronize access to s.stats so it won't be suddenly uninitialized while
+	// in use, the same way processQueryLogsAndStats does.
+	s.serverLock.RLock()
+	defer s.serverLock.RUnlock()
+
+	if s.stats == nil {
+		return
+	}
+
+	threshold := s.retryThreshold(dctx)
+	for _, u := range appendCountedUpstreams(nil, qs.Main(), threshold) {
+		if u.IsCached || u.Error != nil {
+			continue
+		}
+
+		s.stats.UpdateUpstream(&stats.UpstreamEntry{
+			Address:       u.Address,
+			Domain:        domain,
+			QueryDuration: u.QueryDuration,
+		})
+	}
+}
+
 // updateStats writes the request data into statistics.
 func (s *Server) updateStats(dctx *dnsContext, clientIP string, processingTime time.Duration) {
 	pctx := dctx.proxyCtx
 
 	var upstreamStats []*proxy.UpstreamStatistics
-	qs := pctx.QueryStatistics()
-	if qs != nil {
-		upstreamStats = append(upstreamStats, qs.Main()...)
-		upstreamStats = append(upstreamStats, qs.Fallback()...)
+	if qs := pctx.QueryStatistics(); qs != nil {
+		threshold := s.retryThreshold(pctx)
+		upstreamStats = appendCountedUpstreams(upstreamStats, qs.Main(), threshold)
+		upstreamStats = appendCountedUpstreams(upstreamStats, qs.Fallback(), threshold)
 	}
 
 	e := &stats.Entry{