Skip to content

feat(usage): record upstream connection and first-byte timings in usage records - #6087

Open
chokhung588-cell wants to merge 1 commit into
router-for-me:devfrom
chokhung588-cell:feat/usage-upstream-timings
Open

chokhung588-cell wants to merge 1 commit into
router-for-me:devfrom
chokhung588-cell:feat/usage-upstream-timings

Conversation

@chokhung588-cell

@chokhung588-cell chokhung588-cell commented Sep 23, 2026 •

Copy link
Copy Markdown

Summary

Expose upstream HTTP connection setup and first-byte response timings on usage.Record, and propagate them through the usage translation adapter and the Redis usage queue.

This provides proxy operators and downstream metrics/analytics consumers with visibility into the latency split between:

  1. Client ↔ Proxy network transfer
  2. Proxy ↔ Upstream connection establishment (DNS, TCP, TLS)
  3. Upstream Time To First Byte (TTFB, response headers arrival)
  4. Upstream model prefill / Time To First Token (TTFT, response body arrival)

Why

When debugging slow streaming requests, operators frequently observe a large gap between client-perceived TTFT and proxy TTFT.

Currently, usage.Record only records TTFT and GenerationDuration. However, firstPacketDuration is already measured internally in internal/runtime/executor/helps/usage_helpers.go during MarkFirstResponseByte. Furthermore, upstream HTTP transport metrics (DNS, TCP handshake, TLS handshake, and connection reuse via httptrace) were measured during the attempt but discarded before reaching the published usage event.

By capturing UpstreamTTFB, ConnSetupDuration, ConnReused, and FirstPacketDuration:

  • Zero breaking changes: purely additive fields on usage.Record and pluginapi.UsageRecord.
  • Observability and analytics tools can precisely explain whether latency spikes are caused by upstream TLS handshakes, model prefill queuing, or client network congestion.

Changes

  1. internal/runtime/executor/helps/usage_helpers.go:
    • Capture UpstreamTTFB, ConnSetup, and ConnReused via httptrace.ClientTrace in TrackHTTPClient.
    • Implement ObserveUpstreamAttempt with first-wins semantics for multi-attempt / retry scenarios.
    • Populate FirstPacket on MarkFirstResponseByte.
    • Export timings to usage.Record.
  2. sdk/cliproxy/usage/manager.go:
    • Add UpstreamTTFB, ConnSetup, FirstPacket (time.Duration), and ConnReused (bool) to Record.
  3. sdk/pluginapi/types.go:
    • Add corresponding fields to UsageRecord for plugin ABI consumption.
  4. internal/pluginhost/adapters_usage_translation.go:
    • Forward timing fields from usage.Record to pluginapi.UsageRecord.
  5. internal/redisqueue/plugin.go:
    • Serialize upstream timing fields to the Redis queue JSON payload (upstream_ttfb_ns, conn_setup_ns, first_packet_ns, conn_reused).
  6. Tests:
    • Added unit tests in internal/runtime/executor/helps/upstream_timing_test.go:
      • TestRoundTripRecordsUpstreamTiming: verifies accurate recording of TTFB, first packet, and connection setup.
      • TestRoundTripRecordsConnReuse: asserts ConnReused == true and ConnSetup == 0 for pooled keep-alive connections.
      • TestObserveUpstreamAttemptFirstWins: verifies retry first-wins semantics.
      • TestMarkFirstResponseByteRecordsFirstPacket: asserts semantic alignment between FirstPacket and TTFT.

Validation

  • gofmt -w . — clean.
  • go build -o test-output ./cmd/server && rm test-output — verified compile passed.
  • go test -v ./internal/runtime/executor/helps -run "Upstream|MarkFirstResponseByte" -count=1 — 4/4 passed.
  • go test -v ./internal/runtime/executor/helps ./sdk/cliproxy/usage ./sdk/pluginapi ./internal/pluginhost ./internal/redisqueue -count=1 — all passed.
  • Full regression suite go test ./... passed.
  • Verified on a live Linux/amd64 production proxy under real streaming requests.

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