diff --git a/benchmarks/README.md b/benchmarks/README.md index 5c3b96d..1618e8d 100644 --- a/benchmarks/README.md +++ b/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 diff --git a/server/api/routes.py b/server/api/routes.py index 09b4084..351411b 100644 --- a/server/api/routes.py +++ b/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,7 +203,7 @@ 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, @@ -203,7 +211,7 @@ async def _stream_generation( 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( diff --git a/server/api/schema.py b/server/api/schema.py index 8d39d9f..2dfc445 100644 --- a/server/api/schema.py +++ b/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", ) diff --git a/server/api/v1.py b/server/api/v1.py index 851b74d..0da3c48 100644 --- a/server/api/v1.py +++ b/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( diff --git a/server/executor/events.py b/server/executor/events.py index 424f6c0..c478897 100644 --- a/server/executor/events.py +++ b/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, ) ) diff --git a/server/executor/types.py b/server/executor/types.py index 221f736..d444303 100644 --- a/server/executor/types.py +++ b/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 diff --git a/tests/api/test_collector.py b/tests/api/test_collector.py index 05911f0..7841c42 100644 --- a/tests/api/test_collector.py +++ b/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, diff --git a/tests/api/test_routes.py b/tests/api/test_routes.py index b0c18f7..d47ae0e 100644 --- a/tests/api/test_routes.py +++ b/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 diff --git a/tests/executor/test_events.py b/tests/executor/test_events.py index e65687b..ebab5cd 100644 --- a/tests/executor/test_events.py +++ b/tests/executor/test_events.py @@ -4,7 +4,7 @@ import torch from transformers import DynamicCache -from server.executor.events import RequestEventEmitter +from server.executor.events import RequestEventEmitter, compute_timings from server.executor.sinks import SharedQueueSink from server.executor.types import ( DecodeResult, @@ -176,6 +176,158 @@ def test_failure_emits_error_event() -> None: assert events[0].error == "model error" +# --- timing arithmetic ------------------------------------------------------- +# +# compute_timings is pure, so the timeline can be written out directly instead +# of faking a clock. All values are nanoseconds; 1 ms == 1_000_000 ns. + + +def test_timings_split_queue_and_execution() -> None: + timings = compute_timings( + enqueued_ns=0, + start_ns=30_000_000, # queued 30 ms + first_token_ns=45_000_000, + end_ns=130_000_000, # executed 100 ms + ) + + assert timings.queue_wait_ms == pytest.approx(30.0) + assert timings.execution_ms == pytest.approx(100.0) + assert timings.total_ms == pytest.approx(130.0) + # TTFT is measured from enqueue, so it includes the queue wait. + assert timings.ttft_ms == pytest.approx(45.0) + + +@pytest.mark.parametrize( + "enqueued_ns,start_ns,end_ns", + [ + (0, 0, 1_000_000), # no queue wait at all + (0, 5_000_000, 5_000_000), # queued, then finished instantly + (1_000, 900_000_000, 4_000_000_000), # queue dominates + (7_777_777, 8_888_888, 999_999_999), # non-round timestamps + ], +) +def test_total_equals_queue_plus_execution( + enqueued_ns: int, start_ns: int, end_ns: int +) -> None: + timings = compute_timings( + enqueued_ns=enqueued_ns, + start_ns=start_ns, + first_token_ns=None, + end_ns=end_ns, + ) + + assert timings.total_ms == pytest.approx( + timings.queue_wait_ms + timings.execution_ms + ) + + +def test_heavy_queue_wait_does_not_zero_out_execution() -> None: + # The previous implementation computed execution_ms as + # (end - start) - queue_wait, which clamped to 0.0 whenever the queue wait + # exceeded the execution time. Under load that was the common case. + timings = compute_timings( + enqueued_ns=0, + start_ns=4_000_000_000, # 4 s in the queue + first_token_ns=4_020_000_000, + end_ns=5_000_000_000, # 1 s executing + ) + + assert timings.queue_wait_ms == pytest.approx(4000.0) + assert timings.execution_ms == pytest.approx(1000.0) + assert timings.total_ms == pytest.approx(5000.0) + + +def test_ttft_is_none_without_a_first_token() -> None: + timings = compute_timings( + enqueued_ns=0, + start_ns=1_000_000, + first_token_ns=None, + end_ns=2_000_000, + ) + + assert timings.ttft_ms is None + + +def test_timings_are_never_negative() -> None: + # Defensive: out-of-order timestamps should clamp rather than produce + # negative values that would fail the API schema's ge=0.0 constraint. + timings = compute_timings( + enqueued_ns=5_000_000, + start_ns=1_000_000, + first_token_ns=2_000_000, + end_ns=0, + ) + + assert timings.total_ms == 0.0 + assert timings.queue_wait_ms == 0.0 + assert timings.execution_ms == 0.0 + assert timings.ttft_ms == 0.0 + + +def test_done_event_carries_timings_measured_from_enqueue() -> None: + req = make_req() + req.status = RequestStatus.DECODING + req.num_prompt_tokens = 3 + # enqueued_ns is 0 from make_req(); start_ns is set far in the past relative + # to the real perf_counter clock read inside _finish, so total_ms and + # execution_ms are both large and positive, and their difference is exactly + # the fabricated queue wait. + req.start_ns = 25_000_000 + + RequestEventEmitter().on_token( + req, + DecodeResult(token_id=2, token="a", finish_reason=FinishReason.MAX_LENGTH), + ) + + done = drain_events(req)[1] + assert isinstance(done, DoneEvent) + assert done.queue_wait_ms == pytest.approx(25.0) + assert done.total_ms == pytest.approx(done.queue_wait_ms + done.execution_ms) + assert done.ttft_ms is not None + assert done.ttft_ms >= done.queue_wait_ms + + +def test_immediate_eos_reports_null_ttft() -> None: + # The model can sample EOS on the very first decode step. No output token + # is produced, so TTFT must stay null rather than timing the empty + # end-of-stream event. + req = make_req() + req.status = RequestStatus.DECODING + req.num_prompt_tokens = 3 + req.start_ns = 25_000_000 + + RequestEventEmitter().on_token( + req, + DecodeResult(token_id=2, token="", finish_reason=FinishReason.EOS), + ) + + assert req.first_token_ns is None + done = drain_events(req)[1] + assert isinstance(done, DoneEvent) + assert done.num_output_tokens == 0 + assert done.ttft_ms is None + + +def test_eos_after_a_token_keeps_ttft_from_that_token() -> None: + req = make_req() + req.status = RequestStatus.DECODING + req.num_prompt_tokens = 3 + req.start_ns = 25_000_000 + + emitter = RequestEventEmitter() + emitter.on_token(req, DecodeResult(token_id=2, token="a", finish_reason=None)) + first_token_ns = req.first_token_ns + emitter.on_token( + req, DecodeResult(token_id=3, token="", finish_reason=FinishReason.EOS) + ) + + assert req.first_token_ns == first_token_ns + done = drain_events(req)[-1] + assert isinstance(done, DoneEvent) + assert done.num_output_tokens == 1 + assert done.ttft_ms is not None + + def test_finish_requires_start_ns() -> None: req = make_req() req.num_prompt_tokens = 3