telemetry: clock rule, every terminal path, real cache hits, schema + drop counts

[AdvayMonga]

Review of the per-request telemetry rows against the environment's request-trace contract (BlameGraph lab/TRACE.md).

Fixed

• Clocks. No duration mixed clocks before either, but arrival_ts was a separate time.time() read taken inside the pending lock, after enqueue_ts. It's now derived from one perf_counter stamp (ScheduledRequest.arrival_ts, set by each HTTP handler at receipt, before tokenizing) and back-dated to wall time. ttft_s/total_s run from receipt; queue_wait_s still runs from enqueue.
• TTFT/TPOT. ttft_s is set only when a real token was emitted (an EOS-first answer used to get a TTFT with tokens_out=0). tpot_s = (total_s - ttft_s)/(n - 1), same as the environment. decode_steps now counts forward passes (it used to be tokens_out - 1, which is one short on EOS).
• Terminal states. Added cancelled and aborted.
  • cancelled: a streaming client went away (the SSE generators flag the request), or submit was cancelled. Active rows are evicted at the next step and pending ones are never admitted. Before this, a disconnected stream decoded to the end and was recorded as ok.
  • aborted: stop() used to leave queued and in-flight requests with no row and an unresolved future.
  • A wedged worker (_fail_all) now also rejects pending requests. Before, they waited forever.
• cache_hit_tokens. The batched path hardcoded 0 with a stale comment, but CustomTorchBackend.prefill_batch does look up the prefix cache per row. It now reports last_batch_cache_hit_tokens, and the scheduler resets it before each wave. Rows carry prefill_mode. cache_hit_tokens is NULL when no lookup was reported (never admitted, or a backend that doesn't report per-row hits).
• Schema and drops. Rows carry schema_version (1). The SQLite file gets a meta table (schema_version, run_id, rows_written, rows_dropped, closed), updated after every batch and finalised at close. A row put after close used to vanish into an undrained queue; it's now counted as dropped.

Already right

• trace_id is threaded from X-Trace-Id through both shim routes, streaming or not, and echoed back.
• Timeline events carry trace_id and step.
• preempted is set: preemption is terminal here, so it is 0 or 1.
• The decode-width accumulators were correct.
• 429, 400 and expired rows were correct.
• RowStore drops were already in /scheduler/stats.

Not changed (noted)

• Non-streaming client disconnects can't be detected: Starlette doesn't cancel the handler.
• /generate non-stream returns ttft_ms=0.
• prompt_logprobs scoring requests bypass the scheduler, so they have no row.
• Cancelled rows count as failures in the Prometheus rejection counter.

Tests

pytest -q: 374 passed, 37 skipped. ruff check .: clean. New tests cover:

• arrival back-dating and the TPOT identity
• EOS-first rows
• the decode_steps count
• cache hits per prefill mode
• cancelled rows (active and pending)
• cancelled submit
• aborted on stop
• the meta table and post-close drops
• X-Trace-Id joining the row and the timeline end to end through the shim
• a dropped stream setting the cancel flag

🤖 Generated with Claude Code