Skip to content

feat(cache-proxy): per-request phase timing, in-flight gauge, pprof - #1045

Merged
EDsCODE merged 1 commit into
eric/cache-proxy-seek-block-prefixfrom
eric/cache-proxy-phase-timing
Aug 9, 2026
Merged

feat(cache-proxy): per-request phase timing, in-flight gauge, pprof#1045
EDsCODE merged 1 commit into
eric/cache-proxy-seek-block-prefixfrom
eric/cache-proxy-phase-timing

Conversation

@EDsCODE

@EDsCODE EDsCODE commented Aug 9, 2026

Copy link
Copy Markdown
Contributor

Problem

Production investigation of slow cold scans found requests spending 100-400ms each inside the cache proxy, served strictly one at a time, with every externally observable component healthy — no errors, no retries, idle CPU, fast peers. The proxy exposes no per-request timing, no queue-depth signal, and no pprof, so the remaining decomposition (origin fetch vs disk vs response write vs queueing) is unmeasurable. Separately, a continuous stream of co-tenant HEAD requests was found traversing the uncached forward path to origin with no metric counting it.

Change

Instrumentation only — no request-path behavior changes:

  • Served. log line gains dur_ms, peer_ms, s3_ms, write_ms (existing fields unchanged, in order). Forward-proxy served. gains dur_ms.
  • New cache_proxy_request_duration_seconds histogram, labels {path=block|forward, source}, 1ms–8s exponential buckets.
  • New cache_proxy_inflight_requests gauge around HandleProxy — the queue-depth signal. Note: CONNECT tunnels count for their lifetime.
  • New cache_proxy_forward_requests_total{method} counter — quantifies the forward-path HEAD stream.
  • pprof handlers registered explicitly on the health mux (side-effect import only covers DefaultServeMux).
  • docs/metrics.md documents the new family, distinguishing it from the worker-side duckgres_worker_cache_proxy_* view.

Accounting nuance: origin-fetch time under singleflight is attributed to the winning request; followers' waits appear in dur_ms but not s3_ms.

Testing

  • go test ./cmd/cache-proxy -count=1 green; -race green except the pre-existing TestHandleConnectLogsOpenAndClose race (fails identically on the base branch).
  • New test asserts the in-flight gauge returns to its pre-request value after a served request and the duration histogram records exactly one sample, using the repo's existing dto.Metric helper convention.

Notes

Stacked on #1042 (seek fix) — both touch the serve loop. Merge that first; this PR's base is set accordingly.

🤖 Generated with Claude Code

@EDsCODE
EDsCODE marked this pull request as ready for review August 9, 2026 19:03
Production requests spend 100-400ms each inside the proxy with no
per-request visibility. Adds dur_ms/peer_ms/s3_ms/write_ms to the
Served. log line, dur_ms to Forward-proxy served., a request-duration
histogram by path and source, an in-flight gauge, a forward-path
method counter (quantifies the co-tenant HEAD stream), and pprof on
the health mux. Instrumentation only; no request-path behavior change.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@EDsCODE
EDsCODE force-pushed the eric/cache-proxy-phase-timing branch from e128e2d to 40d1c43 Compare August 9, 2026 19:21
@EDsCODE
EDsCODE merged commit 6cb5d11 into main Aug 9, 2026
31 checks passed
@EDsCODE
EDsCODE deleted the eric/cache-proxy-phase-timing branch August 9, 2026 19:44
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant