feat: Add request_duration metric for each endpoint (#634)

Author: keelerm84

internal/metrics/constants.go

@@ -21,7 +21,8 @@ const (
 
 	privatePollingRequestsMeasureName = "internal_polling_requests"
 
-	requestMeasureName = "requests"
+	requestMeasureName         = "requests"
+	requestDurationMeasureName = "request_duration"
 
 	defaultFlushInterval = time.Minute
 

internal/metrics/measures.go

@@ -2,6 +2,7 @@ package metrics
 
 import (
 	"context"
+	"time"
 
 	"github.com/launchdarkly/ld-relay/v8/internal/logging"
 
@@ -19,9 +20,10 @@ var (
 	//
 	// To avoid having to put nolint:gochecknoglobals on everything here, that linter is excluded
 	// specifically for this file in .golangci-lint.yml.
-	connMeasure    = stats.Int64(connMeasureName, "current number of connections", stats.UnitDimensionless)
-	newConnMeasure = stats.Int64(newConnMeasureName, "total number of connections", stats.UnitDimensionless)
-	requestMeasure = stats.Int64(requestMeasureName, "Number of hits to a route", stats.UnitDimensionless)
+	connMeasure            = stats.Int64(connMeasureName, "current number of connections", stats.UnitDimensionless)
+	newConnMeasure         = stats.Int64(newConnMeasureName, "total number of connections", stats.UnitDimensionless)
+	requestMeasure         = stats.Int64(requestMeasureName, "Number of hits to a route", stats.UnitDimensionless)
+	requestDurationMeasure = stats.Float64(requestDurationMeasureName, "request duration in microseconds", stats.UnitDimensionless)
 
 	// For internal event exporter
 	privateConnMeasure            = stats.Int64(privateConnMeasureName, "current number of connections", stats.UnitDimensionless)
@@ -120,3 +122,22 @@ func WithRouteCount(ctx context.Context, userAgent, sdkWrapper, route, method st
 
 	WithCount(ctx, userAgent, sdkWrapper, f, measure)
 }
+
+// RecordRequestDuration records a request duration measurement. The context must already contain
+// the environment and relay ID tags (from the EnvironmentManager's OpenCensus context). The route
+// and method tags are added here.
+func RecordRequestDuration(ctx context.Context, userAgent, sdkWrapper, route, method string, duration time.Duration, measure Measure) {
+	tagCtx, err := tag.New(ctx,
+		tag.Insert(userAgentTagKey, sanitizeTagValue(userAgent)),
+		tag.Insert(sdkWrapperTagKey, sanitizeTagValue(sdkWrapper)),
+		tag.Insert(routeTagKey, sanitizeTagValue(route)),
+		tag.Insert(methodTagKey, sanitizeTagValue(method)),
+	)
+	if err != nil {
+		return
+	}
+	for _, mut := range measure.tags {
+		tagCtx, _ = tag.New(tagCtx, mut)
+	}
+	stats.Record(tagCtx, requestDurationMeasure.M(float64(duration.Microseconds())))
+}

internal/metrics/views.go

@@ -22,6 +22,11 @@ var (
 		Aggregation: view.Count(),
 		TagKeys:     append(publicTags, routeTagKey, methodTagKey),
 	}
+	requestDurationView *view.View = &view.View{ //nolint:gochecknoglobals
+		Measure:     requestDurationMeasure,
+		Aggregation: view.Distribution(10, 25, 50, 100, 250, 500, 1000, 2500, 5000, 10000, 25000, 50000, 100000, 250000, 500000, 1000000),
+		TagKeys:     append(publicTags, routeTagKey, methodTagKey),
+	}
 	privateConnView *view.View = &view.View{ //nolint:gochecknoglobals
 		Measure:     privateConnMeasure,
 		Aggregation: view.Sum(),
@@ -43,7 +48,7 @@ var (
 )
 
 func getPublicViews() []*view.View {
-	return []*view.View{publicConnView, publicNewConnView, requestView}
+	return []*view.View{publicConnView, publicNewConnView, requestView, requestDurationView}
 }
 
 func getPrivateViews() []*view.View {

internal/middleware/metrics_middleware.go

@@ -2,6 +2,8 @@ package middleware
 
 import (
 	"net/http"
+	"strings"
+	"time"
 
 	"github.com/launchdarkly/ld-relay/v8/internal/metrics"
 
@@ -53,7 +55,8 @@ func PollingRequestCount(handler http.Handler) http.Handler {
 	return withCount(handler, metrics.PollingRequests)
 }
 
-// RequestCount is a middleware function that increments the specified metric for each request.
+// RequestCount is a middleware function that increments the specified metric for each request
+// and records the request duration (excluding streaming responses).
 func RequestCount(measure metrics.Measure) mux.MiddlewareFunc {
 	return func(next http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
@@ -62,9 +65,14 @@ func RequestCount(measure metrics.Measure) mux.MiddlewareFunc {
 			sdkWrapper := getSDKWrapper(req)
 			// Ignoring internal routing error that would have been ignored anyway
 			route, _ := mux.CurrentRoute(req).GetPathTemplate()
+			start := time.Now()
 			metrics.WithRouteCount(ctx.Env.GetMetricsContext(), userAgent, sdkWrapper, route, req.Method, func() {
 				next.ServeHTTP(w, req)
 			}, measure)
+			// Don't record duration for streaming responses — their lifetime is unbounded
+			if !strings.HasPrefix(strings.ToLower(w.Header().Get("Content-Type")), "text/event-stream") {
+				metrics.RecordRequestDuration(ctx.Env.GetMetricsContext(), userAgent, sdkWrapper, route, req.Method, time.Since(start), measure)
+			}
 		})
 	}
 }

internal/middleware/metrics_middleware_test.go

@@ -171,3 +171,72 @@ func testCountRequests(t *testing.T, measure metrics.Measure, category string) {
 		})
 	})
 }
+
+func TestRequestDuration(t *testing.T) {
+	t.Run("records duration for non-streaming request", func(t *testing.T) {
+		router := mux.NewRouter()
+		router.Use(RequestCount(metrics.ServerRequests))
+		router.Handle("/duration-test", nullHandler()).Methods("GET")
+
+		metricsMiddlewareTest(t, func(p metricsMiddlewareTestParams) {
+			expectedTags := map[string]string{
+				"env":              p.envName,
+				"method":           "GET",
+				"route":            "_duration-test",
+				"platformCategory": "server",
+				"userAgent":        metricsTestUserAgent,
+				"sdkWrapper":       "not-provided",
+			}
+
+			req, _ := http.NewRequest("GET", "/duration-test", nil)
+			req.Header.Set("User-Agent", metricsTestUserAgent)
+			req = req.WithContext(WithEnvContextInfo(req.Context(), EnvContextInfo{Env: p.env}))
+			router.ServeHTTP(httptest.NewRecorder(), req)
+
+			p.exporter.AwaitData(t, time.Second, p.mockLog.Loggers, func(d st.TestMetricsData) bool {
+				return d.HasRowMatching("request_duration", expectedTags, func(row st.TestMetricsRow) bool {
+					return row.DistributionCount >= 1
+				})
+			})
+		})
+	})
+
+	t.Run("does not record duration for streaming request", func(t *testing.T) {
+		router := mux.NewRouter()
+		router.Use(RequestCount(metrics.ServerRequests))
+		// Handler that sets Content-Type: text/event-stream (like the streaming middleware does)
+		router.Handle("/stream-route", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			w.Header().Set("Content-Type", "text/event-stream")
+		})).Methods("GET")
+
+		metricsMiddlewareTest(t, func(p metricsMiddlewareTestParams) {
+			streamTags := map[string]string{
+				"env":              p.envName,
+				"method":           "GET",
+				"route":            "_stream-route",
+				"platformCategory": "server",
+				"userAgent":        metricsTestUserAgent,
+				"sdkWrapper":       "not-provided",
+			}
+
+			req, _ := http.NewRequest("GET", "/stream-route", nil)
+			req.Header.Set("User-Agent", metricsTestUserAgent)
+			req = req.WithContext(WithEnvContextInfo(req.Context(), EnvContextInfo{Env: p.env}))
+			router.ServeHTTP(httptest.NewRecorder(), req)
+
+			// The request count should still be recorded
+			p.exporter.AwaitData(t, time.Second, p.mockLog.Loggers, func(d st.TestMetricsData) bool {
+				return d.HasRow("requests", st.TestMetricsRow{
+					Tags:  streamTags,
+					Count: 1,
+				})
+			})
+
+			// But there should be no duration data for this specific route
+			lastData := p.exporter.GetLastData()
+			require.False(t, lastData.HasRowMatching("request_duration", streamTags, func(st.TestMetricsRow) bool {
+				return true
+			}), "streaming request should not have duration recorded")
+		})
+	})
+}

