Client latency telemetry (TTFC / duration / per-output-chunk) is measured consumer-side, not at provider receipt

[ajbozarth]

Context

Split out of #1551 (align spans and metrics with OTel GenAI semantic conventions) to keep that PR scoped to the conventions rename, with the measurement corrections tracked here. Raised in review by @planetf1: the client latency instruments are timestamped on the consumer side of the streaming pipeline, so a slow renderer, paused agent loop, or client-side post-processing inflates what is reported as provider latency.

Root cause

Mellea streams through a producer→queue→consumer pipeline: backends push chunks into an asyncio.Queue from send_to_queue() (mellea/helpers/async_helpers.py) while ModelOutputThunk.astream() (mellea/core/base.py) drains it. All three latency instruments take their timestamps in the consumer — after the chunk is dequeued, and for some after it is processed — so they measure when the application handled the data, not when the provider delivered it.

Two structural problems compound, and they have different fix locations:

• (A) Measurement location — timestamps are taken consumer-side instead of at chunk receipt in the producer. Straightforward to move.
• (B) Bounded-queue backpressure — the queue is asyncio.Queue(maxsize=20); once full, the producer's put() blocks, which in turn paces its own anext(). So even a producer-side timestamp is dragged by a stalled consumer on any stream longer than the queue. Removing this needs decoupling the producer's drain from the bounded queue (buffer receipts independently, or use provider-reported timing).

Fixes required

The three are related — all "measure provider time, not consumer time," all enabled by producer-side receipt timestamps — but land in separate places with different scope.

1. time_to_first_chunk — fully fixable (location only, Issue A)

Surfaces: gen_ai.client.operation.time_to_first_chunk (metric) and gen_ai.response.time_to_first_chunk (span attr), both derived from ModelOutputThunk.generation.ttfb_ms.

ttfb_ms is recorded in _record_ttfb() at queue.get() time, so it includes the gap between request dispatch and the consumer draining the first chunk. The spec definition is explicit:

Time to receive the first chunk, measured from when the client issues the generation request to when the first chunk is received in the response stream.

Consumer-side stamping violates that definition. Fix location: send_to_queue() — stamp a monotonic receipt time the instant the first anext() returns (before enqueue) and derive ttfb_ms as first_receipt − request_dispatch. The queue is empty at the first chunk so put() never blocks — this is immune to Issue B and is completely solvable.

2. operation.duration — location fix + backpressure decoupling (Issues A + B)

Surface: gen_ai.client.operation.duration (metric).

latency_ms is _elapsed_ms() read at the generation_post_call hook — after full consumption, post-processing, parsing, and validation — and because that hook fires whenever the consumer finishes, it also absorbs idle time (e.g. a paused agent loop between astream() calls). Note the spec only defines this as "GenAI operation duration" (client perspective) and does not pin the boundary, so including post-processing is arguably within latitude; including arbitrary idle time is not defensible under any reading.

Fix location:

• (a) send_to_queue() — stamp completion at last-chunk receipt; removes post-processing/parse/validate. Same location as Better @generative documentation in the tutorial #1.
• (b) Decouple the producer drain from the bounded queue to remove the Issue B backpressure contamination on long streams.

Resolution options: (i) keep the gen_ai.* spec name and implement (a) + (b); or (ii) rename to an honest mellea metric instead of re-measuring — viable for duration because the current value is a coherent quantity (end-to-end wall time) that only carries the wrong name, so an honest name makes it correct-by-definition and (b) is not needed.

3. time_per_output_chunk / time_since_last_chunk_ms — location + per-item propagation + backpressure (Issues A + B, plus queue-payload rework)

Surfaces: gen_ai.client.operation.time_per_output_chunk (metric) and time_since_last_chunk_ms on chunk_processed span events (opt-in via MELLEA_GENERATION_CHUNK_EVENTS).

time_since_last_chunk_ms is computed in the consumer after await self._gen.process(self, chunk), from datetime.now() deltas at processing time; the consumer also drains in batches, so the deltas reflect processing/batching cadence, not provider inter-arrival.

Fix location:

• (a) Producer captures per-chunk receipt timestamps (send_to_queue()).
• (b) Propagate them per-item through the queue so the consumer can emit them alongside chunk_index/chunk_text_length. The queue currently carries bare items and discriminates end-of-stream/error by identity (is None / isinstance Exception), so this needs a wrapper type or a parallel timestamp channel — the most invasive piece.
• (c) Subject to the same Issue B backpressure ceiling as Easier RCA for failed requirements #2.

Most involved of the three.

