From 1c3fa4aa85581ffa5cc4ded708ac1ec9552c55bb Mon Sep 17 00:00:00 2001 From: Philip Conrad Date: Mon, 9 Jun 2025 12:33:35 -0400 Subject: [PATCH] v1/server: Fix deferred metrics timers. (#7671) The /v1/data endpoint's PUT, PATCH, and DELETE methods all reported incorrect timer information (zeroed out timers). This was caused by the Timer.Stop() calls being deferred in those method handlers. The problem is that the timers do not record a time value until you stop them. So, when the metrics are reported, all of those timers are still storing their initial zero values. The fix was manually calling Timer.Stop() right before metrics collection on each endpoint, similar to how we handle many other endpoints in the server. Signed-off-by: Philip Conrad --- v1/server/server.go | 9 ++++++--- v1/server/server_test.go | 39 +++++++++++++++++++++++++++++++++------ 2 files changed, 39 insertions(+), 9 deletions(-) diff --git a/v1/server/server.go b/v1/server/server.go index 7620816c0c..69d2bd4e22 100644 --- a/v1/server/server.go +++ b/v1/server/server.go @@ -1617,7 +1617,6 @@ func (s *Server) v1DataGet(w http.ResponseWriter, r *http.Request) { func (s *Server) v1DataPatch(w http.ResponseWriter, r *http.Request) { m := metrics.New() m.Timer(metrics.ServerHandler).Start() - defer m.Timer(metrics.ServerHandler).Stop() ctx := r.Context() vars := mux.Vars(r) @@ -1667,6 +1666,8 @@ func (s *Server) v1DataPatch(w http.ResponseWriter, r *http.Request) { return } + m.Timer(metrics.ServerHandler).Stop() + if includeMetrics(r) { result := types.DataResponseV1{ Metrics: m.All(), @@ -1841,7 +1842,6 @@ func (s *Server) v1DataPost(w http.ResponseWriter, r *http.Request) { func (s *Server) v1DataPut(w http.ResponseWriter, r *http.Request) { m := metrics.New() m.Timer(metrics.ServerHandler).Start() - defer m.Timer(metrics.ServerHandler).Stop() ctx := r.Context() vars := mux.Vars(r) @@ -1907,6 +1907,8 @@ func (s *Server) v1DataPut(w http.ResponseWriter, r *http.Request) { return } + m.Timer(metrics.ServerHandler).Stop() + if includeMetrics(r) { result := types.DataResponseV1{ Metrics: m.All(), @@ -1921,7 +1923,6 @@ func (s *Server) v1DataPut(w http.ResponseWriter, r *http.Request) { func (s *Server) v1DataDelete(w http.ResponseWriter, r *http.Request) { m := metrics.New() m.Timer(metrics.ServerHandler).Start() - defer m.Timer(metrics.ServerHandler).Stop() ctx := r.Context() vars := mux.Vars(r) @@ -1961,6 +1962,8 @@ func (s *Server) v1DataDelete(w http.ResponseWriter, r *http.Request) { return } + m.Timer(metrics.ServerHandler).Stop() + if includeMetrics(r) { result := types.DataResponseV1{ Metrics: m.All(), diff --git a/v1/server/server_test.go b/v1/server/server_test.go index 069399765f..01ffb352b6 100644 --- a/v1/server/server_test.go +++ b/v1/server/server_test.go @@ -3363,7 +3363,7 @@ func TestDataProvenanceMultiBundle(t *testing.T) { func TestDataMetricsEval(t *testing.T) { t.Parallel() - // These tests all use the POST /v1/data API with ?metrics appended. + // These tests all use the /v1/data API with ?metrics appended. // We're setting up the disk store because that injects a few extra metrics, // which storage/inmem does not. @@ -3379,7 +3379,7 @@ func TestDataMetricsEval(t *testing.T) { f := newFixtureWithStore(t, disk) // Make a request to evaluate `data` - testDataMetrics(t, f, "/data?metrics", []string{ + testDataMetrics(t, f, http.MethodPost, "/data?metrics", "", []string{ "counter_server_query_cache_hit", "counter_disk_read_keys", "counter_disk_read_bytes", @@ -3393,23 +3393,50 @@ func TestDataMetricsEval(t *testing.T) { // Repeat previous request, expect to have hit the query cache // so fewer timers should have been reported. - testDataMetrics(t, f, "/data?metrics", []string{ + testDataMetrics(t, f, http.MethodPost, "/data?metrics", "", []string{ "counter_server_query_cache_hit", "counter_disk_read_keys", "counter_disk_read_bytes", + "timer_disk_read_ns", + "timer_rego_external_resolve_ns", "timer_rego_input_parse_ns", "timer_rego_query_eval_ns", "timer_server_handler_ns", + }) + + // Exercise the PUT, PATCH, and DELETE endpoints. + testDataMetrics(t, f, http.MethodPut, "/data/example?metrics", "{}", []string{ + "counter_disk_read_keys", + "counter_disk_written_keys", + "timer_disk_commit_ns", "timer_disk_read_ns", - "timer_rego_external_resolve_ns", + "timer_disk_write_ns", + "timer_rego_input_parse_ns", + "timer_server_handler_ns", + }) + + testDataMetrics(t, f, http.MethodPatch, "/data/example?metrics", "[]", []string{ + "timer_disk_commit_ns", + "timer_rego_input_parse_ns", + "timer_server_handler_ns", + }) + + testDataMetrics(t, f, http.MethodDelete, "/data/example?metrics", "{}", []string{ + "counter_disk_deleted_keys", + "counter_disk_read_keys", + "counter_disk_read_bytes", + "timer_disk_commit_ns", + "timer_disk_read_ns", + "timer_disk_write_ns", + "timer_server_handler_ns", }) }) } -func testDataMetrics(t *testing.T, f *fixture, url string, expected []string) { +func testDataMetrics(t *testing.T, f *fixture, method string, url string, payload string, expected []string) { t.Helper() f.reset() - req := newReqV1(http.MethodPost, url, "") + req := newReqV1(method, url, payload) f.server.Handler.ServeHTTP(f.recorder, req) var result types.DataResponseV1