From d6c7b24af38220baafa92e57548482735e6c4b17 Mon Sep 17 00:00:00 2001 From: Richa Banker Date: Wed, 7 Jan 2026 15:47:12 -0800 Subject: [PATCH] Log WatchList initial listing phase completion --- .../apiserver/pkg/endpoints/handlers/watch.go | 15 ++++++++++++++- .../apiserver/pkg/endpoints/metrics/metrics.go | 13 ++----------- 2 files changed, 16 insertions(+), 12 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/watch.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/watch.go index 822e5628894..6b717b26a78 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/watch.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/watch.go @@ -32,13 +32,16 @@ import ( "k8s.io/apimachinery/pkg/util/httpstream/wsstream" utilruntime "k8s.io/apimachinery/pkg/util/runtime" "k8s.io/apimachinery/pkg/watch" + "k8s.io/apiserver/pkg/audit" "k8s.io/apiserver/pkg/endpoints/handlers/negotiation" "k8s.io/apiserver/pkg/endpoints/metrics" apirequest "k8s.io/apiserver/pkg/endpoints/request" "k8s.io/apiserver/pkg/features" + "k8s.io/apiserver/pkg/server/httplog" "k8s.io/apiserver/pkg/storage" utilfeature "k8s.io/apiserver/pkg/util/feature" compbasemetrics "k8s.io/component-base/metrics" + "k8s.io/klog/v2" ) // timeoutFactory abstracts watch timeout logic for testing @@ -308,7 +311,17 @@ func (s *WatchServer) HandleHTTP(w http.ResponseWriter, req *http.Request) { flusher.Flush() } if isWatchListLatencyRecordingRequired { - metrics.RecordWatchListLatency(req.Context(), s.Scope.Resource, s.metricsScope) + // Record completion of initial listing phase for WatchList + receivedTimestamp, ok := apirequest.ReceivedTimestampFrom(req.Context()) + if !ok { + utilruntime.HandleError(fmt.Errorf("unable to measure watchlist latency because no received ts found in the ctx, gvr: %s", s.Scope.Resource)) + } else { + initLatency := time.Since(receivedTimestamp) + metrics.RecordWatchListLatency(req.Context(), s.Scope.Resource, s.metricsScope, initLatency) + auditID := audit.GetAuditIDTruncated(req.Context()) + klog.V(3).InfoS("WatchList initial events sent", "path", req.URL.Path, "auditID", auditID, "initLatency", initLatency) + httplog.AddKeyValue(req.Context(), "watchlist_init_latency", initLatency) + } } } } diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go b/staging/src/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go index c76457175a1..9cfdfbaad84 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go @@ -18,7 +18,6 @@ package metrics import ( "context" - "fmt" "net/http" "net/url" "strconv" @@ -32,7 +31,6 @@ import ( "k8s.io/apimachinery/pkg/apis/meta/v1/validation" "k8s.io/apimachinery/pkg/runtime/schema" "k8s.io/apimachinery/pkg/types" - utilruntime "k8s.io/apimachinery/pkg/util/runtime" utilsets "k8s.io/apimachinery/pkg/util/sets" "k8s.io/apiserver/pkg/audit" "k8s.io/apiserver/pkg/authentication/user" @@ -574,15 +572,8 @@ func RecordLongRunning(req *http.Request, requestInfo *request.RequestInfo, comp } // RecordWatchListLatency simply records response latency for watch list requests. -func RecordWatchListLatency(ctx context.Context, gvr schema.GroupVersionResource, metricsScope string) { - requestReceivedTimestamp, ok := request.ReceivedTimestampFrom(ctx) - if !ok { - utilruntime.HandleError(fmt.Errorf("unable to measure watchlist latency because no received ts found in the ctx, gvr: %s", gvr)) - return - } - elapsedSeconds := time.Since(requestReceivedTimestamp).Seconds() - - watchListLatencies.WithContext(ctx).WithLabelValues(gvr.Group, gvr.Version, gvr.Resource, metricsScope).Observe(elapsedSeconds) +func RecordWatchListLatency(ctx context.Context, gvr schema.GroupVersionResource, metricsScope string, elapsed time.Duration) { + watchListLatencies.WithContext(ctx).WithLabelValues(gvr.Group, gvr.Version, gvr.Resource, metricsScope).Observe(elapsed.Seconds()) } // MonitorRequest handles standard transformations for client and the reported verb and then invokes Monitor to record