Note: these surfaces are new and opt-in (MELLEA_GENERATION_CHUNK_EVENTS, no existing consumers), so an alternative to shipping approximate values is to gate them off until (a) + (b) + (c) land. Renaming does not help here (unlike duration): the current value is a batching-distorted consumer-processing cadence, not a coherent quantity, so an honest name yields a truthful-but-low-value metric rather than a correct one.

Acceptance

• TTFC, duration, and per-chunk timing are derived from provider-side receipt timestamps rather than consumer-side stamps.
• Regression test: stall the consumer after chunks are produced and assert the client latency values do not increase.
• The instruments distinguish provider latency from client-side/orchestration time, so they're usable for performance diagnosis (the original review concern).

[ajbozarth]

I intend to pick this up next sprint iteration when I return from my trip (~8/26), but if someone else wants to take a stab while I'm gone feel free. It's not technically a telemetry fix, but fixing how the values that telemetry emits are recorded.

[planetf1]

A few precise additions after re-verifying the measurement claims against current main (058e3ddc, which has the #1543 streaming refactor on top of #1551). The root cause and fix locations in the issue are accurate; these are gaps and one clarification, not corrections to the analysis.

1. The gen_ai.* names are unreleased, so renaming is still cheap — but the measurement itself shipped. No released build exposes the gen_ai.client.* names: v0.7.0 (2026-07-13, current latest) predates feat(telemetry): align spans and metrics with OTel GenAI semantic conventions #1551, so picking a different name now adds no migration step beyond the one v0.7.0 consumers already face. What did ship is worth stating: duration and TTFB are renames, not new instruments — v0.7.0 has mellea.llm.request.duration and mellea.llm.ttfb (metrics.py:555,562) and already stamps TTFB at dequeue (base.py:808,824), so the defect is live in a release with consumers wired to the wrong value. Only time_per_output_chunk is genuinely new, which is what makes Fix 3's "gate them off until (a)+(b)+(c) land" free. And an honestly-renamed duration stays pacing-dependent (it folds in variable consumer post-processing and idle), so the name's documented boundary still has to be pinned.

2. Scope the two error/timeout latency sites too, not just the three happy-path instruments. generation_error fires with latency_ms = self._elapsed_ms() in both the astream() exception path (base.py:1183) and the cancel path (base.py:975-987, reached via aclose() → cancel_generation(), base.py:1320-1321). Both are consumer-side wall-clock and reach record_request_duration through ErrorMetricsPlugin (metrics_plugins.py:254). One mitigating fact worth recording: those rows are tagged error.type (exception class, metrics_plugins.py:260 → metrics.py:727-728), so they're separable from success rows and can't be silently folded into a provider-latency dashboard — they're just still mismeasured. Conversely, make explicit that the batch/non-streaming path (metrics_plugins.py:287 / backend.py:256) is out of scope: it already uses time.perf_counter() (monotonic) and has no defect. It's the model streaming should mirror.

3. One monotonic clock for both ends. For a producer-side receipt stamp (fix (a)) to be subtractable from dispatch start, both ends must share a clock. They're both in-process (start is stamped in the backends; receipts are taken in send_to_queue), so a single time.perf_counter() is available at each. The batch path already uses it (backend.py:232,256). All eight current start sites use wall-clock datetime.datetime.now() (openai.py:841,1088; huggingface.py:784,1119,1312; litellm.py:464; ollama.py:506; watsonx.py:488); moving only the producer onto a monotonic clock would introduce a mixed-clock / NTP-step hazard. Move start and the receipts onto perf_counter together.

4. Concrete acceptance test. The proposed regression test (stall the consumer, assert the values don't grow) is right, but it should (a) produce well over 20 chunks — the queue is maxsize=20 (base.py:778) — so it actually exercises the backpressure problem (B), not just measurement location (A); and (b) run with MELLEA_GENERATION_CHUNK_EVENTS on and off (default off, base.py:1189-1191) so per-chunk is covered alongside TTFB and duration.

5. Docstring: leave the field docstring, fix AGENTS.md. The ttfb_ms field docstring (base.py:645, "Set when the first chunk is received from the backend") already states the intended, post-fix semantics — it is false today but becomes true once the producer stamps receipt, so it shouldn't change. What is stale is AGENTS.md:92 ("set automatically in astream()"), which should be updated to say it's derived from the provider's first-chunk receipt.

One #1543 context worth carrying into the per-chunk fix: the new single-task driver (stdlib/streaming.py:425 _drive) runs _validate_chunk between yielded chunks (streaming.py:480,495), and with requirements present that issues a real validation_backend call per chunk (streaming.py:396-403, guarded by if not requirements at :394). So post-#1543, inter-chunk consumer time includes per-chunk validation model calls, which widens the gap between provider arrival and consumer processing. That raises the priority of Fix 3, not lowers it.