feat(server): report per-request prefill and decode timings in api responses

docs/cli.md

@@ -116,8 +116,23 @@ Speculative decoding needs `--tp 1` and runs without overlap scheduling; targets
 | `--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-timings-report` | off | Attach a llama.cpp-shaped per-request `timings` object to responses |
 | `--anthropic-inline-system` | auto | Placement of late Anthropic system instructions: `auto`, `preserve`, or `fold` |
 
+With `--enable-timings-report` every chat completion, completion and Responses response
+also carries a llama.cpp-shaped `timings` object next to `usage` (`cache_n`, `prompt_n`,
+`prompt_ms`, `prompt_per_token_ms`, `prompt_per_second`, `predicted_n`, `predicted_ms`,
+`predicted_per_token_ms`, `predicted_per_second`, plus `queue_ms` as a FreeToken
+extension and `draft_n` / `draft_n_accepted` under speculative decoding), so frontends
+like llama-swap and Open Web UI show per-request prefill/decode rates. All spans are
+measured in the scheduler: `queue_ms` covers admission to the first prefill chunk,
+`prompt_ms` the first chunk to the first sampled token (chunk gaps included),
+`predicted_ms` the first to the last committed token; `prompt_n` counts only the
+evaluated tokens and the decode rates divide by `predicted_n - 1`, as in llama.cpp. On
+streams the object rides the final chunk; a multi-prompt `/v1/completions` request
+reports the first prompt's spans, as llama.cpp does. `/v1/messages` never carries it
+(llama.cpp emits no timings there either).
+
 ### Image input
 
 Experimental. Needs a checkpoint whose family registers a vision encoder ([models.md](models.md#image-input) lists them and how each one

python/freetoken/core.py

@@ -32,6 +32,48 @@ def is_greedy(self) -> bool:
         return self.temperature <= 0.0 or self.top_k == 1
 
 
+@dataclass
+class ReqStats:
+    """Per-request timing and draft counters, stamped by the scheduler with
+    time.perf_counter(). Spans follow llama.cpp's server_slot_stats plus a queue
+    span: queue = waiting queue -> first prefill chunk launch, prompt = first
+    chunk launch -> first sampled token on the host (chunk gaps included),
+    predicted = first token -> last committed token. One instance is shared by
+    every chunk Req of a request, so the stamps survive chunked prefill."""
+
+    enqueued_at: float | None = None     # entered the scheduler's waiting queue
+    first_chunk_at: float | None = None  # first prefill chunk launched
+    first_token_at: float | None = None  # first sampled token back on the host
+    last_token_at: float | None = None   # last committed token
+    cache_n: int = 0                     # prompt tokens served from the prefix cache at admission
+    prompt_n: int = 0                    # prompt tokens actually computed
+    draft_n: int = 0                     # drafted tokens summed over verify steps
+    draft_n_accepted: int = 0            # accepted drafts that were committed, after stop truncation
+
+    def stamp_token(self, now: float) -> None:
+        if self.first_token_at is None:
+            self.first_token_at = now
+        self.last_token_at = now
+
+    def finish(self, completion_tokens: int) -> dict | None:
+        """Raw spans and counts for the terminal reply; None when no prefill ever
+        launched or no token was committed (errors and aborts emit nothing)."""
+        if self.first_chunk_at is None or self.first_token_at is None:
+            return None
+        return {
+            "queue_ms": (self.first_chunk_at - self.enqueued_at) * 1000.0
+            if self.enqueued_at is not None else 0.0,
+            "cache_n": self.cache_n,
+            "prompt_n": self.prompt_n,
+            "prompt_ms": (self.first_token_at - self.first_chunk_at) * 1000.0,
+            "predicted_n": completion_tokens,
+            # 1 us floor as in llama.cpp: the first token can land in the same instant
+            "predicted_ms": max((self.last_token_at - self.first_token_at) * 1000.0, 0.001),
+            "draft_n": self.draft_n,
+            "draft_n_accepted": self.draft_n_accepted,
+        }
+
+
 @dataclass(eq=False)
 class Req:
     input_ids: torch.Tensor  # cpu tensor
@@ -68,6 +110,9 @@ class Req:
     # handler must not free resources under an in-flight forward; it sets this flag and
     # _process_last_data frees the request when the batch drains (after copy_done.synchronize).
     aborted: bool = False
+    # Timing/draft counters shared with every other chunk Req of this request (set by
+    # the PrefillManager from the PendingReq's instance; a default blank otherwise).
+    stats: ReqStats = field(default_factory=ReqStats, init=False, repr=False)
     output_token_counts: torch.Tensor | None = field(default=None, init=False, repr=False)
 
     def __post_init__(self) -> None:

python/freetoken/message/frontend.py

@@ -45,6 +45,10 @@ 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 per-request timings (queue/prompt/predicted spans, cache/prompt/
+    # predicted counts, draft counters), passthrough of DetokenizeMsg.timings: present on
+    # the terminal reply of a served request, None otherwise.
+    timings: dict | None = None
     # 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

@@ -49,6 +49,9 @@ 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 per-request timings (ReqStats.finish) on the terminal reply
+    # only; None on intermediate replies, errors and aborts.
+    timings: dict | None = None
 
 
 @dataclass

python/freetoken/scheduler/prefill.py

@@ -1,11 +1,12 @@
 from __future__ import annotations
 
 import math
+import time
 from dataclasses import dataclass, field
 from typing import TYPE_CHECKING, List, Tuple
 
 import torch
-from freetoken.core import Batch, Req
+from freetoken.core import Batch, Req, ReqStats
 from freetoken.utils import align_down, div_ceil, init_logger
 
 from .mm import mm_chunk_end, mm_rows_after
@@ -222,6 +223,9 @@ def _add_one_req(
         req.mm_items = pending_req.mm_items
         req.mrope_positions_full = pending_req.mrope_positions_full
         req.mrope_delta = pending_req.mrope_delta
+        # one ReqStats across all chunk Reqs of the request: the stamps the scheduler
+        # takes on the final chunk's Req must survive the intermediate ones
+        req.stats = pending_req.stats
         # Hybrid GDN per-request state slots (None for non-hybrid). On a fresh admit these are
         # freshly allocated; on a chunked continuation they are inherited from the prior chunk.
         req.linear_slot_idx = linear_slot_idx
@@ -283,6 +287,7 @@ class PrefillManager:
     pending_list: List[PendingReq] = field(default_factory=list)
 
     def add_one_req(self, req: UserMsg) -> None:
+        stats = ReqStats(enqueued_at=time.perf_counter())
         self.pending_list.append(
             PendingReq(
                 req.uid,
@@ -291,6 +296,7 @@ def add_one_req(self, req: UserMsg) -> None:
                 mm_items=req.mm_items,
                 mrope_positions_full=req.mrope_positions,
                 mrope_delta=req.mrope_delta,
+                stats=stats,
             )
         )
 
@@ -331,6 +337,11 @@ def schedule_next_batch(self, prefill_budget: int) -> Batch | None:
                     prompt_admissions.append(
                         (req.uid, pending_req.input_len, req.cache_handle.cached_len)
                     )
+                    # The first prefill chunk is launching: queue time ends here and the
+                    # prompt span starts (ReqStats carries both to the final chunk's Req).
+                    pending_req.stats.first_chunk_at = time.perf_counter()
+                    pending_req.stats.cache_n = req.cache_handle.cached_len
+                    pending_req.stats.prompt_n = pending_req.input_len - req.cache_handle.cached_len
                     if pending_req.mm_items and self.encoder_cache is not None:
                         # claim the rows every chunk of this request will gather; the entry outlives the chunks
                         for item in pending_req.mm_items:

python/freetoken/scheduler/scheduler.py

@@ -336,6 +336,8 @@ def _process_last_data(self, last_data: ForwardData | None) -> None:
         batch, output = last_data[0].batch, last_data[1]
         _, next_tokens_cpu, copy_done = output[:3]
         copy_done.synchronize()
+        # tokens are on the host from here: the per-request timings' token stamps
+        now = time.perf_counter()
         reply: List[DetokenizeMsg] = []
         new_finished_reqs: Set[Req] = set()
         generated = None
@@ -370,7 +372,10 @@ def _process_last_data(self, last_data: ForwardData | None) -> None:
                         # client's terminal reply.
                         continue
                     msg, _ = self._commit_tokens(req, next_tokens_cpu[i : i + 1])
+                    req.stats.stamp_token(now)
                     reply.append(msg)
+                    if msg.finished:
+                        msg.timings = req.stats.finish(req.input_ids.numel() - req.prompt_len)
                     finished = msg.finished
 
                     # NOTE: overlap scheduling may make the request freed twice, skip second free
@@ -424,12 +429,24 @@ def _drain_verify(self, batch: Batch, output, reply: List[DetokenizeMsg], new_fi
         """Commit each request's accepted tokens, return the slots its rejected rows took, then the target state; returns the tokens committed."""
         k = self.config.decode_rows_per_req - 1
         counts, finished = [], []
+        now = time.perf_counter()
         for i, req in enumerate(batch.reqs):
             # spec forces normal_loop, which frees an aborted request between steps; overlap would need rollback_tail here and must not donate the GDN slot the verify rolled
             assert not req.aborted, "a verify batch drained an aborted request"
             cached = req.cached_len
-            msg, n = self._commit_tokens(req, output.next_tokens_cpu[i, : int(output.emitted_cpu[i]) + 1])
+            emitted = int(output.emitted_cpu[i])
+            msg, n = self._commit_tokens(req, output.next_tokens_cpu[i, : emitted + 1])
+            # k drafts were proposed; the step hands _commit_tokens the emitted accepted
+            # drafts plus the target's own token, so when a stop lands on a draft every
+            # committed token is an accepted draft: count min(n, emitted), with n already
+            # post stop-truncation. Never exceeds predicted_n - 1: the request's first
+            # committed token came from prefill, outside every verify step.
+            req.stats.stamp_token(now)
+            req.stats.draft_n += k
+            req.stats.draft_n_accepted += min(n, emitted)
             reply.append(msg)
+            if msg.finished:
+                msg.timings = req.stats.finish(req.input_ids.numel() - req.prompt_len)
             req.commit_pending(n)
             self.cache_manager.rollback_tail(req, req.cached_len, cached + k + 1)
             counts.append(n)

python/freetoken/scheduler/utils.py

@@ -1,10 +1,12 @@
 from __future__ import annotations
 
-from dataclasses import dataclass
+from dataclasses import dataclass, field
 from typing import TYPE_CHECKING, List
 
 import torch
 
+from freetoken.core import ReqStats
+
 if TYPE_CHECKING:
     from freetoken.core import SamplingParams
 
@@ -20,6 +22,9 @@ class PendingReq:
     mm_items: list | None = None
     mrope_positions_full: torch.Tensor | None = None
     mrope_delta: int = 0
+    # timing/draft counters; add_one_req stamps enqueued_at on it, and every chunk
+    # Req built from this pending request shares the same instance
+    stats: ReqStats = field(default_factory=ReqStats)
 
     @property
     def input_len(self) -> int:

python/freetoken/server/args.py

@@ -61,6 +61,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
+    # Attach llama.cpp's per-request `timings` object to OpenAI chat/completions and
+    # Responses responses (plus queue_ms and, under speculative decoding, draft_n /
+    # draft_n_accepted). Opt-in like vLLM's --enable-per-request-metrics.
+    enable_timings_report: bool = False
     anthropic_inline_system: str = "auto"
     # Comma-separated hostname allowlist for client-supplied image URLs; empty admits any domain.
     allowed_media_domains: str = ""
@@ -584,6 +588,18 @@ def _infer_reasoning_parser(model_path: str) -> str | None:
         ),
     )
 
+    parser.add_argument(
+        "--enable-timings-report",
+        action="store_true",
+        default=ServerArgs.enable_timings_report,
+        help=(
+            "Attach a llama.cpp-shaped per-request timings object to every chat completion, "
+            "completion and Responses response (and to the final stream chunk), so frontends "
+            "like llama-swap and Open Web UI can show prefill/decode rates and cache hits. "
+            "Spans are measured in the scheduler; queue_ms is a FreeToken extension."
+        ),
+    )
+
     parser.add_argument(
         "--anthropic-inline-system",
         choices=("auto", "preserve", "fold"),

python/freetoken/server/generation.py

@@ -115,6 +115,7 @@ class GenDone:
     completion_tokens: int
     matched_stop: str | None = None
     cached_tokens: int = 0
+    timings: dict[str, Any] | None = None
 
 
 GenEvent = ReasoningDelta | ContentDelta | ToolCallStart | ToolCallArgsDelta | ToolCallsDelta | GenDone
@@ -130,6 +131,46 @@ class GenResult:
     completion_tokens: int
     matched_stop: str | None = None
     cached_tokens: int = 0
+    timings: dict[str, Any] | None = None
+
+
+def timings_block(state: Any, timings: dict[str, Any] | None) -> dict[str, Any] | None:
+    """llama.cpp's per-request timings object (server_slot_stats::to_json, b10408+) as
+    frontends like llama-swap read it, plus queue_ms as a FreeToken extension. The spans
+    and counts are measured in the scheduler (ReqStats) and arrive on the terminal ack:
+    queue_ms covers waiting-queue admission to the first prefill chunk, prompt_ms the
+    first chunk to the first sampled token on the host, predicted_ms the first to the
+    last committed token. prompt_n counts only the evaluated tokens and the decode rates
+    divide by predicted_n - 1 steps (the first token rides the last prompt batch),
+    matching llama.cpp's arithmetic. Values are not rounded. Off unless
+    --enable-timings-report: usage.prompt_tokens - prompt_n would otherwise still
+    reveal the prefix-cache hit that --enable-cache-report hides."""
+    if timings is None:
+        return None
+    config = getattr(state, "config", None) if state is not None else None
+    if not getattr(config, "enable_timings_report", False):
+        return None
+    prompt_n = timings["prompt_n"]
+    predicted_n = timings["predicted_n"]
+    prompt_ms = timings["prompt_ms"]
+    predicted_ms = timings["predicted_ms"]
+    gen_steps = max(predicted_n - 1, 0)
+    block: dict[str, Any] = {
+        "cache_n": timings["cache_n"],
+        "prompt_n": prompt_n,
+        "prompt_ms": prompt_ms,
+        "prompt_per_token_ms": prompt_ms / prompt_n if prompt_n > 0 else 0.0,
+        "prompt_per_second": 1e3 / prompt_ms * prompt_n if prompt_ms > 0 else 0.0,
+        "predicted_n": predicted_n,
+        "predicted_ms": predicted_ms,
+        "predicted_per_token_ms": predicted_ms / gen_steps if gen_steps > 0 else 0.0,
+        "predicted_per_second": 1e3 / predicted_ms * gen_steps if predicted_ms > 0 else 0.0,
+        "queue_ms": timings["queue_ms"],
+    }
+    if timings.get("draft_n", 0) > 0:
+        block["draft_n"] = timings["draft_n"]
+        block["draft_n_accepted"] = timings["draft_n_accepted"]
+    return block
 
 
 @dataclass
@@ -699,12 +740,15 @@ def _route_tool_text(piece: str) -> list[GenEvent]:
 
     engine_finish_reason: str | None = None
     engine_matched_stop: str | None = None
+    timings: dict[str, Any] | None = None
     async for ack in state.wait_for_ack(uid):
         if getattr(ack, "error", None):
             raise GenerationError(ack.error, getattr(ack, "error_code", None))
         prompt_tokens += ack.prompt_tokens_delta
         completion_tokens += ack.completion_tokens_delta
         cached_tokens += ack.cached_tokens
+        if getattr(ack, "timings", None) is not None:
+            timings = ack.timings
         content_delta = ack.incremental_output
         if reasoning_parser is not None and content_delta:
             reasoning_delta, content_delta = reasoning_parser.parse_stream_chunk(content_delta)
@@ -787,6 +831,7 @@ def _route_tool_text(piece: str) -> list[GenEvent]:
     yield GenDone(
         finish_reason, prompt_tokens, completion_tokens,
         matched_stop=engine_matched_stop, cached_tokens=cached_tokens,
+        timings=timings,
     )
 
 
@@ -797,6 +842,7 @@ async def _generate_full_impl(uid: int, spec: GenSpec, state: Any) -> GenResult:
     prompt_tokens = 0
     completion_tokens = 0
     cached_tokens = 0
+    timings: dict[str, Any] | None = None
     engine_finish_reason: str | None = None
     engine_matched_stop: str | None = None
     async for ack in state.wait_for_ack(uid):
@@ -805,6 +851,8 @@ async def _generate_full_impl(uid: int, spec: GenSpec, state: Any) -> GenResult:
         prompt_tokens += ack.prompt_tokens_delta
         completion_tokens += ack.completion_tokens_delta
         cached_tokens += ack.cached_tokens
+        if getattr(ack, "timings", None) is not None:
+            timings = ack.timings
         full_content += ack.incremental_output
         if ack.finished:
             engine_finish_reason = getattr(ack, "finish_reason", None)
@@ -831,4 +879,5 @@ async def _generate_full_impl(uid: int, spec: GenSpec, state: Any) -> GenResult:
         completion_tokens=completion_tokens,
         matched_stop=engine_matched_stop,
         cached_tokens=cached_tokens,
+        timings=timings,
     )