internal/sharedtest/metrics.go

@@ -36,11 +36,23 @@ func (d TestMetricsData) HasRow(viewName string, expectedRow TestMetricsRow) boo
 	return false
 }
 
+// HasRowMatching returns true if any row for the specified view name has matching tags
+// and satisfies the predicate function.
+func (d TestMetricsData) HasRowMatching(viewName string, tags map[string]string, predicate func(TestMetricsRow) bool) bool {
+	for _, r := range d[viewName] {
+		if reflect.DeepEqual(r.Tags, tags) && predicate(r) {
+			return true
+		}
+	}
+	return false
+}
+
 // TestMetricsRow is a simplified version of an OpenCensus view row.
 type TestMetricsRow struct {
-	Tags  map[string]string
-	Count int64
-	Sum   float64
+	Tags              map[string]string
+	Count             int64
+	Sum               float64
+	DistributionCount int64
 }
 
 // NewTestMetricsExporter creates a TestMetricsExporter.
@@ -88,6 +100,9 @@ func (e *TestMetricsExporter) ExportView(viewData *view.Data) {
 		if countData, ok := vr.Data.(*view.CountData); ok {
 			tr.Count = countData.Value
 		}
+		if distData, ok := vr.Data.(*view.DistributionData); ok {
+			tr.DistributionCount = distData.Count
+		}
 		rows = append(rows, tr)
 	}
 
