all: add upstream time

internal/dnsforward/stats.go

@@ -131,9 +131,10 @@ func (s *Server) updateStats(dctx *dnsContext, clientIP string) {
 	pctx := dctx.proxyCtx
 
 	e := &stats.Entry{
-		Domain: aghnet.NormalizeDomain(pctx.Req.Question[0].Name),
-		Result: stats.RNotFiltered,
-		Time:   pctx.QueryDuration,
+		Domain:          aghnet.NormalizeDomain(pctx.Req.Question[0].Name),
+		Result:          stats.RNotFiltered,
+		ProcesssingTime: time.Since(dctx.startTime),
+		UpstreamTime:    pctx.QueryDuration,
 	}
 
 	if pctx.Upstream != nil {

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,
+			ProcesssingTime: time.Since(startTime),
 		}
 
 		start.Done()

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,
+			ProcesssingTime: 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,
+			ProcesssingTime: 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,
+				ProcesssingTime: 123456,
 			}
 			s.Update(e)
 		}

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
+	// ProcesssingTime is the duration of the request processing from the start
+	// of the request including timeouts.
+	ProcesssingTime 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.
@@ -323,13 +327,14 @@ func (u *unit) add(e *Entry) {
 	}
 
 	u.clients[e.Client]++
+	pt := uint64(e.ProcesssingTime.Microseconds())
+	u.timeSum += pt
 	u.nTotal++
 
 	if e.Upstream != "" {
 		u.upstreamsResponses[e.Upstream]++
-		t := uint64(e.Time.Microseconds())
-		u.timeSum += t
-		u.upstreamsTimeSum[e.Upstream] += t
+		ut := uint64(e.UpstreamTime.Microseconds())
+		u.upstreamsTimeSum[e.Upstream] += ut
 	}
 }