fix(api): measure timings from enqueue, decode rate from execution

[nosyndicate]

The four timings reported per request were internally inconsistent. total_ms was measured from the start of the first prefill (queue wait excluded), but execution_ms was derived as total_ms - queue_wait_ms — subtracting queue wait from a number that never contained it. execution_ms was therefore under-reported by exactly the queue wait, and clamped to 0.0 whenever queue wait exceeded it, which is the common case under load. No field reported true end-to-end latency, and ttft_ms returned a -1.0 sentinel that violated the ge=0.0 constraint on GenerateResponse.ttft_ms.

Every metric is now measured directly between two raw timestamps, so total_ms == queue_wait_ms + execution_ms holds by construction:

enqueue ---- queue_wait_ms ----> first prefill ---- execution_ms ----> completion
|<---------------------------- total_ms --------------------------------->|

• Timing arithmetic moves into a pure compute_timings() in server/executor/events.py returning a frozen RequestTimings, so tests can write the timeline out directly instead of faking a clock.
• ttft_ms is now measured from enqueue and includes queue wait.
• tokens_per_s is now derived from execution_ms rather than total_ms. Since total_ms spans enqueue to completion, dividing by it would fold queue wait into the rate: a request that queued 4s and decoded 1s would report a fifth of its real decode speed, precisely in the overload cells this metric exists to compare. Aggregate system throughput remains a separate figure, computed by the benchmark client over its measurement window.
• DoneEvent.ttft becomes ttft_ms: float | None, and the API schema's ttft_ms fields are nullable — the -1.0 sentinel is gone.
• For v4, execution_ms includes any time a sequence spent preempted: start_ns is deliberately not reset on resume, so preemption is charged to execution rather than to waiting for admission.
• Field descriptions in server/api/schema.py and a new "Server-reported timing semantics" section in benchmarks/README.md document the definitions and the compatibility break.
• Tests cover the queue/execution split, a parametrised total == queue + execution invariant, a regression case for the zeroed-out execution_ms under heavy queue wait, null TTFT, and clamping of out-of-order timestamps.

BREAKING: total_ms, ttft_ms, execution_ms and tokens_per_s all change meaning. Artifacts under bench-results/ produced before this change are not comparable with artifacts produced after it.

[Copilot]

Pull request overview

This PR fixes inconsistencies in server-reported per-request timing metrics by measuring each metric directly from raw timestamps (starting at enqueue), removing the -1.0 TTFT sentinel in favor of null, and redefining tokens_per_s to reflect decode rate over execution time (excluding queue wait).

Changes:

• Introduces a pure compute_timings() helper to derive total_ms, queue_wait_ms, execution_ms, and nullable ttft_ms from raw timestamps, ensuring total_ms == queue_wait_ms + execution_ms.
• Updates DoneEvent/API schema to use ttft_ms: float | None (nullable) and updates routes to propagate the renamed field.
• Computes tokens_per_s using execution_ms (decode-only time) instead of total_ms and updates tests/docs accordingly.

Reviewed changes

Copilot reviewed 9 out of 9 changed files in this pull request and generated 1 comment.

Show a summary per file

File	Description
tests/executor/test_events.py	Adds unit tests for compute_timings() invariants, null TTFT behavior, and regression coverage under heavy queue wait.
tests/api/test_routes.py	Updates DoneEvent construction and adjusts tokens_per_s expectation to use execution_ms.
tests/api/test_collector.py	Updates DoneEvent construction to use ttft_ms.
server/executor/types.py	Renames DoneEvent.ttft to ttft_ms: float | None and documents updated timing semantics.
server/executor/events.py	Adds compute_timings() and uses it to populate DoneEvent timings; stamps first_token_ns only for real output tokens.
server/api/v1.py	Clarifies v1 timing/token rate semantics (no queue; execution == total).
server/api/schema.py	Makes ttft_ms nullable and updates field descriptions to match the new semantics.
server/api/routes.py	Computes tokens_per_s from execution_ms and switches ttft references to ttft_ms.
benchmarks/README.md	Documents the updated server timing semantics and compatibility implications for benchmark artifacts.

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.