@@ -101,6 +116,17 @@ func (e *TestMetricsExporter) ExportView(viewData *view.Data) {
 	}
 }
 
+// GetLastData returns a snapshot of the most recently received metrics data.
+func (e *TestMetricsExporter) GetLastData() TestMetricsData {
+	e.lock.Lock()
+	defer e.lock.Unlock()
+	dataCopy := make(TestMetricsData)
+	for k, v := range e.lastData {
+		dataCopy[k] = v
+	}
+	return dataCopy
+}
+
 // AwaitData waits until matching view data is received.
 func (e *TestMetricsExporter) AwaitData(t *testing.T, timeout time.Duration, loggers ldlog.Loggers, fn func(TestMetricsData) bool) {
 	deadline := time.After(timeout)

internal/streams/stream_provider_ping_jitter_test.go

@@ -11,9 +11,9 @@ import (
 
 	"github.com/launchdarkly/eventsource"
 	"github.com/launchdarkly/go-sdk-common/v3/ldlog"
-	helpers "github.com/launchdarkly/go-test-helpers/v3"
 	"github.com/launchdarkly/go-server-sdk-evaluation/v3/ldmodel"
 	"github.com/launchdarkly/go-server-sdk/v7/subsystems/ldstoreimpl"
+	helpers "github.com/launchdarkly/go-test-helpers/v3"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"