Skip to content

Per-phase timing capture for proxy requests#1

Open
stuartc wants to merge 11 commits intomainfrom
timing-capture
Open

Per-phase timing capture for proxy requests#1
stuartc wants to merge 11 commits intomainfrom
timing-capture

Conversation

@stuartc
Copy link
Copy Markdown
Member

@stuartc stuartc commented Apr 9, 2026

Summary

  • Breaking: finished_result.duration_us is replaced by a timing map containing total_us (same value) plus per-phase breakdown fields
  • New collect_timing: true option for proxy/2 enables timing capture from Finch telemetry events
  • New Philter.Timing module with a single globally-attached telemetry handler (lazy, near-zero cost when unused)

Timing structure

When collect_timing: true:

result.timing
# => %{total_us: 12500, queue_us: 200, connect_us: 3100, send_us: 150, recv_us: 8900,
#       idle_time_us: 50, reused_connection?: false}

When collect_timing is not set (default):

result.timing
# => %{total_us: 12500, queue_us: nil, connect_us: nil, send_us: nil, recv_us: nil,
#       idle_time_us: nil, reused_connection?: nil}

Design

  • Transport-agnostic naming — field names don't reference Finch; semantics survive a client swap
  • Single global handler — attached once via persistent_term guard, avoids O(N²) attach/detach per request
  • Process dictionary opt-in — handler checks Process.get(:philter_timing_ref) on every Finch event; returns nil immediately when no proxy is capturing
  • Cleanup on crashcatch clause in stream_with_timing/5 cleans up process dictionary entries before re-raising

Migration

- result.duration_us
+ result.timing.total_us

All timing keys are always present. Phase fields are nil unless collect_timing: true is passed.

Test plan

  • Philter.Timing unit tests (11 tests): attachment idempotency, round-trip capture, duration conversion, cleanup, mutual exclusivity, edge cases
  • PhilterTest integration tests updated for new timing structure + new timing-specific tests (139 total, 0 failures)
  • mix compile --warnings-as-errors clean
  • mix format --check-formatted clean

stuartc added 11 commits April 9, 2026 08:32
Global telemetry handler attached lazily on first use via
persistent_term. Per-request opt-in through process dictionary
flag — when no proxy has opted in, the handler cost is a single
Process.get/1 returning nil.

Captures queue, connect, send, recv durations and idle_time from
Finch telemetry events. Converts native time units to microseconds.
Covers lazy attachment idempotency, no-op when not opted in,
capture+collect round-trip, native-to-microsecond conversion,
reused_connection flag, process dictionary cleanup after collect,
mutual exclusivity of connect vs reused_connection, idle_time_us
extraction, and graceful handling when no events fire.
Breaking change: finished_result.duration_us is replaced by a timing
map containing total_us (same value) plus per-phase breakdown fields
(queue_us, connect_us, send_us, recv_us, idle_time_us,
reused_connection?).

Phase fields are populated when collect_timing: true is passed to
proxy/2. When timing capture is off, phase fields are nil.

Adds stream_with_timing/5 wrapper around Finch.stream_while that
optionally captures telemetry-based phase timing. The catch clause
cleans up process dictionary entries on raises/exits.
Adapts existing assertions from result.duration_us to
result.timing.total_us. Adds new describe block for timing-specific
tests: default nil phase fields when collect_timing is not set,
populated phase fields with collect_timing: true, and timing
presence on error paths.
Breaking change to finished_result warrants minor version bump.
Breaking change: body_observation no longer has duration_us or
time_to_first_byte_us. Observations are now purely content metadata
(hash, size, preview, body). All timing lives in finished_result.timing.

Removes started_at and first_byte_at from Observation struct.
The response_started callback's time_to_first_byte_us is unchanged
(it measures request-level TTFB, not body-level).
- Document when finished_result.status is nil (error before response)
- Remove misplaced timing comment from README observation example
- Hide internal Timing.t() type from docs (consumers use Handler.timing())
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