include gorouter_time metrics report

Author: kart2bc

accesslog/schema/access_log_record.go

@@ -124,6 +124,7 @@ type AccessLogRecord struct {
 	TlsHandshakeFinishedAt      time.Time
 	AppRequestFinishedAt        time.Time
 	FinishedAt                  time.Time
+	GorouterTime                float64
 
 	LocalAddress string
 }
@@ -136,17 +137,6 @@ func (r *AccessLogRecord) roundtripTime() float64 {
 	return r.FinishedAt.Sub(r.ReceivedAt).Seconds()
 }
 
-func (r *AccessLogRecord) gorouterTime() float64 {
-	rt := r.roundtripTime()
-	at := r.appTime()
-
-	if rt >= 0 && at >= 0 {
-		return rt - at
-	} else {
-		return -1
-	}
-}
-
 func (r *AccessLogRecord) dialTime() float64 {
 	if r.DialStartedAt.IsZero() || r.DialFinishedAt.IsZero() {
 		return -1
@@ -168,10 +158,6 @@ func (r *AccessLogRecord) tlsTime() float64 {
 	return r.TlsHandshakeFinishedAt.Sub(r.TlsHandshakeStartedAt).Seconds()
 }
 
-func (r *AccessLogRecord) appTime() float64 {
-	return r.AppRequestFinishedAt.Sub(r.AppRequestStartedAt).Seconds()
-}
-
 // failedAttemptsTime will be negative if there was no failed attempt.
 func (r *AccessLogRecord) failedAttemptsTime() float64 {
 	if r.LastFailedAttemptFinishedAt.IsZero() {
@@ -281,7 +267,7 @@ func (r *AccessLogRecord) makeRecord(performTruncate bool) []byte {
 
 	// #nosec  G104 - ignore errors from writing the access log as it will only cause more errors to log this error
 	b.WriteString(`gorouter_time:`)
-	b.WriteDashOrFloatValue(r.gorouterTime())
+	b.WriteDashOrFloatValue(r.GorouterTime)
 
 	// #nosec  G104 - ignore errors from writing the access log as it will only cause more errors to log this error
 	b.WriteString(`app_id:`)

config/config.go

@@ -126,13 +126,15 @@ var defaultPrometheusConfig = PrometheusConfig{
 
 type MetersConfig struct {
 	RouteLookupTimeHistogramBuckets          []float64 `yaml:"route_lookup_time_histogram_buckets,omitempty"`
+	GorouterTimeHistogramBuckets             []float64 `yaml:"gorouter_time_histogram_buckets,omitempty"`
 	RouteRegistrationLatencyHistogramBuckets []float64 `yaml:"route_registration_latency_histogram_buckets,omitempty"`
 	RoutingResponseLatencyHistogramBuckets   []float64 `yaml:"routing_response_latency_histogram_buckets,omitempty"`
 	HTTPLatencyHistogramBuckets              []float64 `yaml:"http_latency_histogram_buckets,omitempty"`
 }
 
 var defaultMetersConfig = MetersConfig{
 	RouteLookupTimeHistogramBuckets:          []float64{10_000, 20_000, 30_000, 40_000, 50_000, 60_000, 70_000, 80_000, 90_000, 100_000},
+	GorouterTimeHistogramBuckets:             []float64{1, 2, 4, 6, 8, 10, 20, 40, 50, 100, 500, 1000},
 	RouteRegistrationLatencyHistogramBuckets: []float64{0.1, 0.5, 1, 1.5, 2, 2.5, 3, 3.5, 4},
 	RoutingResponseLatencyHistogramBuckets:   []float64{1, 2, 4, 6, 8, 10, 20, 40, 50, 100, 500, 1000},
 	HTTPLatencyHistogramBuckets:              []float64{0.1, 0.2, 0.4, 0.8, 1.6, 3.2, 6.4, 12.8, 25.6},

config/config_test.go

@@ -252,6 +252,7 @@ prometheus:
   meters:
     route_lookup_time_histogram_buckets: [0, 100, 10000]
     route_registration_latency_histogram_buckets: [-10, 0, 10]
+    gorouter_time_histogram_buckets: [1,2,4]
     routing_response_latency_histogram_buckets: [0.1, 0.5, 1]
 `)
 
@@ -260,6 +261,7 @@ prometheus:
 
 			Expect(config.Prometheus.Meters.RouteLookupTimeHistogramBuckets).To(Equal([]float64{0, 100, 10000}))
 			Expect(config.Prometheus.Meters.RouteRegistrationLatencyHistogramBuckets).To(Equal([]float64{-10, 0, 10}))
+			Expect(config.Prometheus.Meters.GorouterTimeHistogramBuckets).To(Equal([]float64{1, 2, 4}))
 			Expect(config.Prometheus.Meters.RoutingResponseLatencyHistogramBuckets).To(Equal([]float64{0.1, 0.5, 1}))
 		})
 

handlers/access_log.go

@@ -6,7 +6,6 @@ import (
 	"net/http"
 	"slices"
 	"sync/atomic"
-	"time"
 
 	"github.com/urfave/negroni/v3"
 
@@ -60,8 +59,6 @@ func (a *accessLog) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http
 		return
 	}
 
-	reqInfo.FinishedAt = time.Now()
-
 	alr.HeadersOverride = reqInfo.BackendReqHeaders
 	alr.RouteEndpoint = reqInfo.RouteEndpoint
 	alr.RequestBytesReceived = requestBodyCounter.GetCount()
@@ -82,6 +79,7 @@ func (a *accessLog) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http
 	alr.TlsHandshakeFinishedAt = reqInfo.TlsHandshakeFinishedAt
 	alr.AppRequestFinishedAt = reqInfo.AppRequestFinishedAt
 	alr.FinishedAt = reqInfo.FinishedAt
+	alr.GorouterTime = reqInfo.GorouterTime
 
 	alr.LocalAddress = reqInfo.LocalAddress
 

handlers/access_log_test.go

@@ -107,7 +107,6 @@ var _ = Describe("AccessLog", func() {
 		Expect(alr.Request.URL).To(Equal(req.URL))
 		Expect(alr.Request.RemoteAddr).To(Equal(req.RemoteAddr))
 		Expect(alr.ExtraHeadersToLog).To(Equal(extraHeadersToLog))
-		Expect(alr.FinishedAt).ToNot(BeZero())
 		Expect(alr.RequestBytesReceived).To(Equal(13))
 		Expect(alr.BodyBytesSent).To(Equal(37))
 		Expect(alr.StatusCode).To(Equal(http.StatusTeapot))

handlers/reporter.go

@@ -57,6 +57,22 @@ func (rh *reporterHandler) ServeHTTP(rw http.ResponseWriter, r *http.Request, ne
 		requestInfo.RouteEndpoint, proxyWriter.Status(),
 		requestInfo.ReceivedAt, requestInfo.AppRequestFinishedAt.Sub(requestInfo.ReceivedAt),
 	)
+	rh.calculateGorouterTime(requestInfo)
+	rh.reporter.CaptureGorouterTime(requestInfo.GorouterTime)
+}
+
+// calculateGorouterTime
+// calculate the gorouter time by subtracting app response time from the total roundtrip time.
+// Parameters:
+//   - requestInfo *RequestInfo
+func (rh *reporterHandler) calculateGorouterTime(requestInfo *RequestInfo) {
+	requestInfo.FinishedAt = time.Now()
+	requestInfo.GorouterTime = -1
+	appTime := requestInfo.AppRequestFinishedAt.Sub(requestInfo.AppRequestStartedAt).Seconds()
+	rtTime := requestInfo.FinishedAt.Sub(requestInfo.ReceivedAt).Seconds()
+	if rtTime >= 0 && appTime >= 0 {
+		requestInfo.GorouterTime = rtTime - appTime
+	}
 }
 
 // validContentLength ensures that if the `Content-Length` header is set, it is not empty.

handlers/reporter_test.go

@@ -2,6 +2,7 @@ package handlers_test
 
 import (
 	"bytes"
+	"fmt"
 	"io"
 	"net/http"
 	"net/http/httptest"
@@ -51,7 +52,10 @@ var _ = Describe("Reporter Handler", func() {
 			reqInfo, err := handlers.ContextRequestInfo(req)
 			Expect(err).NotTo(HaveOccurred())
 			reqInfo.RouteEndpoint = route.NewEndpoint(&route.EndpointOpts{AppId: "appID", PrivateInstanceIndex: "1", PrivateInstanceId: "id"})
-			reqInfo.AppRequestFinishedAt = time.Now()
+			timeNow := time.Now()
+			reqInfo.ReceivedAt = timeNow.Add(-1 * time.Millisecond)
+			reqInfo.AppRequestStartedAt = timeNow.Add(1 * time.Millisecond)
+			reqInfo.AppRequestFinishedAt = timeNow.Add(2 * time.Millisecond)
 
 			nextCalled = true
 		})
@@ -103,6 +107,12 @@ var _ = Describe("Reporter Handler", func() {
 		Expect(latency).To(BeNumerically(">", 0))
 		Expect(latency).To(BeNumerically("<", 10*time.Millisecond))
 
+		Expect(fakeReporter.CaptureGorouterTimeCallCount()).To(Equal(1))
+		gorouterTime := fakeReporter.CaptureGorouterTimeArgsForCall(0)
+		fmt.Println(gorouterTime)
+		Expect(gorouterTime).To(BeNumerically(">", 0))
+		Expect(gorouterTime).To(BeNumerically("<", 1*time.Millisecond))
+
 		Expect(nextCalled).To(BeTrue(), "Expected the next handler to be called.")
 	})
 

handlers/requestinfo.go

@@ -63,6 +63,8 @@ type RequestInfo struct {
 	// recorded before the access log, but we need the value to be able to
 	// produce the log.
 	FinishedAt time.Time
+	// GorouterTime is calculated in the reporter
+	GorouterTime float64
 
 	RoutePool                         *route.EndpointPool
 	RouteEndpoint                     *route.Endpoint

metrics/compositereporter.go

@@ -30,6 +30,7 @@ type MetricReporter interface {
 	CaptureRoutingRequest(b *route.Endpoint)
 	CaptureRoutingResponse(statusCode int)
 	CaptureRoutingResponseLatency(b *route.Endpoint, statusCode int, t time.Time, d time.Duration)
+	CaptureGorouterTime(gorouterTime float64)
 	CaptureRouteServiceResponse(res *http.Response)
 	CaptureWebSocketUpdate()
 	CaptureWebSocketFailure()
@@ -131,6 +132,12 @@ func (m MultiMetricReporter) CaptureRoutingResponseLatency(b *route.Endpoint, st
 	}
 }
 
+func (m MultiMetricReporter) CaptureGorouterTime(gorouterTime float64) {
+	for _, r := range m {
+		r.CaptureGorouterTime(gorouterTime)
+	}
+}
+
 func (m MultiMetricReporter) CaptureWebSocketUpdate() {
 	for _, r := range m {
 		r.CaptureWebSocketUpdate()

metrics/compositereporter_test.go

@@ -91,6 +91,14 @@ var _ = Describe("CompositeReporter", func() {
 		Expect(callDuration).To(Equal(responseDuration))
 	})
 
+	It("forwards CaptureGorouterTime to Multireporter", func() {
+		composite.CaptureGorouterTime(3000)
+
+		Expect(fakeMultiReporter.CaptureGorouterTimeCallCount()).To(Equal(1))
+		value := fakeMultiReporter.CaptureGorouterTimeArgsForCall(0)
+		Expect(value).To(BeEquivalentTo(3000))
+	})
+
 	It("forwards CaptureRoutingServiceResponse to proxy reporter", func() {
 		composite.CaptureRouteServiceResponse(response)
 

metrics/fakes/fake_metricreporter.go

@@ -77,6 +77,16 @@ func (m *Metrics) CaptureRoutingResponse(statusCode int) {
 	m.Batcher.BatchIncrementCounter("responses")
 }
 
+func (m *Metrics) CaptureGorouterTime(gorouterTime float64) {
+	if m.PerRequestMetricsReporting {
+		unit := "ms"
+		err := m.Sender.SendValue("gorouter_time", gorouterTime*1000, unit)
+		if err != nil {
+			m.Logger.Debug("failed-sending-metric", log.ErrAttr(err), slog.String("metric", "gorouter_time"))
+		}
+	}
+}
+
 func (m *Metrics) CaptureRoutingResponseLatency(b *route.Endpoint, _ int, _ time.Time, d time.Duration) {
 	if m.PerRequestMetricsReporting {
 		//this function has extra arguments to match varz reporter

metrics/fakes/fake_varzreporter.go

@@ -439,6 +439,25 @@ var _ = Describe("MetricsReporter", func() {
 		Expect(sender.SendValueCallCount()).To(Equal(0))
 	})
 
+	It("sends the gorouter time", func() {
+		metricReporter.CaptureGorouterTime(3)
+
+		Expect(sender.SendValueCallCount()).To(Equal(1))
+		name, value, unit := sender.SendValueArgsForCall(0)
+		Expect(name).To(Equal("gorouter_time"))
+		Expect(value).To(BeEquivalentTo(3000))
+		Expect(unit).To(Equal("ms"))
+
+	})
+
+	It("does not send the goroutertime if switched off", func() {
+		metricReporter.PerRequestMetricsReporting = false
+		metricReporter.CaptureGorouterTime(3)
+
+		Expect(sender.SendValueCallCount()).To(Equal(0))
+
+	})
+
 	Context("sends route metrics", func() {
 		var endpoint *route.Endpoint
 

metrics/metricsreporter.go

@@ -21,6 +21,7 @@ type Metrics struct {
 	TotalRoutes                 mr.Gauge
 	TimeSinceLastRegistryUpdate mr.Gauge
 	RouteLookupTime             mr.Histogram
+	GorouterTime                mr.Histogram
 	RouteRegistrationLatency    mr.Histogram
 	RoutingRequest              mr.CounterVec
 	BadRequest                  mr.Counter
@@ -66,6 +67,7 @@ func NewMetrics(registry *mr.Registry, perRequestMetricsReporting bool, meterCon
 		TotalRoutes:                 registry.NewGauge("total_routes", "number of total routes"),
 		TimeSinceLastRegistryUpdate: registry.NewGauge("ms_since_last_registry_update", "time since last registry update in ms"),
 		RouteLookupTime:             registry.NewHistogram("route_lookup_time", "route lookup time per request in ns", meterConfig.RouteLookupTimeHistogramBuckets),
+		GorouterTime:                registry.NewHistogram("gorouter_time", "gorouter time per request in seconds", meterConfig.GorouterTimeHistogramBuckets),
 		RouteRegistrationLatency:    registry.NewHistogram("route_registration_latency", "route registration latency in ms", meterConfig.RouteRegistrationLatencyHistogramBuckets),
 		RoutingRequest:              registry.NewCounterVec("total_requests", "number of routing requests", []string{"component"}),
 		BadRequest:                  registry.NewCounter("rejected_requests", "number of rejected requests"),
@@ -115,6 +117,12 @@ func (metrics *Metrics) CaptureLookupTime(t time.Duration) {
 	}
 }
 
+func (metrics *Metrics) CaptureGorouterTime(t float64) {
+	if metrics.perRequestMetricsReporting {
+		metrics.GorouterTime.Observe(t)
+	}
+}
+
 func (metrics *Metrics) CaptureRouteRegistrationLatency(t time.Duration) {
 	metrics.RouteRegistrationLatency.Observe(float64(t) / float64(time.Millisecond))
 }

metrics/metricsreporter_test.go

@@ -85,6 +85,15 @@ var _ = Describe("Metrics", func() {
 			Expect(getMetrics(r.Port())).To(ContainSubstring("route_lookup_time_bucket{le=\"100000\"} 1"))
 		})
 
+		It("sends the gorouter time per request", func() {
+			m.CaptureGorouterTime(1)
+			Expect(getMetrics(r.Port())).To(ContainSubstring("gorouter_time_bucket{le=\"1.2\"} 1"))
+
+			m.perRequestMetricsReporting = false
+			m.CaptureGorouterTime(1)
+			Expect(getMetrics(r.Port())).To(ContainSubstring("gorouter_time_bucket{le=\"1.2\"} 1"))
+		})
+
 		It("increments the routes pruned metric", func() {
 			m.CaptureRoutesPruned(50)
 			Expect(getMetrics(r.Port())).To(ContainSubstring(`routes_pruned 50`))
@@ -451,6 +460,7 @@ var _ = Describe("Metrics", func() {
 func getMetersConfig() config.MetersConfig {
 	return config.MetersConfig{
 		RouteLookupTimeHistogramBuckets:          []float64{10_000, 20_000, 30_000, 40_000, 50_000, 60_000, 70_000, 80_000, 90_000, 100_000},
+		GorouterTimeHistogramBuckets:             []float64{0.2, 0.4, 0.6, 0.8, 1, 1.2, 1.4, 1.6, 1.8, 2},
 		RouteRegistrationLatencyHistogramBuckets: []float64{0.2, 0.4, 0.6, 0.8, 1, 1.2, 1.4, 1.6, 1.8, 2},
 		RoutingResponseLatencyHistogramBuckets:   []float64{0.2, 0.4, 0.6, 0.8, 1, 1.2, 1.4, 1.6, 1.8, 2},
 		HTTPLatencyHistogramBuckets:              []float64{0.1, 0.2, 0.4, 0.8, 1.6, 3.2, 6.4, 12.8, 25.6},