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

benchmarks/README.md

@@ -157,6 +157,33 @@ bench-results/
 | `config.json` | Exact CLI arguments and the resolved scenario definition; sufficient to reproduce the run |
 | `requests.jsonl` | One JSON object per request (including failures); raw data for post-hoc analysis |
 
+### Server-reported timing semantics
+
+The server reports four timings per request, each measured between two raw
+timestamps so that `total_ms == queue_wait_ms + execution_ms`:
+
+```
+enqueue ---- queue_wait_ms ----> first prefill ---- execution_ms ----> completion
+|<---------------------------- total_ms --------------------------------->|
+```
+
+- `ttft_ms` is measured **from enqueue**, so it includes queue wait. It is
+  `null` when a request completes without emitting a token.
+- `tokens_per_s` is the decode rate: output tokens over `execution_ms`. It
+  deliberately excludes queue wait, so it stays comparable across load levels.
+  System-level throughput is a separate figure, computed by the benchmark
+  client over its measurement window and reported in `summary.json`.
+- When preemption available, `execution_ms` includes any time a sequence spent 
+  preempted. The start of the *first* prefill is not reset on resume, so preemption 
+  cost is accounted as execution rather than as queue wait.
+
+> **Compatibility:** these definitions changed. Previously `total_ms` and
+> `ttft_ms` were measured from the start of prefill rather than from enqueue,
+> `execution_ms` was computed as `total_ms - queue_wait_ms` (which
+> under-reported it by exactly the queue wait, clamping to `0.0` under load),
+> and `ttft_ms` used a `-1.0` sentinel instead of `null`. Artifacts produced
+> before this change are **not** comparable with artifacts produced after it.
+
 ---
 
 ## Common recipes

server/api/routes.py

@@ -23,9 +23,17 @@
 _GENERATION_TIMEOUT_S = 300  # 5 minutes
 
 
-def _compute_tokens_per_s(num_output_tokens: int, total_ms: float) -> float:
-    """Compute tokens per second from output token count and total time."""
-    return (num_output_tokens / (total_ms / 1000.0)) if total_ms > 0 else 0.0
+def _compute_tokens_per_s(num_output_tokens: int, execution_ms: float) -> float:
+    """Compute the decode rate in tokens per second.
+
+    Deliberately measured over ``execution_ms`` rather than ``total_ms``: since
+    ``total_ms`` spans enqueue to completion, dividing by it would fold queue
+    wait into the rate and make a request that queued for 4s and decoded for 1s
+    report a fifth of its real decode speed. Aggregate system throughput is a
+    separate number, computed by the benchmark client over its measurement
+    window.
+    """
+    return (num_output_tokens / (execution_ms / 1000.0)) if execution_ms > 0 else 0.0
 
 
 health_router = APIRouter()
