Pull request 2054: 6220-average-processing-time

Updates #6220. Squashed commit of the following: commit 2ad87979b4f8ade2cad8a1b86b8e0663dd53b098 Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Thu Nov 9 13:55:09 2023 +0300 all: upd go commit 387200c3de899e6f59e8d2455cb2aa2b7194b311 Merge: 37f2855ed f8fe9bfc8 Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Thu Nov 9 13:49:59 2023 +0300 Merge branch 'master' into 6220-average-processing-time commit 37f2855ed104c20faa3f4d57d48bd221a59cacb3 Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Wed Nov 8 17:08:13 2023 +0300 client: upd locales commit a09be4183811cef29b594f9916dc76b87f89d304 Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Tue Nov 7 20:46:24 2023 +0300 all: imp docs commit f0b85ac1fef366da37b996d53e29d76d6279691f Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Fri Nov 3 14:17:32 2023 +0300 all: add todo commit 48a5879865a1625410787edef6d78b309056af7b Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Fri Nov 3 13:38:14 2023 +0300 all: add upstream time commit 4d7431c00e24f8a9d3e86160851b5ef3bd9d03fa Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Tue Oct 31 17:27:19 2023 +0300 all: upd chlog commit 040b6b9cdebea2c9789d4d38f2a0a40ef4cb26d7 Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Tue Oct 31 15:42:04 2023 +0300 all: imp average processing time
2023-11-09 16:14:05 +03:00
parent f8fe9bfc8b
commit d3862614e5
48 changed files with 70 additions and 100 deletions
--- a/internal/dnsforward/dnsforward.go
+++ b/internal/dnsforward/dnsforward.go
@@ -354,9 +354,8 @@ func (s *Server) Exchange(ip netip.Addr) (host string, ttl time.Duration, err er
 	}

 	dctx := &proxy.DNSContext{
-		Proto:     "udp",
-		Req:       req,
-		StartTime: time.Now(),
+		Proto: "udp",
+		Req:   req,
 	}

 	var resolver *proxy.Proxy
