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:`)

accesslog/schema/access_log_record_test.go

@@ -60,6 +60,7 @@ var _ = Describe("AccessLogRecord", func() {
 			AppRequestFinishedAt: time.Date(2000, time.January, 1, 0, 0, 55, 0, time.UTC),
 			RequestBytesReceived: 30,
 			RouterError:          "some-router-error",
+			GorouterTime:         10,
 		}
 	})
 
@@ -227,6 +228,7 @@ var _ = Describe("AccessLogRecord", func() {
 				record.AppRequestFinishedAt = time.Time{}
 				record.RequestBytesReceived = 0
 				record.RouterError = ""
+				record.GorouterTime = -1
 			})
 
 			It("makes a record", func() {
@@ -301,6 +303,7 @@ var _ = Describe("AccessLogRecord", func() {
 					AppRequestFinishedAt: time.Date(2000, time.January, 1, 0, 0, 55, 0, time.UTC),
 					RequestBytesReceived: 30,
 					ExtraHeadersToLog:    []string{},
+					GorouterTime:         10,
 				}
 
 				r := BufferReader(bytes.NewBufferString(record.LogMessage()))

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

@@ -5,13 +5,15 @@ import (
 	"io"
 	"net/http"
 	"net/http/httptest"
+	"time"
 
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
 	"github.com/urfave/negroni/v3"
 
 	"code.cloudfoundry.org/gorouter/accesslog/fakes"
 	"code.cloudfoundry.org/gorouter/handlers"
+	metrics_fakes "code.cloudfoundry.org/gorouter/metrics/fakes"
 	"code.cloudfoundry.org/gorouter/proxy/utils"
 	"code.cloudfoundry.org/gorouter/route"
 	"code.cloudfoundry.org/gorouter/test_util"
@@ -26,6 +28,7 @@ var _ = Describe("AccessLog", func() {
 
 		logger            *test_util.TestLogger
 		accessLogger      *fakes.FakeAccessLogger
+		fakeReporter      *metrics_fakes.FakeMetricReporter
 		extraHeadersToLog []string
 
 		nextCalled bool
@@ -52,6 +55,10 @@ var _ = Describe("AccessLog", func() {
 		reqInfo, err := handlers.ContextRequestInfo(req)
 		if err == nil {
 			reqInfo.RouteEndpoint = testEndpoint
+			timeNow := time.Now()
+			reqInfo.ReceivedAt = timeNow.Add(-1 * time.Millisecond)
+			reqInfo.AppRequestStartedAt = timeNow.Add(1 * time.Millisecond)
+			reqInfo.AppRequestFinishedAt = timeNow.Add(2 * time.Millisecond)
 		}
 
 		if next != nil {
@@ -75,13 +82,15 @@ var _ = Describe("AccessLog", func() {
 		extraHeadersToLog = []string{}
 
 		accessLogger = &fakes.FakeAccessLogger{}
+		fakeReporter = new(metrics_fakes.FakeMetricReporter)
 
 		logger = test_util.NewTestLogger("test")
 
 		handler = negroni.New()
 		handler.Use(handlers.NewRequestInfo())
 		handler.Use(handlers.NewProxyWriter(logger.Logger))
 		handler.Use(handlers.NewAccessLog(accessLogger, extraHeadersToLog, nil, logger.Logger))
+		handler.Use(handlers.NewReporter(fakeReporter, logger.Logger))
 		handler.Use(nextHandler)
 
 		reqChan = make(chan *http.Request, 1)
@@ -107,8 +116,8 @@ 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.GorouterTime).ToNot(BeZero())
 		Expect(alr.BodyBytesSent).To(Equal(37))
 		Expect(alr.StatusCode).To(Equal(http.StatusTeapot))
 		Expect(alr.RouteEndpoint).To(Equal(testEndpoint))

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/metricsreporter.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