@@ -118,14 +126,14 @@ async def _await_generation(
                 continue
             elif isinstance(event, DoneEvent):
                 tokens_per_s = _compute_tokens_per_s(
-                    event.num_output_tokens, event.total_ms
+                    event.num_output_tokens, event.execution_ms
                 )
 
                 return GenerateResponse(
                     text=event.text,
                     prompt_tokens=event.num_prompt_tokens,
                     output_tokens=event.num_output_tokens,
-                    ttft_ms=event.ttft,
+                    ttft_ms=event.ttft_ms,
                     total_ms=event.total_ms,
                     tokens_per_s=tokens_per_s,
                     queue_wait_ms=event.queue_wait_ms,
@@ -195,15 +203,15 @@ async def _stream_generation(
                         return
                     if isinstance(done_event, DoneEvent):
                         tokens_per_s = _compute_tokens_per_s(
-                            done_event.num_output_tokens, done_event.total_ms
+                            done_event.num_output_tokens, done_event.execution_ms
                         )
                         chunk = StreamChunk(
                             token_str=event.token,
                             is_first=event.is_first,
                             is_done=True,
                             prompt_tokens=done_event.num_prompt_tokens,
                             output_tokens=done_event.num_output_tokens,
-                            ttft_ms=done_event.ttft,
+                            ttft_ms=done_event.ttft_ms,
                             total_ms=done_event.total_ms,
                             tokens_per_s=tokens_per_s,
                             queue_wait_ms=done_event.queue_wait_ms,
@@ -213,7 +221,7 @@ async def _stream_generation(
                         log_event(
                             "stream_done",
                             output_tokens=done_event.num_output_tokens,
-                            ttft_ms=done_event.ttft,
+                            ttft_ms=done_event.ttft_ms,
                         )
                     elif isinstance(done_event, ErrorEvent):
                         error_chunk = StreamChunk(

server/api/schema.py

@@ -24,24 +24,39 @@ class GenerateResponse(BaseModel):
     output_tokens: int = Field(
         ..., ge=0, description="Number of tokens generated in the output"
     )
-    ttft_ms: float = Field(
-        ..., ge=0.0, description="Time to first token in milliseconds"
+    ttft_ms: float | None = Field(
+        default=None,
+        ge=0.0,
+        description=(
+            "Time from enqueue to the first token, in milliseconds. Null when "
+            "the request finished without emitting a token."
+        ),
     )
     total_ms: float = Field(
-        ..., ge=0.0, description="Total time for generation in milliseconds"
+        ...,
+        ge=0.0,
+        description=(
+            "Time from enqueue to completion, in milliseconds. Equals "
+            "queue_wait_ms + execution_ms."
+        ),
     )
     tokens_per_s: float = Field(
-        ..., ge=0.0, description="Generation speed in tokens per second"
+        ...,
+        ge=0.0,
+        description=(
+            "Decode rate: output tokens divided by execution_ms. Excludes queue "
+            "wait so the value stays comparable across load levels."
+        ),
     )
     queue_wait_ms: float = Field(
         0.0,
         ge=0.0,
-        description="Time spent waiting in the server queue before execution",
+        description="Time from enqueue to the start of the first prefill",
     )
     execution_ms: float = Field(
         0.0,
         ge=0.0,
-        description="Time spent executing after the request left the queue",
+        description="Time from the start of the first prefill to completion",
     )
 
 
@@ -65,21 +80,27 @@ class StreamChunk(BaseModel):
         default=None, ge=0, description="Output token count when known"
     )
     ttft_ms: float | None = Field(
-        default=None, ge=0.0, description="Time to first token in milliseconds"
+        default=None,
+        ge=0.0,
+        description="Time from enqueue to the first token, in milliseconds",
     )
     total_ms: float | None = Field(
-        default=None, ge=0.0, description="Total generation time in milliseconds"
+        default=None,
+        ge=0.0,
+        description="Time from enqueue to completion, in milliseconds",
     )
     tokens_per_s: float | None = Field(
-        default=None, ge=0.0, description="Generation speed in tokens per second"
+        default=None,
+        ge=0.0,
+        description="Decode rate: output tokens divided by execution_ms",
     )
     queue_wait_ms: float | None = Field(
         default=None,
         ge=0.0,
-        description="Time spent waiting in the server queue before execution",
+        description="Time from enqueue to the start of the first prefill",
     )
     execution_ms: float | None = Field(
         default=None,
         ge=0.0,
-        description="Time spent executing after the request left the queue",
+        description="Time from the start of the first prefill to completion",
     )

server/api/v1.py

@@ -80,6 +80,10 @@ def generate(req: GenerateRequest, request: Request) -> GenerateResponse:
 
     # We don't have streaming right now, so ttft_ms is the same as total_ms.
     ttft_ms = total_ms
+    # v1 runs inline in the HTTP handler with no queue, so enqueue, first prefill
+    # and the timer start all coincide: queue_wait_ms is 0 and execution_ms ==
+    # total_ms. Passing total_ms here is therefore the execution time that
+    # _compute_tokens_per_s expects.
     tokens_per_s = _compute_tokens_per_s(output_tokens, total_ms)
 
     log_event(

server/executor/events.py

@@ -1,3 +1,5 @@
+from dataclasses import dataclass
+
 from server.executor.types import (
     DecodeResult,
     DoneEvent,
@@ -11,6 +13,54 @@
 from server.metrics.timers import now_ns, ns_to_ms
 
 
+@dataclass(frozen=True)
+class RequestTimings:
+    """The four timing metrics reported for a completed request."""
+
+    total_ms: float
+    queue_wait_ms: float
+    execution_ms: float
+    ttft_ms: float | None
+
+
+def compute_timings(
+    *,
+    enqueued_ns: int,
+    start_ns: int,
+    first_token_ns: int | None,
+    end_ns: int,
+) -> RequestTimings:
+    """Derive the reported timings from the four raw request timestamps.
+
+    Each metric is measured directly between two timestamps rather than derived
+    from the others, so ``total_ms == queue_wait_ms + execution_ms`` holds to
+    floating-point precision::
+
+        enqueued_ns ---- queue_wait ----> start_ns ---- execution ----> end_ns
+        |<------------------------- total ---------------------------->|
+
+    ``start_ns`` is the start of the *first* prefill. v4 deliberately does not
+    reset it when a preempted sequence resumes (see
+    ``ScheduleInferenceEngine._post_prefill``), so time spent preempted is
+    counted as execution rather than as queue wait — preemption is a cost of
+    running, not of waiting to be admitted.
+
+    The ``max(..., 0.0)`` guards are defensive only: ``enqueued_ns`` is stamped
+    in ``Worker.submit`` before the request is queued and ``start_ns`` on the
+    engine thread after it is dequeued, so the timestamps are already ordered.
+    """
+    return RequestTimings(
+        total_ms=max(ns_to_ms(end_ns - enqueued_ns), 0.0),
+        queue_wait_ms=max(ns_to_ms(start_ns - enqueued_ns), 0.0),
+        execution_ms=max(ns_to_ms(end_ns - start_ns), 0.0),
+        ttft_ms=(
+            max(ns_to_ms(first_token_ns - enqueued_ns), 0.0)
+            if first_token_ns is not None
+            else None
+        ),
+    )
+
+
 class RequestEventEmitter:
     """Translates executor results into events emitted to each request's sink.
 
@@ -46,12 +96,17 @@ def on_token(
         On EOS the token text is emitted as an empty string (the model's EOS
         token itself is not part of the output).  For all other finished
         reasons (e.g. max length), the final token text is included.
+
+        ``first_token_ns`` is stamped only when an output token is actually
+        appended, so TTFT stays null for a request that finishes without
+        emitting one.
         """
         is_first = request_state.num_output_tokens == 0
-        if is_first:
-            request_state.first_token_ns = now_ns()
 
         if result.finish_reason == FinishReason.EOS:
+            # EOS produces no output token, so first_token_ns is deliberately
+            # left unset here. A request whose very first decode step is EOS
+            # finishes with zero output tokens and therefore a null TTFT.
             request_state.sink.emit(
                 TokenEvent(
                     request_id=request_state.request_id,
@@ -65,6 +120,9 @@ def on_token(
             self._finish(request_state)
             return
 
+        if is_first:
+            request_state.first_token_ns = now_ns()
+
         request_state.output_tokens.append(result.token)
         request_state.sink.emit(
             TokenEvent(
@@ -104,30 +162,25 @@ def _finish(self, request_state: GenerationRequestState) -> None:
         if request_state.enqueued_ns is None:
             raise RuntimeError("enqueued_ns must be set before _finish()")
 
-        total_ms = ns_to_ms(end_ns - request_state.start_ns)
-        queue_wait_ms = max(
-            ns_to_ms(request_state.start_ns - request_state.enqueued_ns),
-            0.0,
-        )
-        ttft_ms = (
-            ns_to_ms(request_state.first_token_ns - request_state.start_ns)
-            if request_state.first_token_ns is not None
-            else -1.0
-        )
-        execution_ms = max(total_ms - queue_wait_ms, 0.0)
-
         if request_state.num_prompt_tokens is None:
             raise RuntimeError("num_prompt_tokens is required to finish the request")
 
+        timings = compute_timings(
+            enqueued_ns=request_state.enqueued_ns,
+            start_ns=request_state.start_ns,
+            first_token_ns=request_state.first_token_ns,
+            end_ns=end_ns,
+        )
+
         request_state.sink.emit(
             DoneEvent(
                 request_id=request_state.request_id,
                 text="".join(request_state.output_tokens),
                 num_prompt_tokens=request_state.num_prompt_tokens,
                 num_output_tokens=request_state.num_output_tokens,
-                ttft=ttft_ms,
-                total_ms=total_ms,
-                queue_wait_ms=queue_wait_ms,
-                execution_ms=execution_ms,
+                ttft_ms=timings.ttft_ms,
+                total_ms=timings.total_ms,
+                queue_wait_ms=timings.queue_wait_ms,
+                execution_ms=timings.execution_ms,
             )
         )

server/executor/types.py

@@ -44,10 +44,20 @@ class DoneEvent:
         text: The full decoded text for the sequence, including all tokens.
         num_prompt_tokens: The number of tokens in the prompt.
         num_output_tokens: The number of tokens in the output sequence.
-        ttft: The time to first token in milliseconds (from start of prefill to first token).
-        total_ms: The total time from the start of prefill to completion in milliseconds.
-        queue_wait_ms: The time spent waiting in the queue before prefill started, in milliseconds.
-        execution_ms: Time spent executing after leaving the queue (total_ms - queue_wait_ms).
+
+    Every timing field below is derived from a raw timestamp rather than from
+    arithmetic on the other fields, so ``total_ms == queue_wait_ms +
+    execution_ms`` holds by construction:
+
+        ttft_ms: Enqueue to first token, in milliseconds. ``None`` when the
+            request finished without emitting a token.
+        total_ms: Enqueue to completion, in milliseconds.
+        queue_wait_ms: Enqueue to the start of the first prefill, in milliseconds.
+        execution_ms: Start of the first prefill to completion, in milliseconds.
+            For v4 this includes any time the sequence spent preempted, because
+            ``start_ns`` is deliberately not reset when a preempted sequence
+            resumes (see ``ScheduleInferenceEngine._post_prefill``). Preemption
+            cost therefore lands in execution, not in queue wait.
     """
 
     request_id: str
@@ -56,7 +66,7 @@ class DoneEvent:
     num_prompt_tokens: int
     num_output_tokens: int
 
-    ttft: float
+    ttft_ms: float | None
     total_ms: float
     queue_wait_ms: float
     execution_ms: float

tests/api/test_collector.py

@@ -28,7 +28,7 @@ def make_done(request_id: str) -> DoneEvent:
         text="hi",
         num_prompt_tokens=1,
         num_output_tokens=1,
-        ttft=1.0,
+        ttft_ms=1.0,
         total_ms=2.0,
         queue_wait_ms=0.5,
         execution_ms=1.5,

tests/api/test_routes.py

@@ -246,7 +246,7 @@ def make_done(request_id: str = "req-1") -> DoneEvent:
         text="hello world",
         num_prompt_tokens=3,
         num_output_tokens=2,
-        ttft=12.5,
+        ttft_ms=12.5,
         total_ms=50.0,
         queue_wait_ms=5.0,
         execution_ms=45.0,
@@ -297,7 +297,9 @@ async def test_await_generation_returns_done_event_metrics() -> None:
     assert response.total_ms == 50.0
     assert response.queue_wait_ms == 5.0
     assert response.execution_ms == 45.0
-    assert response.tokens_per_s == pytest.approx(40.0)
+    # Decode rate is measured over execution_ms (45 ms), not total_ms (50 ms),
+    # so the 5 ms of queue wait does not drag the reported rate down.
+    assert response.tokens_per_s == pytest.approx(2 / 0.045)
     # Terminal event consumed: the handler is gone, so is its mailbox.
     assert len(registry) == 0