feat(server): serve per-request inference metrics under --enable-metr…

docs/cli.md

@@ -98,6 +98,62 @@ See [models.md](models.md#moe-strategies) for what each strategy does.
 | `--tool-call-parser` | auto | Tool-call format; auto-inferred from the model family |
 | `--reasoning-parser` | auto | Splits chain-of-thought into `reasoning_content`; auto-inferred; `off` disables |
 | `--enable-cache-report` | off | Report prefix-cache hits in each response's usage block |
+| `--enable-metrics-report` | off | Serve a per-request `metrics` object next to usage ([below](#per-request-performance-metrics)) |
+
+### Per-request performance metrics
+
+`--enable-metrics-report` adds a `metrics` object to each response on `/v1/chat/completions`,
+`/v1/messages` and `/v1/responses`. It is not part of any of those protocols, which is why it is
+off by default; clients that do not read it are unaffected.
+
+```json
+{
+  "usage": { "prompt_tokens": 8192, "completion_tokens": 256, "total_tokens": 8448 },
+  "metrics": {
+    "ttft_ms": 320.5,
+    "prefill_tokens": 2048,
+    "cached_prompt_tokens": 6144,
+    "prefill_time_ms": 410.0,
+    "prefill_tokens_per_second": 4995.12,
+    "decode_tokens": 256,
+    "decode_time_ms": 5120.8,
+    "decode_tokens_per_second": 49.8,
+    "total_time_ms": 5480.2
+  }
+}
+```
+
+| Field | Meaning |
+| --- | --- |
+| `ttft_ms` | Time to the first generated token, from the point the request entered the generation path |
+| `prefill_tokens` | Prompt tokens actually forwarded: `prompt_tokens - cached_prompt_tokens` |
+| `cached_prompt_tokens` | Prompt tokens served from the prefix cache instead of recomputed |
+| `prefill_time_ms` | The scheduler's own prefill span: admission to the token sampled off the last prefill chunk |
+| `prefill_tokens_per_second` | `prefill_tokens / prefill_time_ms` |
+| `decode_tokens` | Generated tokens (same as `usage.completion_tokens`) |
+| `decode_time_ms` | First generated token to the last |
+| `decode_tokens_per_second` | `(decode_tokens - 1) / decode_time_ms`; the first token comes out of prefill, so it spans no decode interval |
+| `total_time_ms` | Request latency up to the terminal engine reply, excluding HTTP framing |
+
+Reading the numbers:
+
+- `prefill_time_ms` is measured inside the scheduler, which is the point of the flag: a client
+  timing SSE frames cannot see when prefill starts or ends. The others are measured at the API
+  layer and carry the same IPC hops a client's own timestamps would.
+- `ttft_ms` is larger than `prefill_time_ms` by the time the request spent queued before
+  admission. Under load that gap is the queue, not the model.
+- Every span is **this request's share of shared work**. Its prefill chunk is co-scheduled with
+  other prompts and its decode steps are batched with other requests, so the throughputs
+  describe this request under that load, not isolated engine benchmarks. For those,
+  send one request at a time.
+- `cached_prompt_tokens` here always reports the real prefix-cache hit, whether or not
+  `--enable-cache-report` is set; that flag governs the billing fields in `usage`. Without it
+  `prefill_tokens_per_second` would be computed over tokens that were never forwarded.
+
+Streaming responses carry `metrics` on the same final message as usage, so the request has to ask
+for usage too: `stream_options: {"include_usage": true}` on `/v1/chat/completions`. On
+`/v1/messages` it rides `message_delta`; on `/v1/responses`, `response.completed`.
+`/v1/completions` does not serve `metrics`: it does not go through the shared generation core.
 
 ### Image input
 

python/freetoken/message/frontend.py

@@ -45,6 +45,9 @@ class UserReply(BaseFrontendMsg):
     swa_total_tokens: int = 0
     # Bytes the engine process holds on the GPU (torch reserved pool). 0 when not reported.
     gpu_mem_bytes: int = 0
+    # Scheduler-measured prefill span (see DetokenizeMsg.prefill_ms). Arrives once, on the
+    # reply carrying the request's first generated token; 0.0 on every other reply.
+    prefill_ms: float = 0.0
     # Set (with finished=True) when a request failed before producing output — e.g. a chat
     # template that the tokenizer cannot render, or a prompt that exceeds the KV budget the
     # scheduler can serve. Carries a human-readable reason. Without this, such a request would

python/freetoken/message/tokenizer.py

@@ -48,6 +48,11 @@ class DetokenizeMsg(BaseTokenizerMsg):
     swa_total_tokens: int = 0
     # Bytes this engine process holds on the GPU (torch reserved pool). 0 on CPU.
     gpu_mem_bytes: int = 0
+    # Scheduler-measured prefill span for this request: admission (the first prefill batch
+    # was prepared) to the token sampled off its last prefill chunk. Set on that first token
+    # only, 0.0 on every later one -- it is the one span a client cannot derive from HTTP
+    # timestamps, which is why it rides the wire instead of being re-estimated frontend-side.
+    prefill_ms: float = 0.0
 
 
 @dataclass

python/freetoken/scheduler/scheduler.py

@@ -1,6 +1,7 @@
 from __future__ import annotations
 
 import os
+import time
 
 from typing import TYPE_CHECKING, List, NamedTuple, NoReturn, Set, Tuple, TypeAlias
 
@@ -111,6 +112,11 @@ def __init__(self, config: SchedulerConfig):
         # tombstone so an abort-before-admission request can never be resurrected after its
         # terminal accounting acknowledgement has already been published.
         self._abort_tombstones: dict[int, None] = {}
+        # uid -> monotonic clock at admission, for the per-request prefill span shipped on the
+        # first sampled token. An entry existing IS the "this is the first token" test, so it is
+        # popped there; _free_req_resources pops too, so a request aborted mid-prefill (which
+        # never samples) cannot leave one behind.
+        self._prefill_start: dict[int, float] = {}
         self._forward_iter = 0  # global forward counter; drives the SWA proactive-eviction cadence
         # The launched-but-not-yet-drained batch (overlap): set at the top of each overlap_loop
         # iteration so the abort handler can tell whether a request's forward is still in flight
@@ -370,6 +376,10 @@ def _process_last_data(self, last_data: ForwardData | None) -> None:
                     and not finished
                 ):
                     req.toolcall_anchor_len = req.input_ids.numel()
+                # Present only until this request's first token is sampled, i.e. off its last
+                # prefill chunk -- so popping it both ends the prefill span and marks this as
+                # the one reply that carries it.
+                started_at = self._prefill_start.pop(req.uid, None)
                 reply.append(
                     DetokenizeMsg(
                         uid=req.uid,
@@ -378,6 +388,10 @@ def _process_last_data(self, last_data: ForwardData | None) -> None:
                         finish_reason=finish_reason,
                         matched_stop=matched_stop,
                         stop_strs=req.sampling_params.stop_strs or None,
+                        prefill_ms=(
+                            0.0 if started_at is None
+                            else (time.monotonic() - started_at) * 1000.0
+                        ),
                     )
                 )
 
@@ -631,6 +645,9 @@ def _free_req_resources(self, req: Req) -> None:
         # slots to two later requests. table_idx == -1 marks an already-freed request.
         if req.table_idx == -1:
             return
+        # A request freed without ever sampling (aborted mid-prefill) would otherwise keep its
+        # admission timestamp forever; a normally-finished one popped it at its first token.
+        self._prefill_start.pop(req.uid, None)
         # Polymorphic free: the DSV4 manager returns the request's window pages + cmp/idx blocks
         # to their tier free-lists; the generic manager frees its KV pages (it reads
         # page_table[req.table_idx], so free the table entry after).
@@ -886,6 +903,11 @@ def _report_prompt_admissions(self, batch: Batch) -> None:
         """
         if not batch.is_prefill or not batch.prompt_admissions:
             return
+        # Before the forward, which is what makes this the prefill START: _schedule_next_batch
+        # has prepared the batch but not run it.
+        now = time.monotonic()
+        for uid, _, _ in batch.prompt_admissions:
+            self._prefill_start[uid] = now
         self.send_result(
             [
                 PromptAdmittedMsg(uid=uid, prompt_tokens=prompt_tokens, cached_tokens=cached_tokens)

python/freetoken/server/anthropic_api.py

@@ -44,9 +44,11 @@
     ToolCallArgsDelta,
     ToolCallsDelta,
     ToolCallStart,
+    build_metrics,
     count_prompt_tokens,
     generate_events,
     generate_full,
+    metrics_enabled,
     render_messages,
     resolve_sampling,
     split_tool_lists,
@@ -126,10 +128,11 @@ async def handle_anthropic_messages(
         return _anthropic_error_response(400, "invalid_request_error", str(exc))
 
     cache_report = getattr(state.config, "enable_cache_report", False)
+    metrics = metrics_enabled(state)
     if req.stream:
         events = anthropic_event_stream(
             generate_events(uid, spec, state, source="/v1/messages"),
-            req.model, uid, cache_report=cache_report,
+            req.model, uid, cache_report=cache_report, metrics=metrics,
         )
         if request is not None:
             events = state.stream_with_cancellation(events, request, uid)
@@ -139,7 +142,9 @@ async def handle_anthropic_messages(
         result = await generate_full(uid, spec, state, source="/v1/messages")
     except GenerationError as exc:
         return _anthropic_error_response(400, "invalid_request_error", str(exc))
-    response = anthropic_full_response(result, req.model, uid, cache_report=cache_report)
+    response = anthropic_full_response(
+        result, req.model, uid, cache_report=cache_report, metrics=metrics
+    )
     return JSONResponse(content=response.model_dump(exclude_none=True))
 
 
@@ -375,7 +380,7 @@ def _tool_result_parts(content) -> tuple[str, list[dict[str, Any]]]:
 # Output formatting: GenResult / GenEvent -> Anthropic response / events
 # --------------------------------------------------------------------------- #
 def anthropic_full_response(
-    result: GenResult, model: str, uid: int, cache_report: bool = False
+    result: GenResult, model: str, uid: int, cache_report: bool = False, metrics: bool = False
 ) -> AnthropicMessagesResponse:
     content: list[AnthropicContentBlock] = []
     if result.reasoning:
@@ -402,6 +407,12 @@ def anthropic_full_response(
         usage=_anthropic_usage(
             result.prompt_tokens, result.completion_tokens, result.cached_tokens, cache_report
         ),
+        metrics=build_metrics(
+            prompt_tokens=result.prompt_tokens,
+            completion_tokens=result.completion_tokens,
+            cached_tokens=result.cached_tokens,
+            timings=result.timings,
+        ) if metrics else None,
     )
 
 
@@ -420,7 +431,8 @@ def _anthropic_usage(
 
 
 async def anthropic_event_stream(
-    events: AsyncIterator[Any], model: str, uid: int, cache_report: bool = False
+    events: AsyncIterator[Any], model: str, uid: int, cache_report: bool = False,
+    metrics: bool = False,
 ) -> AsyncIterator[str]:
     """Format the protocol-neutral GenEvent stream into Anthropic SSE events.
 
@@ -576,6 +588,12 @@ def _tool_args_delta(fragment: str) -> str:
                     usage=_anthropic_usage(
                         ev.prompt_tokens, ev.completion_tokens, ev.cached_tokens, cache_report
                     ),
+                    metrics=build_metrics(
+                        prompt_tokens=ev.prompt_tokens,
+                        completion_tokens=ev.completion_tokens,
+                        cached_tokens=ev.cached_tokens,
+                        timings=ev.timings,
+                    ) if metrics else None,
                 ))
                 yield _event(AnthropicStreamEvent(type="message_stop"))
                 # Anthropic streams terminate on message_stop — no OpenAI-style