--- a/internal/dnsforward/msg.go
+++ b/internal/dnsforward/msg.go
@@ -2,7 +2,6 @@ package dnsforward

 import (
 	"net/netip"
-	"time"

 	"github.com/AdguardTeam/AdGuardHome/internal/filtering"
 	"github.com/AdguardTeam/dnsproxy/proxy"
@@ -270,10 +269,9 @@ func (s *Server) genBlockedHost(request *dns.Msg, newAddr string, d *proxy.DNSCo
 	replReq.RecursionDesired = true

 	newContext := &proxy.DNSContext{
-		Proto:     d.Proto,
-		Addr:      d.Addr,
-		StartTime: time.Now(),
-		Req:       &replReq,
+		Proto: d.Proto,
+		Addr:  d.Addr,
+		Req:   &replReq,
 	}

 	prx := s.proxy()
--- a/internal/dnsforward/stats.go
+++ b/internal/dnsforward/stats.go
@@ -20,11 +20,10 @@ func (s *Server) processQueryLogsAndStats(dctx *dnsContext) (rc resultCode) {
 	log.Debug("dnsforward: started processing querylog and stats")
 	defer log.Debug("dnsforward: finished processing querylog and stats")

-	elapsed := time.Since(dctx.startTime)
 	pctx := dctx.proxyCtx
-
 	q := pctx.Req.Question[0]
 	host := aghnet.NormalizeDomain(q.Name)
+	processingTime := time.Since(dctx.startTime)

 	ip, _ := netutil.IPAndPortFromAddr(pctx.Addr)
 	ip = slices.Clone(ip)
@@ -43,7 +42,7 @@ func (s *Server) processQueryLogsAndStats(dctx *dnsContext) (rc resultCode) {
 	defer s.serverLock.RUnlock()

 	if s.shouldLog(host, qt, cl, ids) {
-		s.logQuery(dctx, pctx, elapsed, ip)
+		s.logQuery(dctx, ip, processingTime)
 	} else {
 		log.Debug(
 			"dnsforward: request %s %s %q from %s ignored; not adding to querylog",
@@ -55,7 +54,7 @@ func (s *Server) processQueryLogsAndStats(dctx *dnsContext) (rc resultCode) {
 	}

 	if s.shouldCountStat(host, qt, cl, ids) {
-		s.updateStats(dctx, elapsed, *dctx.result, ipStr)
+		s.updateStats(dctx, ipStr, processingTime)
 	} else {
 		log.Debug(
 			"dnsforward: request %s %s %q from %s ignored; not counting in stats",
@@ -90,12 +89,9 @@ func (s *Server) shouldCountStat(host string, qt, cl uint16, ids []string) (ok b
 }

 // logQuery pushes the request details into the query log.
-func (s *Server) logQuery(
-	dctx *dnsContext,
-	pctx *proxy.DNSContext,
-	elapsed time.Duration,
-	ip net.IP,
-) {
+func (s *Server) logQuery(dctx *dnsContext, ip net.IP, processingTime time.Duration) {
+	pctx := dctx.proxyCtx
+
 	p := &querylog.AddParams{
 		Question:          pctx.Req,
 		ReqECS:            pctx.ReqECS,
@@ -104,7 +100,7 @@ func (s *Server) logQuery(
 		Result:            dctx.result,
 		ClientID:          dctx.clientID,
 		ClientIP:          ip,
-		Elapsed:           elapsed,
+		Elapsed:           processingTime,
 		AuthenticatedData: dctx.responseAD,
 	}

@@ -132,30 +128,27 @@ func (s *Server) logQuery(
 }

 // updatesStats writes the request into statistics.
-func (s *Server) updateStats(
-	ctx *dnsContext,
-	elapsed time.Duration,
-	res filtering.Result,
-	clientIP string,
-) {
-	pctx := ctx.proxyCtx
+func (s *Server) updateStats(dctx *dnsContext, clientIP string, processingTime time.Duration) {
+	pctx := dctx.proxyCtx
+
 	e := &stats.Entry{
-		Domain: aghnet.NormalizeDomain(pctx.Req.Question[0].Name),
-		Result: stats.RNotFiltered,
-		Time:   elapsed,
+		Domain:         aghnet.NormalizeDomain(pctx.Req.Question[0].Name),
+		Result:         stats.RNotFiltered,
+		ProcessingTime: processingTime,
+		UpstreamTime:   pctx.QueryDuration,
 	}

 	if pctx.Upstream != nil {
 		e.Upstream = pctx.Upstream.Address()
 	}

-	if clientID := ctx.clientID; clientID != "" {
+	if clientID := dctx.clientID; clientID != "" {
 		e.Client = clientID
 	} else {
 		e.Client = clientIP
 	}

-	switch res.Reason {
+	switch dctx.result.Reason {
 	case filtering.FilteredSafeBrowsing:
 		e.Result = stats.RSafeBrowsing
 	case filtering.FilteredParental:
--- a/internal/stats/stats_internal_test.go
+++ b/internal/stats/stats_internal_test.go
@@ -33,10 +33,10 @@ func TestStats_races(t *testing.T) {

 	writeFunc := func(start, fin *sync.WaitGroup, waitCh <-chan unit, i int) {
 		e := &Entry{
-			Domain: fmt.Sprintf("example-%d.org", i),
-			Client: fmt.Sprintf("client_%d", i),
-			Result: Result(i)%(resultLast-1) + 1,
-			Time:   time.Since(startTime),
+			Domain:         fmt.Sprintf("example-%d.org", i),
+			Client:         fmt.Sprintf("client_%d", i),
+			Result:         Result(i)%(resultLast-1) + 1,
+			ProcessingTime: time.Since(startTime),
 		}

 		start.Done()
--- a/internal/stats/stats_test.go
+++ b/internal/stats/stats_test.go
@@ -76,17 +76,19 @@ func TestStats(t *testing.T) {
 		const respUpstream = "upstream"

 		entries := []*stats.Entry{{
-			Domain:   reqDomain,
-			Client:   cliIPStr,
-			Result:   stats.RFiltered,
-			Time:     time.Microsecond * 123456,
-			Upstream: respUpstream,
+			Domain:         reqDomain,
+			Client:         cliIPStr,
+			Result:         stats.RFiltered,
+			ProcessingTime: time.Microsecond * 123456,
+			Upstream:       respUpstream,
+			UpstreamTime:   time.Microsecond * 222222,
 		}, {
-			Domain:   reqDomain,
-			Client:   cliIPStr,
-			Result:   stats.RNotFiltered,
-			Time:     time.Microsecond * 123456,
-			Upstream: respUpstream,
+			Domain:         reqDomain,
+			Client:         cliIPStr,
+			Result:         stats.RNotFiltered,
+			ProcessingTime: time.Microsecond * 123456,
+			Upstream:       respUpstream,
+			UpstreamTime:   time.Microsecond * 222222,
 		}}

 		wantData := &stats.StatsResp{
@@ -95,7 +97,7 @@ func TestStats(t *testing.T) {
 			TopClients:            []map[string]uint64{0: {cliIPStr: 2}},
 			TopBlocked:            []map[string]uint64{0: {reqDomain: 1}},
 			TopUpstreamsResponses: []map[string]uint64{0: {respUpstream: 2}},
-			TopUpstreamsAvgTime:   []map[string]float64{0: {respUpstream: 0.123456}},
+			TopUpstreamsAvgTime:   []map[string]float64{0: {respUpstream: 0.222222}},
 			DNSQueries: []uint64{
 				0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
 				0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2,
@@ -196,10 +198,10 @@ func TestLargeNumbers(t *testing.T) {
 		for i := 0; i < cliNumPerHour; i++ {
 			ip := net.IP{127, 0, byte((i & 0xff00) >> 8), byte(i & 0xff)}
 			e := &stats.Entry{
-				Domain: fmt.Sprintf("domain%d.hour%d", i, h),
-				Client: ip.String(),
-				Result: stats.RNotFiltered,
-				Time:   123456,
+				Domain:         fmt.Sprintf("domain%d.hour%d", i, h),
+				Client:         ip.String(),
+				Result:         stats.RNotFiltered,
+				ProcessingTime: 123456,
 			}
 			s.Update(e)
 		}
--- a/internal/stats/unit.go
+++ b/internal/stats/unit.go
@@ -68,8 +68,12 @@ type Entry struct {
 	// Result is the result of processing the request.
 	Result Result

-	// Time is the duration of the request processing.
-	Time time.Duration
+	// ProcessingTime is the duration of the request processing from the start
+	// of the request including timeouts.
+	ProcessingTime time.Duration
+
+	// UpstreamTime is the duration of the successful request to the upstream.
+	UpstreamTime time.Duration
 }

 // validate returns an error if entry is not valid.
@@ -103,8 +107,8 @@ type unit struct {
 	// upstreamsResponses stores the number of responses from each upstream.
 	upstreamsResponses map[string]uint64

-	// upstreamsTimeSum stores the sum of processing time in microseconds of
-	// responses from each upstream.
+	// upstreamsTimeSum stores the sum of durations of successful queries in
+	// microseconds to each upstream.
 	upstreamsTimeSum map[string]uint64

 	// nResult stores the number of requests grouped by it's result.
@@ -323,13 +327,14 @@ func (u *unit) add(e *Entry) {
 	}

 	u.clients[e.Client]++
-	t := uint64(e.Time.Microseconds())
-	u.timeSum += t
+	pt := uint64(e.ProcessingTime.Microseconds())
+	u.timeSum += pt
 	u.nTotal++

 	if e.Upstream != "" {
 		u.upstreamsResponses[e.Upstream]++
-		u.upstreamsTimeSum[e.Upstream] += t
+		ut := uint64(e.UpstreamTime.Microseconds())
+		u.upstreamsTimeSum[e.Upstream] += ut
 	}
 }