python/freetoken/server/anthropic_models.py

@@ -153,6 +153,10 @@ class AnthropicMessagesResponse(BaseModel):
     ) = None
     stop_sequence: str | None = None
     usage: AnthropicUsage | None = None
+    # FreeToken extension, served only under --enable-metrics-report: per-request inference
+    # timings. Anthropic's wire has no such field, so it stays absent by default rather than
+    # being emitted as null -- both response paths dump with exclude_none.
+    metrics: dict[str, Any] | None = None
 
     def model_post_init(self, __context):
         if not self.id:
@@ -176,3 +180,5 @@ class AnthropicStreamEvent(BaseModel):
     index: int | None = None
     error: AnthropicError | None = None
     usage: AnthropicUsage | None = None
+    # Rides message_delta next to usage, under --enable-metrics-report only.
+    metrics: dict[str, Any] | None = None

python/freetoken/server/args.py

@@ -59,6 +59,10 @@ class ServerArgs(SchedulerConfig):
     # prompt_tokens_details.cached_tokens, Anthropic cache_read_input_tokens, Responses
     # input_tokens_details.cached_tokens). Mirrors sglang's --enable-cache-report.
     enable_cache_report: bool = False
+    # Serve a per-request `metrics` object (TTFT, prefill/decode times and throughputs,
+    # prefix-cache hit) alongside usage. Off by default: it is a non-standard field on
+    # every protocol we speak.
+    enable_metrics_report: bool = False
     # Comma-separated hostname allowlist for client-supplied image URLs; empty admits any domain.
     allowed_media_domains: str = ""
     # Directory file:// image refs may be read from; empty rejects local files.
@@ -524,6 +528,22 @@ def _infer_reasoning_parser(model_path: str) -> str | None:
         ),
     )
 
+    parser.add_argument(
+        "--enable-metrics-report",
+        action="store_true",
+        default=ServerArgs.enable_metrics_report,
+        help=(
+            "Serve a per-request `metrics` object next to usage on /v1/chat/completions, "
+            "/v1/completions, /v1/messages and /v1/responses: ttft_ms, prefill_time_ms and "
+            "prefill_tokens_per_second (the prefill span measured by the scheduler itself), "
+            "decode_time_ms and decode_tokens_per_second, cached_prompt_tokens and "
+            "total_time_ms. Streaming responses carry it on the same final chunk as usage, so "
+            "the request must also ask for usage (OpenAI stream_options.include_usage). "
+            "Non-standard on every protocol, hence opt-in. Under concurrency the spans are "
+            "this request's share of shared batches, not isolated engine throughput."
+        ),
+    )
+
     parser.add_argument(
         "--sampling-defaults",
         type=str,