diff --git a/components/src/dynamo/frontend/frontend_args.py b/components/src/dynamo/frontend/frontend_args.py index b60180a78fb6..f1f0e5c9d630 100644 --- a/components/src/dynamo/frontend/frontend_args.py +++ b/components/src/dynamo/frontend/frontend_args.py @@ -201,6 +201,7 @@ class FrontendConfig(RouterConfigBase, KvRouterConfigBase, AisPerfConfigBase): model_name: Optional[str] model_path: Optional[str] metrics_prefix: Optional[str] = None + ttft_detail: str = "metrics" kserve_grpc_server: bool grpc_metrics_port: int @@ -228,6 +229,9 @@ class FrontendConfig(RouterConfigBase, KvRouterConfigBase, AisPerfConfigBase): _VALID_TOKENIZER_BACKENDS = {"default", "fastokens", "basetenkenizer"} def validate(self) -> None: + if self.ttft_detail not in {"off", "metrics", "logs", "both"}: + raise ValueError("--ttft-detail must be off, metrics, logs, or both") + if self.preprocess_workers is None: self.preprocess_workers = ( _default_sglang_preprocess_workers() @@ -648,6 +652,14 @@ def add_arguments(self, parser) -> None: arg_type=validate_model_path if self.env is None else str, env=self.env, ) + add_argument( + g, + flag_name="--ttft-detail", + env_var="DYN_FRONTEND_TTFT_DETAIL", + default="metrics", + choices=["off", "metrics", "logs", "both"], + help="Exclusive TTFT detail; logs also require dynamo_frontend::ttft=debug in DYN_LOG.", + ) add_argument( g, flag_name="--metrics-prefix", diff --git a/components/src/dynamo/frontend/main.py b/components/src/dynamo/frontend/main.py index b0522c4df354..7bfa56978f95 100644 --- a/components/src/dynamo/frontend/main.py +++ b/components/src/dynamo/frontend/main.py @@ -440,6 +440,7 @@ def signal_handler(): "router_config": router_config, "migration_limit": config.migration_limit, "metrics_prefix": metrics_prefix, + "ttft_detail": config.ttft_detail, "enable_anthropic_api": config.enable_anthropic_api, "enable_systemone_api": config.enable_systemone_api, "strip_anthropic_preamble": config.strip_anthropic_preamble, diff --git a/components/src/dynamo/frontend/prepost.py b/components/src/dynamo/frontend/prepost.py index 3231a4a456f9..bb2648b0ce14 100644 --- a/components/src/dynamo/frontend/prepost.py +++ b/components/src/dynamo/frontend/prepost.py @@ -44,6 +44,7 @@ should_attempt_structural_tag, ) from .thinking import apply_default_thinking_mode_to_template_kwargs +from .ttft import ttft_renderer_stage, ttft_stage from .utils import legacy_guided_decoding get_model_structural_tag: Any @@ -788,6 +789,7 @@ async def preprocess_chat_request( structural_tag_scope: str = "auto", structural_tag_schema: str = "auto", structural_tag_excludes_reasoning: bool = False, + context: Any | None = None, ) -> PreprocessResult: validated_request = _validate_chat_completion_request(request) assistant_guided_decoding = _build_assistant_guided_decoding(validated_request) @@ -844,39 +846,43 @@ async def preprocess_chat_request( # Render first: whether generation starts inside a reasoning block depends # on the rendered prompt (e.g. a template that ends the generation prompt # with an open think tag), and the tool-call grammar must match it. - _, engine_prompt = await renderer.render_messages_async(messages, chat_params) + with ttft_renderer_stage(context) as renderer_timing: + _, engine_prompt = await renderer.render_messages_async(messages, chat_params) + renderer_timing[0] = "prompt_token_ids" in engine_prompt if "prompt_token_ids" in engine_prompt: tokens = list(engine_prompt["prompt_token_ids"]) else: - async_tokenizer = _get_async_tokenizer(tokenizer) - encoded = await async_tokenizer( - engine_prompt["prompt"], - add_special_tokens=request_for_sampling.add_special_tokens, - ) - tokens = list(encoded.input_ids) - - tool_guided_decoding = build_tool_call_guided_decoding( - request_for_sampling, - tool_parser, - parser_guided_decoding=parser_guided_decoding, - structural_tag_mode=structural_tag_mode, - structural_tag_scope=structural_tag_scope, - structural_tag_schema=structural_tag_schema, - starts_in_reasoning=( - structural_tag_mode == "on" - and tool_parser is not None - and bool(request_for_sampling.tools) - and not structural_tag_excludes_reasoning - and _prompt_leaves_reasoning_open( - tokens, - tokenizer=tokenizer, - reasoning_parser_class=reasoning_parser_class, - chat_template_kwargs=chat_template_kwargs, - model_config=model_config, + with ttft_stage(context, "tokenize"): + async_tokenizer = _get_async_tokenizer(tokenizer) + encoded = await async_tokenizer( + engine_prompt["prompt"], + add_special_tokens=request_for_sampling.add_special_tokens, ) - ), - ) + tokens = list(encoded.input_ids) + + with ttft_stage(context, "structural_tag_build"): + tool_guided_decoding = build_tool_call_guided_decoding( + request_for_sampling, + tool_parser, + parser_guided_decoding=parser_guided_decoding, + structural_tag_mode=structural_tag_mode, + structural_tag_scope=structural_tag_scope, + structural_tag_schema=structural_tag_schema, + starts_in_reasoning=( + structural_tag_mode == "on" + and tool_parser is not None + and bool(request_for_sampling.tools) + and not structural_tag_excludes_reasoning + and _prompt_leaves_reasoning_open( + tokens, + tokenizer=tokenizer, + reasoning_parser_class=reasoning_parser_class, + chat_template_kwargs=chat_template_kwargs, + model_config=model_config, + ) + ), + ) # A forced tool choice already claims the decoder's single grammar slot, so a # caller-set guided_*/structured_outputs constraint over the same token stream # cannot also be honored. Reject it (InvalidArgument -> 400) rather than diff --git a/components/src/dynamo/frontend/sglang_prepost.py b/components/src/dynamo/frontend/sglang_prepost.py index 5f34314d5617..0ed41e43bbdd 100644 --- a/components/src/dynamo/frontend/sglang_prepost.py +++ b/components/src/dynamo/frontend/sglang_prepost.py @@ -40,6 +40,7 @@ should_attempt_structural_tag, ) from .thinking import apply_default_thinking_mode_to_template_kwargs +from .ttft import ttft_coarse, ttft_stage from .utils import PreprocessError, legacy_guided_decoding, random_call_id logger = logging.getLogger(__name__) @@ -522,6 +523,7 @@ def _render_deepseek_v4_prompt_token_ids( messages: list[dict[str, Any]], tokenizer, template_tools: list[dict[str, Any]] | None, + context: Any | None = None, ) -> list[int]: """Render DeepSeek-V4 prompt token ids via SGLang's ``encoding_dsv4``. @@ -581,12 +583,14 @@ def _render_deepseek_v4_prompt_token_ids( if reasoning_effort not in ("max", "high", None): reasoning_effort = None - prompt = encode_messages( - encoding_messages, - thinking_mode=thinking_mode, - reasoning_effort=reasoning_effort, - ) - return _normalize_prompt_token_ids(tokenizer.encode(prompt)) + with ttft_stage(context, "template_render"): + prompt = encode_messages( + encoding_messages, + thinking_mode=thinking_mode, + reasoning_effort=reasoning_effort, + ) + with ttft_stage(context, "tokenize"): + return _normalize_prompt_token_ids(tokenizer.encode(prompt)) @lru_cache(maxsize=64) @@ -890,6 +894,7 @@ def preprocess_chat_request( structural_tag_mode: str = "off", structural_tag_scope: str = "auto", structural_tag_schema: str = "auto", + context: Any | None = None, ) -> SglangPreprocessResult: """Preprocess a chat request using SGLang tokenizer and parser APIs. @@ -977,6 +982,7 @@ def preprocess_chat_request( messages=messages, tokenizer=tokenizer, template_tools=template_tools, + context=context, ) else: # Build template kwargs -- single call for rendering + tokenization @@ -1004,25 +1010,30 @@ def preprocess_chat_request( template_messages = _normalize_messages_for_template(messages, tokenizer) - try: - rendered = tokenizer.apply_chat_template( - template_messages, **template_kwargs - ) - except (TemplateError, TypeError) as exc: - # Jinja filters such as tojson can raise TypeError for invalid inputs. - raise PreprocessError(str(exc)) from exc - prompt_token_ids = _normalize_prompt_token_ids(rendered) - - response_format_guided_decoding = build_response_format_guided_decoding(request) - tool_call_guided_decoding = build_tool_call_guided_decoding( - request, - tool_call_parser_name=tool_call_parser_name, - sglang_tools=sglang_tools, - structural_tag_mode=structural_tag_mode, - structural_tag_scope=structural_tag_scope, - structural_tag_schema=structural_tag_schema, - tokenizer=tokenizer, - ) + # A custom apply_chat_template may combine backend-specific rendering + # and tokenization. Preserve its single call and expose the opaque span. + ttft_coarse(context, "opaque_template") + with ttft_stage(context, "template_tokenize"): + try: + rendered = tokenizer.apply_chat_template( + template_messages, **template_kwargs + ) + except (TemplateError, TypeError) as exc: + # Jinja filters such as tojson can raise TypeError for invalid inputs. + raise PreprocessError(str(exc)) from exc + prompt_token_ids = _normalize_prompt_token_ids(rendered) + + with ttft_stage(context, "structural_tag_build"): + response_format_guided_decoding = build_response_format_guided_decoding(request) + tool_call_guided_decoding = build_tool_call_guided_decoding( + request, + tool_call_parser_name=tool_call_parser_name, + sglang_tools=sglang_tools, + structural_tag_mode=structural_tag_mode, + structural_tag_scope=structural_tag_scope, + structural_tag_schema=structural_tag_schema, + tokenizer=tokenizer, + ) # This path also never reads the legacy guided_json / guided_regex / # guided_grammar / guided_choice fields at all, so those are dropped silently # while both other paths honor them (and reject them against a forced choice). diff --git a/components/src/dynamo/frontend/sglang_processor.py b/components/src/dynamo/frontend/sglang_processor.py index fee11389ecc7..2a02e9abe417 100644 --- a/components/src/dynamo/frontend/sglang_processor.py +++ b/components/src/dynamo/frontend/sglang_processor.py @@ -43,6 +43,13 @@ ) from .structural_tag_policy import runtime_structural_tag_options from .thinking import runtime_default_thinking_mode +from .ttft import ( + TimingBatch, + WorkerTiming, + import_worker_batch, + ttft_context, + ttft_stage, +) from .usage import response_usage, update_usage_metadata from .utils import ( PreprocessError, @@ -347,6 +354,16 @@ class SglangPreprocessWorkerResult: effective_reasoning_parser_name: str | None = None +@dataclass +class SglangTimedPreprocessWorkerResult(SglangPreprocessWorkerResult): + """Enabled-only payload; the off result does not serialize a timing field.""" + + timing_batch: TimingBatch | None = None + + +_WorkerPreprocessTiming = WorkerTiming + + def _init_worker( model_path: str, tool_call_parser_name: str | None, @@ -382,8 +399,10 @@ def _preprocess_worker( request: dict[str, Any], model_name: str, eos_token_ids: list[int] | None, + record_ttft_timing: bool = False, ) -> SglangPreprocessWorkerResult: """Preprocess a request in a worker process and return a picklable result.""" + timing = _WorkerPreprocessTiming() if record_ttft_timing else None pre = preprocess_chat_request( request, tokenizer=_w_tokenizer, @@ -395,6 +414,7 @@ def _preprocess_worker( structural_tag_mode=_w_structural_tag_mode, structural_tag_scope=_w_structural_tag_scope, structural_tag_schema=_w_structural_tag_schema, + context=timing, ) n = request.get("n", 1) @@ -419,7 +439,7 @@ def _preprocess_worker( _w_reasoning_parser_name if _client_wants_separate_reasoning(request) else None ) - return SglangPreprocessWorkerResult( + result = SglangPreprocessWorkerResult( prompt_token_ids=pre.prompt_token_ids, dynamo_preproc=dynamo_preproc, request=request, @@ -427,6 +447,11 @@ def _preprocess_worker( effective_reasoning_parser_name=effective_reasoning_parser_name, named_zero_arg_tool=pre.named_zero_arg_tool, ) + if timing is not None: + return SglangTimedPreprocessWorkerResult( + **vars(result), timing_batch=timing.batch() + ) + return result def _build_dynamo_preproc( @@ -680,23 +705,26 @@ async def _generator_inner( ) -> AsyncGenerator[dict[str, Any], None]: """Single-process path: preprocess, dispatch, stream post-process.""" request_id = random_uuid() + timing_context = ttft_context(context) try: if self.debug_perf: t0 = time.monotonic() - pre = preprocess_chat_request( - request, - tokenizer=self.tokenizer, - tool_call_parser_name=self.tool_call_parser_name, - reasoning_parser_name=self.reasoning_parser_name, - exclude_tools_when_tool_choice_none=self.exclude_tools_when_tool_choice_none, - template_force_reasoning=self.template_force_reasoning, - default_thinking_mode=self.default_thinking_mode, - structural_tag_mode=self.structural_tag_mode, - structural_tag_scope=self.structural_tag_scope, - structural_tag_schema=self.structural_tag_schema, - ) + with ttft_stage(timing_context, "preprocess"): + pre = preprocess_chat_request( + request, + tokenizer=self.tokenizer, + tool_call_parser_name=self.tool_call_parser_name, + reasoning_parser_name=self.reasoning_parser_name, + exclude_tools_when_tool_choice_none=self.exclude_tools_when_tool_choice_none, + template_force_reasoning=self.template_force_reasoning, + default_thinking_mode=self.default_thinking_mode, + structural_tag_mode=self.structural_tag_mode, + structural_tag_scope=self.structural_tag_scope, + structural_tag_schema=self.structural_tag_schema, + context=timing_context, + ) if self.debug_perf: t1 = time.monotonic() @@ -760,17 +788,31 @@ async def _generator_inner_pool( # --- Phase 1: Preprocess (semaphore held) --- assert self._worker_semaphore is not None assert self.preprocess_pool is not None + timing_context = ttft_context(context) + enabled = timing_context is not None try: - async with self._worker_semaphore: - future = self.preprocess_pool.submit( - _preprocess_worker, - request, - request["model"], - self.eos_token_ids, - ) - preproc_result: SglangPreprocessWorkerResult = ( - await asyncio.wrap_future(future) - ) + with ttft_stage(timing_context, "preprocess"): + with ttft_stage(timing_context, "preprocess_queue"): + await self._worker_semaphore.acquire() + try: + submitted_ns = time.monotonic_ns() if enabled else 0 + # Omit the optional argument entirely when disabled, and use + # the base result without any timing payload on that path. + args = (request, request["model"], self.eos_token_ids) + future = self.preprocess_pool.submit( + _preprocess_worker, *args, *((True,) if enabled else ()) + ) + preproc_result: SglangPreprocessWorkerResult = ( + await asyncio.wrap_future(future) + ) + finally: + self._worker_semaphore.release() + if enabled: + import_worker_batch( + timing_context, + getattr(preproc_result, "timing_batch", None), + submitted_ns, + ) except InvalidArgument: raise except PreprocessError as exc: diff --git a/components/src/dynamo/frontend/tests/test_frontend_preprocess_workers_args.py b/components/src/dynamo/frontend/tests/test_frontend_preprocess_workers_args.py index 57b21c1a5382..b53598e48f39 100644 --- a/components/src/dynamo/frontend/tests/test_frontend_preprocess_workers_args.py +++ b/components/src/dynamo/frontend/tests/test_frontend_preprocess_workers_args.py @@ -222,3 +222,27 @@ def test_cgroup_v1_uses_ancestor_quota( ) assert frontend_args._cpu_quota_count() == 1 + + +@pytest.mark.parametrize("mode", ["off", "metrics", "logs", "both"]) +def test_ttft_detail_env_and_explicit_cli_precedence(monkeypatch, mode): + monkeypatch.setenv("DYN_FRONTEND_TTFT_DETAIL", mode) + assert parse_frontend_config([]).ttft_detail == mode + assert parse_frontend_config(["--ttft-detail", "off"]).ttft_detail == "off" + + +def test_ttft_detail_defaults_metrics(monkeypatch): + monkeypatch.delenv("DYN_FRONTEND_TTFT_DETAIL", raising=False) + assert parse_frontend_config([]).ttft_detail == "metrics" + + +def test_ttft_detail_rejects_invalid_mode(monkeypatch): + monkeypatch.delenv("DYN_FRONTEND_TTFT_DETAIL", raising=False) + with pytest.raises(SystemExit): + parse_frontend_config(["--ttft-detail", "invalid"]) + + +def test_ttft_detail_rejects_invalid_environment(monkeypatch): + monkeypatch.setenv("DYN_FRONTEND_TTFT_DETAIL", "invalid") + with pytest.raises(ValueError, match="ttft-detail"): + parse_frontend_config([]) diff --git a/components/src/dynamo/frontend/tests/test_ttft_stages.py b/components/src/dynamo/frontend/tests/test_ttft_stages.py new file mode 100644 index 000000000000..c8299929523d --- /dev/null +++ b/components/src/dynamo/frontend/tests/test_ttft_stages.py @@ -0,0 +1,960 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 + +"""Frontend TTFT boundaries with lightweight backend and native-binding stubs.""" + +import asyncio +import importlib +import pickle +from concurrent.futures import Future +from contextlib import contextmanager +from pathlib import Path +from types import SimpleNamespace + +import pytest +import test_sglang_processor_metrics_unit as processor_tests +from test_sglang_processor_metrics_unit import _load_processor_module + +# Register the shared fixture for pytest discovery. +module_stubs = processor_tests.module_stubs + +pytestmark = [ + pytest.mark.unit, + pytest.mark.gpu_0, + pytest.mark.pre_merge, + pytest.mark.core, +] + + +class RecordingContext: + ttft_enabled = True + + def __init__(self): + self.events = [] + self.intervals = [] + self.quality = [] + + @contextmanager + def start_ttft_stage(self, stage): + self.events.append(("start", stage)) + try: + yield + finally: + self.events.append(("end", stage)) + + def record_ttft_batch_ago(self, intervals, coarse_reasons=()): + self.intervals.extend(intervals) + self.quality.extend(("coarse", reason) for reason in coarse_reasons) + + def mark_ttft_quality(self, quality, reason): + self.quality.append((quality, reason)) + + +class Tokenizer: + chat_template = "{{ messages }}" + bos_token_id = 1 + + def apply_chat_template(self, messages, **kwargs): + return [1, 2, 3] + + def encode(self, text): + return [4, 5] + + +def chat_request(): + return {"model": "test", "messages": [{"role": "user", "content": "hello"}]} + + +@pytest.fixture +def frontend_stubs(request): + install, remove = request.getfixturevalue("module_stubs") + # Load only the pure Python utilities used here; common.utils.__init__ + # otherwise imports unrelated runtime-backed endpoint helpers. + install( + "dynamo.common.utils", + __path__=[str(Path(__file__).parents[2] / "common" / "utils")], + ) + install("dynamo._internal", ModelDeploymentCard=object) + # Deliberately synthetic IDs prove the Python transport uses the binding + # registry, rather than copying production enum discriminants. + names = ( + "preprocess", + "preprocess_queue", + "template_tokenize", + "template_render", + "tokenize", + "structural_tag_build", + "multimodal_prepare", + "mm_routing_build", + ) + install("dynamo._core", ttft_stage_registry=lambda: list(enumerate(names, 100))) + from dynamo.frontend import ttft + + ttft.stage_registry.cache_clear() + install("dynamo.frontend.frontend_args", FrontendConfig=object) + install( + "dynamo.llm", + ModelCardInstanceId=object, + PythonAsyncEngine=object, + RoutedEngine=object, + ) + install( + "dynamo.llm.exceptions", + HttpError=type("HttpError", (Exception,), {}), + InvalidArgument=type("InvalidArgument", (Exception,), {}), + Unknown=type("Unknown", (Exception,), {}), + WorkerUnavailable=type("WorkerUnavailable", (Exception,), {}), + ) + # Restore all frontend modules imported against these stubs after each test. + for name in ( + "utils", + "sglang_prepost", + "sglang_processor", + "prepost", + "vllm_processor", + ): + remove("dynamo.frontend." + name) + for name in ("dynamo.common.utils.guided_json", "dynamo.vllm.errors"): + remove(name) + return install, remove + + +@pytest.fixture +def sglang_modules(frontend_stubs, monkeypatch): + processor = _load_processor_module(frontend_stubs) + _, remove = frontend_stubs + importlib.import_module("dynamo.llm").HttpError = importlib.import_module( + "dynamo.llm.exceptions" + ).HttpError + remove("dynamo.frontend.sglang_prepost") + prepost = importlib.import_module("dynamo.frontend.sglang_prepost") + monkeypatch.setattr( + processor, "preprocess_chat_request", prepost.preprocess_chat_request + ) + monkeypatch.setattr( + processor, "SglangStreamingPostProcessor", lambda **kwargs: object() + ) + + async def stream(*args, **kwargs): + yield {"ok": True} + + monkeypatch.setattr(processor.SglangProcessor, "_generate_and_stream", stream) + return processor, prepost + + +def make_sglang_processor(module, **kwargs): + return module.SglangProcessor( + tokenizer=Tokenizer(), + routed_engine=None, + tool_call_parser_name=None, + reasoning_parser_name=None, + eos_token_ids=None, + **kwargs, + ) + + +def test_sglang_inline_preprocess_and_legacy_context(sglang_modules): + module, _ = sglang_modules + processor = make_sglang_processor(module) + context = RecordingContext() + + async def collect(context): + return [ + item async for item in processor.generator(chat_request(), context=context) + ] + + assert asyncio.run(collect(context)) == [{"ok": True}] + assert context.events == [ + ("start", "preprocess"), + ("start", "template_tokenize"), + ("end", "template_tokenize"), + ("start", "structural_tag_build"), + ("end", "structural_tag_build"), + ("end", "preprocess"), + ] + assert asyncio.run(collect(None)) == [{"ok": True}] + assert asyncio.run(collect(object())) == [{"ok": True}] + + +def test_sglang_template_error_closes_spans(sglang_modules): + from jinja2.exceptions import TemplateError + + module, _ = sglang_modules + context = RecordingContext() + + class BrokenTokenizer(Tokenizer): + def apply_chat_template(self, *args, **kwargs): + raise TemplateError("bad template") + + processor = make_sglang_processor(module) + processor.tokenizer = BrokenTokenizer() + + async def collect(): + return [ + item async for item in processor.generator(chat_request(), context=context) + ] + + with pytest.raises(module.InvalidArgument, match="bad template"): + asyncio.run(collect()) + assert context.events[-2:] == [ + ("end", "template_tokenize"), + ("end", "preprocess"), + ] + + +def test_sglang_deepseek_custom_encoder_is_timed( + sglang_modules, frontend_stubs, monkeypatch +): + _, prepost = sglang_modules + install, _ = frontend_stubs + context = RecordingContext() + + def encode_messages(*args, **kwargs): + assert context.events[-1] == ("start", "template_render") + return "rendered" + + install( + "sglang.srt.entrypoints.openai.encoding_dsv4", encode_messages=encode_messages + ) + monkeypatch.setattr( + prepost, "_should_use_deepseek_v4_encoding", lambda *args, **kwargs: True + ) + result = prepost.preprocess_chat_request( + chat_request(), + tokenizer=Tokenizer(), + tool_call_parser_name=None, + reasoning_parser_name=None, + context=context, + ) + assert result.prompt_token_ids == [4, 5] + assert context.events == [ + ("start", "template_render"), + ("end", "template_render"), + ("start", "tokenize"), + ("end", "tokenize"), + ("start", "structural_tag_build"), + ("end", "structural_tag_build"), + ] + + +def test_sglang_worker_returns_picklable_monotonic_intervals( + sglang_modules, monkeypatch +): + module, _ = sglang_modules + monkeypatch.setattr(module, "_w_tokenizer", Tokenizer()) + from dynamo.frontend import ttft + + clock = iter([10_000_000_000, 10_200_000_000, 10_300_000_000, 10_400_000_000]) + monkeypatch.setattr(ttft.time, "monotonic_ns", lambda: next(clock)) + result = module._preprocess_worker(chat_request(), "test", None, True) + result = pickle.loads(pickle.dumps(result)) + assert result.timing_batch.intervals_ns == ( + ttft.TimingInterval( + ttft.stage_registry()["template_tokenize"], 10_000_000_000, 10_200_000_000 + ), + ttft.TimingInterval( + ttft.stage_registry()["structural_tag_build"], + 10_300_000_000, + 10_400_000_000, + ), + ) + assert result.timing_batch.coarse_reasons == ("opaque_template",) + assert result.prompt_token_ids == [1, 2, 3] + disabled = module._preprocess_worker(chat_request(), "test", None) + assert not hasattr(disabled, "timing_batch") + assert b"timing_batch" not in pickle.dumps(disabled) + + +def test_sglang_worker_rejects_unsupported_ttft_stage(sglang_modules): + module, _ = sglang_modules + timing = module._WorkerPreprocessTiming() + with pytest.raises(ValueError, match="Unsupported TTFT stage: arbitrary"): + with timing.start_ttft_stage("arbitrary"): + pass + assert timing.intervals_ns == [] + + +def test_sglang_pool_reattaches_worker_intervals(sglang_modules, monkeypatch): + module, _ = sglang_modules + context = RecordingContext() + from dynamo.frontend import ttft + + result = module.SglangTimedPreprocessWorkerResult( + prompt_token_ids=[1], + dynamo_preproc={"sampling_options": {"guided_decoding": None}}, + request=chat_request(), + timing_batch=ttft.TimingBatch( + 1, + ttft.clock_domain(), + ( + ttft.TimingInterval( + ttft.stage_registry()["template_render"], + 10_000_000_000, + 10_200_000_000, + ), + ttft.TimingInterval( + ttft.stage_registry()["tokenize"], 10_200_000_000, 10_400_000_000 + ), + ), + ), + ) + + class Pool: + def submit(self, fn, *args): + assert args[-1] is True + assert context not in args + assert context.events[-1] == ("end", "preprocess_queue") + future = Future() + future.set_result(result) + return future + + clock = iter([9_000_000_000, 11_000_000_000]) + monkeypatch.setattr(ttft.time, "monotonic_ns", lambda: next(clock)) + processor = make_sglang_processor(module, preprocess_pool=Pool()) + + async def collect(): + return [ + item async for item in processor.generator(chat_request(), context=context) + ] + + assert asyncio.run(collect()) == [{"ok": True}] + assert context.intervals == [ + (ttft.stage_registry()["template_render"], 1_000_000_000, 800_000_000), + (ttft.stage_registry()["tokenize"], 800_000_000, 600_000_000), + ] + assert context.events == [ + ("start", "preprocess"), + ("start", "preprocess_queue"), + ("end", "preprocess_queue"), + ("end", "preprocess"), + ] + assert processor._worker_semaphore._value == 2 + + +@pytest.mark.parametrize("queued", [False, True]) +def test_sglang_pool_cancellation_preserves_semaphore(sglang_modules, queued): + module, _ = sglang_modules + context = RecordingContext() + + class Pool: + def submit(self, *args): + assert not queued + return Future() + + processor = make_sglang_processor(module, preprocess_pool=Pool()) + initial_capacity = 0 if queued else 2 + processor._worker_semaphore = asyncio.Semaphore(initial_capacity) + + async def cancel(): + task = asyncio.create_task( + anext(processor.generator(chat_request(), context=context)) + ) + await asyncio.sleep(0) + task.cancel() + with pytest.raises(asyncio.CancelledError): + await task + + asyncio.run(cancel()) + assert context.events[-1] == ("end", "preprocess") + assert processor._worker_semaphore._value == initial_capacity + + +@pytest.fixture +def vllm_modules(frontend_stubs): + install, _ = frontend_stubs + dummy = type("BackendType", (), {}) + install("vllm") + install( + "vllm.config", + CacheConfig=dummy, + LoadConfig=dummy, + ModelConfig=dummy, + VllmConfig=dummy, + ) + install( + "vllm.entrypoints.generate.base.protocol", + DeltaFunctionCall=dummy, + DeltaMessage=dummy, + DeltaToolCall=dummy, + ) + install( + "vllm.renderers.chat_utils", + make_tool_call_id=lambda: "call", + load_chat_template=lambda value: value, + ) + install("vllm.renderers.hf", resolve_chat_template=lambda *args, **kwargs: None) + install( + "vllm.entrypoints.openai.chat_completion.protocol", + ChatCompletionNamedFunction=dummy, + ChatCompletionNamedToolChoiceParam=dummy, + ChatCompletionRequest=dummy, + ) + install("vllm.reasoning", ReasoningParser=dummy, ReasoningParserManager=dummy) + install("vllm.renderers", ChatParams=dummy, merge_kwargs=lambda *args: {}) + install( + "vllm.sampling_params", + SamplingParams=SimpleNamespace, + RequestOutputKind=SimpleNamespace(DELTA=0), + ) + install("vllm.tokenizers", TokenizerLike=dummy) + install("vllm.tool_parsers", ToolParser=dummy, ToolParserManager=dummy) + install("vllm.tool_parsers.utils", get_json_schema_from_tools=lambda *args: None) + install("vllm.utils.async_utils", make_async=lambda fn, **kwargs: fn) + install("vllm.tasks", GENERATION_TASKS=("generate",)) + install( + "vllm.v1.engine", + EngineCoreOutput=dummy, + EngineCoreRequest=dummy, + FinishReason=type("FinishReason", (), {"STOP": 0, "LENGTH": 1, "ABORT": 2}), + ) + install("vllm.v1.engine.input_processor", InputProcessor=dummy) + install( + "vllm.v1.engine.output_processor", + OutputProcessor=dummy, + OutputProcessorOutput=dummy, + ) + install("vllm.v1.engine.parallel_sampling", ParentRequest=dummy) + install( + "vllm.exceptions", + VLLMClientError=type("VLLMClientError", (Exception,), {}), + VLLMNotFoundError=type("VLLMNotFoundError", (Exception,), {}), + VLLMUnprocessableEntityError=type( + "VLLMUnprocessableEntityError", (Exception,), {} + ), + ) + install("msgspec.structs", replace=lambda value, **kwargs: value) + install( + "dynamo.frontend.vllm_protocol", + DeltaFunctionCall=dummy, + DeltaMessage=dummy, + DeltaToolCall=dummy, + FunctionDefinition=dummy, + ) + install( + "dynamo.common.multimodal.mm_kwargs_transfer", + MmKwargsSender=dummy, + MmKwargsShmSender=dummy, + MmKwargsNixlSender=dummy, + ) + install( + "dynamo.common.multimodal.routing_utils", + build_mm_routing_info_from_features=lambda *args, **kwargs: { + "block_mm_infos": [[]] + }, + ) + importlib.import_module("dynamo.llm").HttpError = importlib.import_module( + "dynamo.llm.exceptions" + ).HttpError + prepost = importlib.import_module("dynamo.frontend.prepost") + processor = importlib.import_module("dynamo.frontend.vllm_processor") + return processor, prepost + + +@pytest.mark.parametrize( + "pretokenized,fail_render", [(False, False), (True, False), (False, True)] +) +def test_vllm_template_tokenizer_preserves_tokens_and_closes_on_error( + vllm_modules, monkeypatch, pretokenized, fail_render +): + _, prepost = vllm_modules + context = RecordingContext() + request = SimpleNamespace( + tool_choice="auto", + structured_outputs=None, + add_special_tokens=True, + extract_structured_outputs=lambda: None, + ) + monkeypatch.setattr( + prepost, "_validate_chat_completion_request", lambda value: request + ) + monkeypatch.setattr(prepost, "_build_assistant_guided_decoding", lambda value: None) + monkeypatch.setattr(prepost, "_has_explicit_output_constraint", lambda value: False) + monkeypatch.setattr( + prepost, + "_prepare_request", + lambda *args, **kwargs: (request, None, {}, [], None), + ) + monkeypatch.setattr( + prepost, "build_tool_call_guided_decoding", lambda *args, **kwargs: None + ) + + class Renderer: + async def render_messages_async(self, messages, params): + if fail_render: + raise ValueError("render failed") + return [], {"prompt_token_ids": [1, 2]} if pretokenized else { + "prompt": "hello" + } + + async def tokenize(prompt, **kwargs): + assert not pretokenized + assert context.events[-1] == ("start", "tokenize") + return SimpleNamespace(input_ids=[1, 2]) + + monkeypatch.setattr(prepost, "_get_async_tokenizer", lambda tokenizer: tokenize) + coro = prepost.preprocess_chat_request( + chat_request(), + tokenizer=Tokenizer(), + renderer=Renderer(), + tool_parser_class=None, + context=context, + ) + if fail_render: + with pytest.raises(ValueError, match="render failed"): + asyncio.run(coro) + else: + assert asyncio.run(coro).prompt_token_ids == [1, 2] + from dynamo.frontend import ttft + + label = "template_tokenize" if pretokenized else "template_render" + assert context.intervals[0][0] == ttft.stage_registry()[label] + assert context.events == ( + [] + if fail_render + else ( + ([] if pretokenized else [("start", "tokenize"), ("end", "tokenize")]) + + [("start", "structural_tag_build"), ("end", "structural_tag_build")] + ) + ) + assert context.quality == ([("coarse", "opaque_template")] if pretokenized else []) + + +@pytest.mark.parametrize("has_media", [False, True]) +@pytest.mark.parametrize("enabled", [False, True]) +def test_vllm_generator_forwards_timeline_and_times_input_preparation( + vllm_modules, monkeypatch, has_media, enabled +): + module, _ = vllm_modules + context = RecordingContext() + context.ttft_enabled = enabled + + class RequestForSampling(SimpleNamespace): + model_fields = frozenset() + + request_for_sampling = RequestForSampling( + max_completion_tokens=None, + max_tokens=1, + logprobs=False, + top_logprobs=None, + cache_salt=None, + mm_processor_kwargs=None, + ) + + async def preprocess(request, **kwargs): + if enabled: + assert kwargs["context"].start_ttft_stage == context.start_ttft_stage + assert context.events[-1] == ("start", "preprocess") + else: + assert kwargs["context"] is None + assert context.events == [] + return SimpleNamespace( + request_for_sampling=request_for_sampling, + tool_parser=None, + chat_template_kwargs={}, + engine_prompt={}, + prompt_token_ids=[1], + guided_decoding=None, + ) + + monkeypatch.setattr(module, "preprocess_chat_request", preprocess) + monkeypatch.setattr( + module, + "extract_mm_urls", + lambda messages: ({"image_url": ["image"]} if has_media else None, None), + ) + expected_stage = "multimodal_prepare" if has_media else "preprocess" + + class ReachedInputPreparation(Exception): + pass + + async def build_inputs(*args, **kwargs): + if enabled: + assert context.events[-1] == ("start", expected_stage) + else: + assert context.events == [] + raise ReachedInputPreparation() + + monkeypatch.setattr(module, "_build_engine_inputs", build_inputs) + processor = module.VllmProcessor( + tokenizer=Tokenizer(), + input_processor=SimpleNamespace( + renderer=None, model_config=None, generation_config_fields={} + ), + output_processor=None, + tool_parser_class=None, + reasoning_parser_class=None, + routed_engine=None, + ) + + async def collect(): + return [ + item async for item in processor.generator(chat_request(), context=context) + ] + + with pytest.raises(ReachedInputPreparation): + asyncio.run(collect()) + assert context.events == ( + [ + ("start", "preprocess"), + ("end", "preprocess"), + ("start", expected_stage), + ("end", expected_stage), + ] + if enabled + else [] + ) + + +@pytest.mark.parametrize("fail_transfer", [False, True]) +def test_vllm_mm_routing_and_transfer_have_separate_intervals( + vllm_modules, monkeypatch, fail_transfer +): + module, _ = vllm_modules + context = RecordingContext() + + def build_metadata(*args, **kwargs): + assert context.events[-1] == ("start", "mm_routing_build") + return {"block_mm_infos": [[]]} + + monkeypatch.setattr(module, "build_mm_routing_info_from_features", build_metadata) + feature = SimpleNamespace( + modality="image", + mm_hash="hash", + mm_position=SimpleNamespace(offset=1, length=2), + ) + preprocessed = SimpleNamespace(mm_features=[feature], prompt_token_ids=[1, 2]) + + class Sender: + async def prepare(self, *args, **kwargs): + assert context.events[-1] == ("start", "multimodal_prepare") + if fail_transfer: + raise ValueError("transfer failed") + return {"transport": "shm"}, ["cleanup"] + + processor = module.VllmProcessor( + tokenizer=Tokenizer(), + input_processor=None, + output_processor=None, + tool_parser_class=None, + reasoning_parser_class=None, + routed_engine=None, + ) + processor.nixl_mm_enabled = True + processor._sender = Sender() + request = {} + routing, cleanup, transferred = asyncio.run( + processor._prepare_mm_routing( + preprocessed, + request, + context=context, + ) + ) + assert routing == {"block_mm_infos": [[]]} + assert transferred is not fail_transfer + assert cleanup == ([] if fail_transfer else ["cleanup"]) + assert request["extra_args"]["expanded_token_ids"] == [1, 2] + assert context.events == [ + ("start", "mm_routing_build"), + ("end", "mm_routing_build"), + ("start", "multimodal_prepare"), + ("end", "multimodal_prepare"), + ] + + +def test_vllm_text_and_uuid_only_paths_skip_mm_stages(vllm_modules): + module, _ = vllm_modules + processor = module.VllmProcessor( + tokenizer=Tokenizer(), + input_processor=None, + output_processor=None, + tool_parser_class=None, + reasoning_parser_class=None, + routed_engine=None, + ) + context = RecordingContext() + for request in ({}, {"multi_modal_uuids": {"image": ["cached"]}}): + assert asyncio.run( + processor._prepare_mm_routing( + SimpleNamespace(mm_features=[]), + request, + context=context, + ) + ) == (None, [], False) + assert context.events == [] + + +@pytest.mark.parametrize("pool", [False, True]) +def test_disabled_context_skips_native_calls_and_pool_clocks( + sglang_modules, monkeypatch, pool +): + module, _ = sglang_modules + + class DisabledContext: + ttft_enabled = False + + def start_ttft_stage(self, *args): + pytest.fail("OFF must not call PyO3 stage entry") + + def record_ttft_stage_ago(self, *args): + pytest.fail("OFF must not import pool timing") + + def unexpected_clock(): + pytest.fail("OFF must not read the pool timing clock") + + from dynamo.frontend import ttft + + monkeypatch.setattr(ttft.time, "monotonic_ns", unexpected_clock) + monkeypatch.setattr(module, "_w_tokenizer", Tokenizer()) + + class Pool: + def submit(self, fn, *args): + assert len(args) == 3 + result = fn(*args) + assert not hasattr(result, "timing_batch") + assert b"timing_batch" not in pickle.dumps(result) + future = Future() + future.set_result(result) + return future + + processor = make_sglang_processor(module, preprocess_pool=Pool() if pool else None) + + async def collect(): + return [ + item + async for item in processor.generator( + chat_request(), context=DisabledContext() + ) + ] + + assert asyncio.run(collect()) == [{"ok": True}] + + +@pytest.mark.parametrize( + "change,reason", + [ + ({"version": 2}, "invalid_version"), + ({"version": True}, "invalid_version"), + ({"clock_domain": "foreign-clock"}, "clock_mismatch"), + ({"truncated": True}, "interval_limit"), + ({"invalid": True}, "invalid_batch"), + ({"intervals_ns": None}, "invalid_batch"), + ({"coarse_reasons": ("unknown",)}, "invalid_batch"), + ({"coarse_reasons": ([],)}, "invalid_batch"), + ], +) +def test_worker_batch_rejects_invalid_metadata( + frontend_stubs, monkeypatch, change, reason +): + from dataclasses import replace + + from dynamo.frontend import ttft + + context = RecordingContext() + batch = ttft.TimingBatch(1, ttft.clock_domain(), ()) + monkeypatch.setattr(ttft.time, "monotonic_ns", lambda: 100) + ttft.import_worker_batch(context, replace(batch, **change), 10) + assert context.intervals == [] + assert context.quality == [("degraded", reason)] + + +@pytest.mark.parametrize("field", ["intervals_ns", "coarse_reasons"]) +def test_worker_batch_rejects_tuple_subclasses_before_iteration( + frontend_stubs, monkeypatch, field +): + from dataclasses import replace + + from dynamo.frontend import ttft + + calls = [] + + class LyingTuple(tuple): + def __len__(self): + calls.append("len") + return 0 + + def __iter__(self): + calls.append("iter") + raise AssertionError("malformed timing payload must not be iterated") + + context = RecordingContext() + batch = ttft.TimingBatch(1, ttft.clock_domain(), ()) + payload = LyingTuple(range(ttft.MAX_TIMING_INTERVALS + 1)) + monkeypatch.setattr(ttft.time, "monotonic_ns", lambda: 100) + ttft.import_worker_batch(context, replace(batch, **{field: payload}), 10) + assert calls == [] + assert context.intervals == [] + assert context.quality == [("degraded", "invalid_batch")] + + +@pytest.mark.parametrize("kind", ["batch", "interval"]) +def test_worker_batch_rejects_dataclass_subclasses_before_field_access( + frontend_stubs, monkeypatch, kind +): + from dynamo.frontend import ttft + + calls = [] + + class BatchSubclass(ttft.TimingBatch): + def __getattribute__(self, name): + calls.append(name) + raise AssertionError("malformed timing batch must not be inspected") + + class IntervalSubclass(ttft.TimingInterval): + def __getattribute__(self, name): + calls.append(name) + raise AssertionError("malformed timing interval must not be inspected") + + batch = ( + BatchSubclass(1, ttft.clock_domain(), ()) + if kind == "batch" + else ttft.TimingBatch(1, ttft.clock_domain(), (IntervalSubclass(103, 20, 30),)) + ) + context = RecordingContext() + monkeypatch.setattr(ttft.time, "monotonic_ns", lambda: 100) + ttft.import_worker_batch(context, batch, 10) + assert calls == [] + assert context.intervals == [] + assert context.quality == [("degraded", "invalid_batch")] + + +@pytest.mark.parametrize( + "stage,start,end,reason", + [ + (-1, 20, 30, "invalid_stage"), + (True, 20, 30, "invalid_stage"), + (103, 30, 20, "invalid_interval"), + (103, 9, 20, "invalid_interval"), + (103, 20, 101, "invalid_interval"), + (103, -1, 30, "timestamp_overflow"), + (103, 20, 1 << 65, "timestamp_overflow"), + (103, 20.5, 30, "timestamp_overflow"), + ], +) +def test_worker_batch_rejects_invalid_intervals( + frontend_stubs, monkeypatch, stage, start, end, reason +): + from dynamo.frontend import ttft + + context = RecordingContext() + batch = ttft.TimingBatch( + 1, ttft.clock_domain(), (ttft.TimingInterval(stage, start, end),) + ) + monkeypatch.setattr(ttft.time, "monotonic_ns", lambda: 100) + ttft.import_worker_batch(context, batch, 10) + assert context.intervals == [] + assert context.quality == [("degraded", reason)] + + +def test_worker_batch_bounds_repeats_and_unsupported_clock(frontend_stubs, monkeypatch): + from dataclasses import replace + + from dynamo.frontend import ttft + + context = RecordingContext() + interval = ttft.TimingInterval(ttft.stage_registry()["tokenize"], 20, 30) + batch = ttft.TimingBatch(1, ttft.clock_domain(), (interval, interval)) + clock_reads = [] + + def now(): + clock_reads.append(True) + return 100 + + monkeypatch.setattr(ttft.time, "monotonic_ns", now) + ttft.import_worker_batch(context, batch, 10) + assert len(clock_reads) == 1 + assert context.intervals == [(interval.stage_id, 80, 70)] * 2 + ttft.import_worker_batch(context, replace(batch, intervals_ns=(interval,) * 65), 10) + assert context.quality[-1] == ("degraded", "interval_limit") + ttft.import_worker_batch(context, replace(batch, clock_domain="unsupported"), 10) + assert context.quality[-1] == ("coarse", "unsupported_clock") + assert len(context.intervals) == 2 + + +def test_worker_recorder_is_bounded_before_clock_reads(frontend_stubs, monkeypatch): + from contextlib import ExitStack + + from dynamo.frontend import ttft + + clock_reads = [] + monkeypatch.setattr( + ttft.time, "monotonic_ns", lambda: clock_reads.append(1) or len(clock_reads) + ) + worker = ttft.WorkerTiming() + with ExitStack() as stack: + for _ in range(70): + stack.enter_context(worker.start_ttft_stage("template_render")) + assert len(worker.batch().intervals_ns) == 64 + assert worker.batch().truncated is True + assert len(clock_reads) == 128 + + +def test_worker_invalid_stage_check_survives_python_optimized(frontend_stubs): + import subprocess + import sys + + from dynamo.frontend import ttft + + code = """ +import importlib.util +import sys +import types +path = sys.argv[1] +spec = importlib.util.spec_from_file_location('timing_test_module', path) +module = importlib.util.module_from_spec(spec) +sys.modules[spec.name] = module +spec.loader.exec_module(module) +module.stage_registry = lambda: {'template_render': 19} +try: + with module.WorkerTiming().start_ttft_stage('unknown'): + pass +except ValueError: + pass +else: + raise RuntimeError('stage validation disabled by -O') +""" + subprocess.run([sys.executable, "-O", "-c", code, ttft.__file__], check=True) + + +def _same_host_pool_batch(registry): + """Actual spawned worker; only the unavailable native registry is stubbed.""" + import sys + import types + + from dynamo.frontend import ttft + + sys.modules["dynamo._core"] = types.SimpleNamespace( + ttft_stage_registry=lambda: [ + (stage_id, name) for name, stage_id in registry.items() + ] + ) + ttft.stage_registry.cache_clear() + timing = ttft.WorkerTiming() + with timing.start_ttft_stage("template_render"): + pass + with timing.start_ttft_stage("tokenize"): + pass + return timing.batch() + + +def test_actual_same_host_process_pool_batch(frontend_stubs): + import multiprocessing + import time + from concurrent.futures import ProcessPoolExecutor + + from dynamo.frontend import ttft + + with ProcessPoolExecutor( + max_workers=1, mp_context=multiprocessing.get_context("spawn") + ) as pool: + submitted = time.monotonic_ns() + batch = pool.submit(_same_host_pool_batch, ttft.stage_registry()).result( + timeout=30 + ) + context = RecordingContext() + ttft.import_worker_batch(context, batch, submitted) + assert context.quality == [] + assert [interval[0] for interval in context.intervals] == [ + ttft.stage_registry()["template_render"], + ttft.stage_registry()["tokenize"], + ] + assert all(start >= end >= 0 for _, start, end in context.intervals) diff --git a/components/src/dynamo/frontend/ttft.py b/components/src/dynamo/frontend/ttft.py new file mode 100644 index 000000000000..b0fa989bfcf7 --- /dev/null +++ b/components/src/dynamo/frontend/ttft.py @@ -0,0 +1,233 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 + +"""Bounded same-host timing transport for the HTTP request's TTFT timeline.""" + +import sys +import time +from contextlib import AbstractContextManager, contextmanager, nullcontext +from dataclasses import dataclass +from functools import lru_cache +from typing import Any + +TIMING_BATCH_VERSION = 1 +MAX_TIMING_INTERVALS = 64 +_MAX_NS = (1 << 64) - 1 + + +@lru_cache(maxsize=1) +def stage_registry() -> dict[str, int]: + """Read the canonical Rust registry; Python never maintains a second list.""" + from dynamo._core import ttft_stage_registry + + return {name: stage_id for stage_id, name in ttft_stage_registry()} + + +def clock_domain() -> str: + """Only local ProcessPoolExecutor workers share this supported clock domain.""" + if sys.platform not in {"linux", "darwin"}: + return "unsupported" + return sys.platform + ":" + time.get_clock_info("monotonic").implementation + + +@dataclass(frozen=True) +class TimingInterval: + stage_id: int + start_ns: int + end_ns: int + + +@dataclass(frozen=True) +class TimingBatch: + version: int + clock_domain: str + intervals_ns: tuple[TimingInterval, ...] + truncated: bool = False + invalid: bool = False + coarse_reasons: tuple[str, ...] = () + + +class WorkerTiming: + """Picklable fixed-stage intervals; allocated only for enabled requests.""" + + ttft_enabled = True + + def __init__(self) -> None: + self.intervals_ns: list[TimingInterval] = [] + self.truncated = False + self.started = 0 + self.invalid = False + self.coarse_reasons: set[str] = set() + self.domain = clock_domain() + + @contextmanager + def start_ttft_stage(self, stage: str): + stage_id = stage_registry().get(stage) + if stage_id is None: + raise ValueError(f"Unsupported TTFT stage: {stage}") + if self.domain == "unsupported": + self.coarse_reasons.add("unsupported_clock") + yield + return + if self.started >= MAX_TIMING_INTERVALS: + self.truncated = True + yield + return + self.started += 1 + start_ns = time.monotonic_ns() + try: + yield + finally: + end_ns = time.monotonic_ns() + if len(self.intervals_ns) < MAX_TIMING_INTERVALS: + self.intervals_ns.append(TimingInterval(stage_id, start_ns, end_ns)) + else: + self.truncated = True + + def mark_ttft_quality(self, quality: str, reason: str) -> None: + if quality == "coarse" and reason in { + "opaque_template", + "unsupported_clock", + "missing_coverage", + }: + self.coarse_reasons.add(reason) + else: + self.invalid = True + + def batch(self) -> TimingBatch: + return TimingBatch( + TIMING_BATCH_VERSION, + self.domain, + tuple(self.intervals_ns), + self.truncated, + self.invalid, + tuple(sorted(self.coarse_reasons)), + ) + + +class _TtftContext: + """Cache native methods once per enabled request, outside the hot path.""" + + ttft_enabled = True + + def __init__(self, context: Any) -> None: + self.start_ttft_stage = context.start_ttft_stage + self.record_ttft_batch_ago = context.record_ttft_batch_ago + self.mark_ttft_quality = context.mark_ttft_quality + + +def ttft_context(context: Any | None) -> Any | None: + if isinstance(context, _TtftContext): + return context + if not getattr(context, "ttft_enabled", False): + return None + return _TtftContext(context) + + +def ttft_stage(context: Any | None, stage: str) -> AbstractContextManager: + if not getattr(context, "ttft_enabled", False): + return nullcontext() + return context.start_ttft_stage(stage) + + +def ttft_coarse(context: Any | None, reason: str) -> None: + if getattr(context, "ttft_enabled", False): + context.mark_ttft_quality("coarse", reason) + + +@contextmanager +def ttft_renderer_stage(context: Any | None): + """Classify one renderer call after learning whether it also tokenized. + + This never executes the renderer/tokenizer twice or mutates backend objects. + The result flag is set by the caller only when token IDs were returned. + """ + result = [False] + if not getattr(context, "ttft_enabled", False): + yield result + return + start_ns = time.monotonic_ns() + try: + yield result + finally: + end_ns = time.monotonic_ns() + stage = "template_tokenize" if result[0] else "template_render" + context.record_ttft_batch_ago( + [(stage_registry()[stage], end_ns - start_ns, 0)], + ("opaque_template",) if result[0] else (), + ) + + +def import_worker_batch(context: Any, batch: Any, submitted_ns: int) -> None: + """Validate local worker intervals and cross PyO3 once using integer ages. + + One receive clock read anchors every interval. Rust takes one corresponding + Instant; the FFI scheduling delay remains a small, nonzero alignment error. + Untrusted timing never changes the inference result. + """ + now_ns = time.monotonic_ns() + + def degraded(reason: str) -> None: + context.mark_ttft_quality("degraded", reason) + + if type(batch) is not TimingBatch: + degraded("invalid_batch") + return + if type(batch.version) is not int or batch.version != TIMING_BATCH_VERSION: + degraded("invalid_version") + return + if type(batch.clock_domain) is not str: + degraded("invalid_batch") + return + if batch.clock_domain == "unsupported" or clock_domain() == "unsupported": + context.mark_ttft_quality("coarse", "unsupported_clock") + return + if batch.clock_domain != clock_domain(): + degraded("clock_mismatch") + return + # Exact types make the size checks authoritative: tuple/dataclass subclasses + # can override __len__, __iter__, or attribute access before validation. + if ( + type(batch.truncated) is not bool + or type(batch.invalid) is not bool + or type(batch.intervals_ns) is not tuple + or type(batch.coarse_reasons) is not tuple + or len(batch.coarse_reasons) > 3 + ): + degraded("invalid_batch") + return + if batch.truncated or len(batch.intervals_ns) > MAX_TIMING_INTERVALS: + degraded("interval_limit") + return + if batch.invalid: + degraded("invalid_batch") + return + allowed = set(stage_registry().values()) + ages = [] + for interval in batch.intervals_ns: + if type(interval) is not TimingInterval: + degraded("invalid_batch") + return + if type(interval.stage_id) is not int or interval.stage_id not in allowed: + degraded("invalid_stage") + return + if any( + type(value) is not int or not 0 <= value <= _MAX_NS + for value in (interval.start_ns, interval.end_ns) + ): + degraded("timestamp_overflow") + return + if not submitted_ns <= interval.start_ns <= interval.end_ns <= now_ns: + degraded("invalid_interval") + return + ages.append( + (interval.stage_id, now_ns - interval.start_ns, now_ns - interval.end_ns) + ) + if any( + type(reason) is not str + or reason not in {"opaque_template", "unsupported_clock", "missing_coverage"} + for reason in batch.coarse_reasons + ): + degraded("invalid_batch") + return + context.record_ttft_batch_ago(ages, batch.coarse_reasons) diff --git a/components/src/dynamo/frontend/vllm_processor.py b/components/src/dynamo/frontend/vllm_processor.py index e454bfc83602..33c17a5ad089 100644 --- a/components/src/dynamo/frontend/vllm_processor.py +++ b/components/src/dynamo/frontend/vllm_processor.py @@ -50,6 +50,7 @@ runtime_structural_tag_options, ) from .thinking import runtime_default_thinking_mode +from .ttft import ttft_context, ttft_stage from .usage import response_usage, update_usage_metadata from .utils import ( PromptLogprobsAccumulator, @@ -771,6 +772,7 @@ async def _prepare_mm_routing( vllm_preproc: EngineCoreRequest, dynamo_preproc: dict[str, Any], mm_processor_kwargs: dict[str, Any] | None = None, + context: Any | None = None, ) -> tuple[dict | None, list, bool]: """Extract MM routing info and prepare mm_kwargs transfer. @@ -797,70 +799,73 @@ async def _prepare_mm_routing( return None, cleanup_items, nixl_transferred if vllm_preproc.mm_features: - if mm_processor_kwargs: - # vLLM rehashes supplied UUIDs when processor kwargs are - # present. Fall back to text-prefix routing so the router and - # worker cannot publish different cache keys. - logger.debug( - "[mm-routing] Exact MM routing disabled because " - "mm_processor_kwargs is non-empty" - ) - else: - mm_routing_info = build_mm_routing_info_from_features( - vllm_preproc.mm_features, - prompt_token_ids=list(vllm_preproc.prompt_token_ids), - ) - ( - mm_hashes_list, - mm_placeholders_list, - mm_hashes_by_modality, - mm_placeholders_by_modality, - ) = _group_mm_feature_metadata(vllm_preproc.mm_features) - if "extra_args" not in dynamo_preproc: - dynamo_preproc["extra_args"] = {} - # Forward hashes only when this frontend built the matching exact - # routing sequence. Their presence is the worker's request-time - # readiness signal; transfer-only metadata is deliberately separate. - if mm_routing_info is not None: - dynamo_preproc["extra_args"]["mm_hashes"] = mm_hashes_list - dynamo_preproc["extra_args"][ - "mm_hashes_by_modality" - ] = mm_hashes_by_modality - dynamo_preproc["extra_args"]["mm_placeholders"] = mm_placeholders_list - dynamo_preproc["extra_args"][ - "mm_placeholders_by_modality" - ] = mm_placeholders_by_modality - # Forward the expanded prompt_token_ids (with image placeholders) - # so the backend can use them in the pre-rendered MultiModalInput. - dynamo_preproc["extra_args"]["expanded_token_ids"] = list( - vllm_preproc.prompt_token_ids - ) - - n_blocks = len(mm_routing_info["block_mm_infos"]) if mm_routing_info else 0 - n_mm_blocks = sum( - 1 for b in (mm_routing_info or {}).get("block_mm_infos", []) if b - ) - logger.debug( - "[mm-routing] Built mm_routing_info: %d mm_features, " - "%d hashes, %d total blocks, %d blocks with MM content, " - "block_size=%d", - len(vllm_preproc.mm_features), - len(mm_hashes_list), - n_blocks, - n_mm_blocks, - self.block_size, - ) - if logger.isEnabledFor(logging.DEBUG): - for i, f in enumerate(vllm_preproc.mm_features): + with ttft_stage(context, "mm_routing_build"): + if mm_processor_kwargs: + # vLLM rehashes supplied UUIDs when processor kwargs are + # present. Fall back to text-prefix routing so the router and + # worker cannot publish different cache keys. logger.debug( - "[mm-routing] feature[%d]: modality=%s, hash=%s..., " - "offset=%d, length=%d", - i, - _mm_feature_modality(f), - f.mm_hash[:16] if f.mm_hash else "None", - f.mm_position.offset, - f.mm_position.length, + "[mm-routing] Exact MM routing disabled because " + "mm_processor_kwargs is non-empty" + ) + else: + mm_routing_info = build_mm_routing_info_from_features( + vllm_preproc.mm_features, + prompt_token_ids=list(vllm_preproc.prompt_token_ids), ) + ( + mm_hashes_list, + mm_placeholders_list, + mm_hashes_by_modality, + mm_placeholders_by_modality, + ) = _group_mm_feature_metadata(vllm_preproc.mm_features) + if "extra_args" not in dynamo_preproc: + dynamo_preproc["extra_args"] = {} + # Forward hashes only when this frontend built the matching exact + # routing sequence. Their presence is the worker's request-time + # readiness signal; transfer-only metadata is deliberately separate. + if mm_routing_info is not None: + dynamo_preproc["extra_args"]["mm_hashes"] = mm_hashes_list + dynamo_preproc["extra_args"][ + "mm_hashes_by_modality" + ] = mm_hashes_by_modality + dynamo_preproc["extra_args"]["mm_placeholders"] = mm_placeholders_list + dynamo_preproc["extra_args"][ + "mm_placeholders_by_modality" + ] = mm_placeholders_by_modality + # Forward the expanded prompt_token_ids (with image placeholders) + # so the backend can use them in the pre-rendered MultiModalInput. + dynamo_preproc["extra_args"]["expanded_token_ids"] = list( + vllm_preproc.prompt_token_ids + ) + + n_blocks = ( + len(mm_routing_info["block_mm_infos"]) if mm_routing_info else 0 + ) + n_mm_blocks = sum( + 1 for b in (mm_routing_info or {}).get("block_mm_infos", []) if b + ) + logger.debug( + "[mm-routing] Built mm_routing_info: %d mm_features, " + "%d hashes, %d total blocks, %d blocks with MM content, " + "block_size=%d", + len(vllm_preproc.mm_features), + len(mm_hashes_list), + n_blocks, + n_mm_blocks, + self.block_size, + ) + if logger.isEnabledFor(logging.DEBUG): + for i, f in enumerate(vllm_preproc.mm_features): + logger.debug( + "[mm-routing] feature[%d]: modality=%s, hash=%s..., " + "offset=%d, length=%d", + i, + _mm_feature_modality(f), + f.mm_hash[:16] if f.mm_hash else "None", + f.mm_position.offset, + f.mm_position.length, + ) # Transfer pre-processed mm_kwargs to the backend so it can skip # the HF processor. Strategy: @@ -892,10 +897,11 @@ async def _prepare_mm_routing( ) # NVTX annotation is owned by MmKwargsSender.prepare via # the subclass's _nvtx_label/_nvtx_color class attrs. - extra_update, cleanup_items = await self._sender.prepare( - vllm_preproc.mm_features, - modality=transfer_modality, - ) + with ttft_stage(context, "multimodal_prepare"): + extra_update, cleanup_items = await self._sender.prepare( + vllm_preproc.mm_features, + modality=transfer_modality, + ) if extra_update is not None: dynamo_preproc["extra_args"].update(extra_update) nixl_transferred = True @@ -940,6 +946,7 @@ async def _generator_inner( self, request: dict[str, Any], context: Any | None = None ) -> AsyncGenerator[dict[str, Any], None]: request_id = random_uuid() + timing_context = ttft_context(context) _reject_unsupported_chat_logprobs( request.get("logprobs"), @@ -955,7 +962,10 @@ async def _generator_inner( # Images are fetched by vLLM's renderer via DynamoMediaConnector, # which wraps our ImageLoader (LRU cache + in-flight dedup). # No data URI encoding needed. - with _nvtx.annotate("mm_frontend:preprocess_chat", color="yellow"): + with ( + _nvtx.annotate("mm_frontend:preprocess_chat", color="yellow"), + ttft_stage(timing_context, "preprocess"), + ): pre = await preprocess_chat_request( request, tokenizer=self.tokenizer, @@ -971,6 +981,7 @@ async def _generator_inner( structural_tag_scope=self.structural_tag_scope, structural_tag_schema=self.structural_tag_schema, structural_tag_excludes_reasoning=self.structural_tag_excludes_reasoning, + context=timing_context, ) request_for_sampling = pre.request_for_sampling @@ -1032,7 +1043,13 @@ async def _generator_inner( # legacy nvext passthrough. thinking_token_budget = resolve_thinking_token_budget(request) - with _nvtx.annotate("mm_frontend:process_inputs", color="orange"): + with ( + _nvtx.annotate("mm_frontend:process_inputs", color="orange"), + ttft_stage( + timing_context, + "multimodal_prepare" if mm_data or mm_uuids else "preprocess", + ), + ): # render_messages_async returns a raw prompt. Convert it to a typed # EngineInput before process_inputs. User UUID requests deliberately # stay token-only here: the selected worker must populate and query @@ -1125,6 +1142,7 @@ async def _generator_inner( vllm_preproc, dynamo_preproc, mm_processor_kwargs=request_for_sampling.mm_processor_kwargs, + context=timing_context, ) # Forward multimodal URLs so the backend handler can load the media. diff --git a/docs/fern/pages/reference/components/frontend-configuration.mdx b/docs/fern/pages/reference/components/frontend-configuration.mdx index e63e75e9cd0e..4936da06f96c 100644 --- a/docs/fern/pages/reference/components/frontend-configuration.mdx +++ b/docs/fern/pages/reference/components/frontend-configuration.mdx @@ -622,6 +622,38 @@ See the [KServe gRPC Frontend](../../developer-guide/knowledge-base/modular-comp Environment variable: `DYN_DUMP_CONFIG_TO` +### TTFT Detail + +Set `--ttft-detail` or `DYN_FRONTEND_TTFT_DETAIL` before startup. The CLI value takes precedence. + +| Value | Detail histogram | Per-request DEBUG event | Collection | +| --- | --- | --- | --- | +| `off` | Disabled | Disabled | None | +| `metrics` (default) | Enabled | Disabled | One request-local timeline | +| `logs` | Disabled | Enabled when `DYN_LOG` permits `dynamo_frontend::ttft` at DEBUG | Only when that target is enabled | +| `both` | Enabled | Enabled when the target is enabled | One timeline shared by both outputs | + +Existing total TTFT, operation histograms, and stage gauges retain their original behavior in +every mode. Detail metrics collect by default; per-request logs remain disabled even if the +global log level is DEBUG. The detail view partitions each request's TTFT into mutually exclusive +contributions. To enable logs alongside metrics: + +```bash +export DYN_FRONTEND_TTFT_DETAIL=both +export DYN_LOG='info,dynamo_frontend::ttft=debug' +``` + +Invalid modes fail at startup. The mode is fixed for the lifetime of the frontend; requests are +not sampled. Startup logs report the selected mode and whether the detail DEBUG target is enabled. +Only `metrics` and `both` register the detail histogram and diagnostic metric families. In `off`, +the frontend skips detail timelines, stage clock reads, histogram +observations, Python timing calls, and process-pool timing results. Small fixed enablement checks +remain. The histogram bucket variables below configure boundaries only; they do not enable +collection. + +See [TTFT stage durations](../observability/metrics-catalog.mdx#ttft-stage-durations) for boundaries +and [Per-Request First-Token Log](../observability/logging.mdx#per-request-first-token-log) for fields. + ### Histogram buckets Most frontend latency and size histograms use log-spaced buckets, rounded to two significant figures, always starting with a `0` edge. Each histogram is tuned by three environment variables that share a prefix: `_MIN` and `_MAX` bound the range, and `_COUNT` is the total number of bucket edges **including** that leading `0`, so `COUNT - 1` edges are spread across the range. Every edge, including the top one, is rounded to two significant figures, so the highest exported edge is `MAX` rounded rather than `MAX` itself. These variables have no CLI equivalent, and the frontend reads them once while building its metrics, so changing one requires a restart. @@ -632,6 +664,7 @@ Most frontend latency and size histograms use log-spaced buckets, rounded to two | `dynamo_frontend_input_sequence_tokens` | `DYN_METRICS_INPUT_SEQUENCE` | `50.0` | `128000.0` | `12` | `130000` | | `dynamo_frontend_output_sequence_tokens` | `DYN_METRICS_OUTPUT_SEQUENCE` | `50.0` | `32000.0` | `10` | `32000` | | `dynamo_frontend_time_to_first_token_seconds` | `DYN_METRICS_TTFT` | `0.001` | `480.0` | `18` | `480` | +| `dynamo_frontend_ttft_stage_seconds` | `DYN_METRICS_TTFT_STAGE` | `0.000001` | `480.0` | `26` | `480` | | `dynamo_frontend_inter_token_latency_seconds` | `DYN_METRICS_ITL` | `0.001` | `80.0` | `20` | `80` | | `dynamo_frontend_embedding_latency_seconds` | `DYN_METRICS_EMBEDDING_LATENCY` | `0.001` | `10.0` | `14` | `10` | @@ -646,6 +679,15 @@ Rounding can move the top edge either way, so pick a `MAX` that is already two s `dynamo_frontend_cached_tokens` shares the input sequence buckets, so `DYN_METRICS_INPUT_SEQUENCE_*` changes both histograms. +When detail metrics are enabled, `dynamo_frontend_ttft_stage_seconds` exposes only the legal +`stage`/`phase` pairs in its registry. Each pair has the same bucket boundaries. For `N` pairs and +`B` finite boundaries, the `_bucket`, `_sum`, and `_count` series total `N * (B + 3)` per model, +including the `+Inf` bucket. The current registry has 24 pairs, so the default 26 finite boundaries +produce 696 series per model. The coverage counters add at most 12 fixed global series, independent +of model count. See +[TTFT stage durations](../observability/metrics-catalog.mdx#ttft-stage-durations) for the stage +contract and additive mean queries. + Set `DYN_METRICS_ITL_BUCKETS` to an explicit, comma-separated list of ITL boundaries in seconds. The list must contain 1 to 512 finite, non-negative, strictly increasing values and be at most 16,384 bytes long. Boundaries are used as supplied, without logarithmic spacing or rounding. For example, to use explicit boundaries for an SGLang deployment: diff --git a/docs/fern/pages/reference/observability/logging.mdx b/docs/fern/pages/reference/observability/logging.mdx index ce5fdbcdac48..bccb5fc30f3e 100644 --- a/docs/fern/pages/reference/observability/logging.mdx +++ b/docs/fern/pages/reference/observability/logging.mdx @@ -63,6 +63,54 @@ For example, keep the default at `info` and enable trace output for the system-s export DYN_LOG='info,dynamo_runtime::system_status_server=trace' ``` +## Per-Request First-Token Log + +When enabled, the frontend emits one DEBUG event for each HTTP chat or text completion request when +it first observes a nonzero output token count. The target is `dynamo_frontend::ttft` and the message is +`frontend first token`. Requests that end, fail, or are canceled before that observation do not +emit the event. Later tokens do not emit additional TTFT events. + +The event contains the canonical HTTP context `request_id`, `model`, `ttft_ms`, and numeric stage +durations in milliseconds for every legal stage/phase pair. Field names use `_ms` for an +empty phase and `__ms` otherwise, such as `structural_tag_build_ms`, +`template_render_ms`, `tokenize_ms`, `dispatch_prepare_prefill_ms`, `dispatch_decode_ms`, and +`backend_overlap_prefill_decode_ms`. All stage/phase combinations are present, including zeros for +unused stages. In `both` mode these frozen values match the +[TTFT stage histogram](metrics-catalog.mdx#ttft-stage-durations), and their sum equals `ttft_ms`, +subject to floating-point rounding. + +The event also includes `quality` (`complete`, `coarse`, or `degraded`), `degraded_reason`, +`coarse_reason`, and `unexpected_overlap`. Reason fields contain fixed diagnostic values or an +empty value when absent. A degraded result places all time in `unclassified_ms`. The event does +not contain prompt text, tool schemas, or per-span payloads. + +Detail collection defaults to `metrics`, which emits no per-request event even at global DEBUG. +To enable events alongside metrics while keeping other logs at INFO, set both the detail mode and +log target before starting the frontend: + +```bash +export DYN_FRONTEND_TTFT_DETAIL=both +export DYN_LOG='info,dynamo_frontend::ttft=debug' +``` + +Use `logs` instead of `both` to emit events without detail histograms. With +`logs` or `both` selected, a global DEBUG or TRACE level also enables these events. To disable them while retaining other +DEBUG logs, set: + +```bash +export DYN_LOG='debug,dynamo_frontend::ttft=off' +``` + +With `logs` and a disabled target, no detail timeline is collected. With `metrics` or `both`, +metrics remain independent of the filter. With `off`, no detail metrics or events are emitted, +even at DEBUG. Existing total TTFT and other metrics remain enabled in every mode. + +Set `DYN_LOGGING_CONSOLE_FORMAT=jsonl` for machine-readable records; duration fields remain JSON +numbers. Readable and JSONL formats use the same filters. TOML `log_filters` entries are applied +after `DYN_LOG`, so an entry for the same target overrides the environment directive. The file +selected by `DYN_LOGGING_CONFIG_PATH` overrides matching entries in `/opt/dynamo/etc/logging.toml`. +More specific target filters take precedence over broader prefixes. + ## OTLP Export `OTEL_EXPORT_ENABLED=true` is the master switch for runtime trace and log export. Configure a diff --git a/docs/fern/pages/reference/observability/metric-labels.mdx b/docs/fern/pages/reference/observability/metric-labels.mdx index 699fefba7032..61b7467fdb57 100644 --- a/docs/fern/pages/reference/observability/metric-labels.mdx +++ b/docs/fern/pages/reference/observability/metric-labels.mdx @@ -66,13 +66,20 @@ Added by an individual metric family. Each label appears only on the metrics not `[Shared]` On `dynamo_frontend_stage_requests` — the frontend pipeline stage a request currently occupies. See [Stage values](#stage-values). - Allowed values: preprocess route dispatch + On `dynamo_frontend_ttft_stage_seconds`, identifies an exclusive TTFT contribution. Its values + reuse `preprocess`, `route`, and `dispatch` from the request gauge and add finer contributions; see [TTFT stage durations](metrics-catalog.mdx#ttft-stage-durations). + + Request gauge values: preprocess route dispatch `[Shared]` On `dynamo_frontend_stage_requests` — the serving phase. See [Phase values](#phase-values). The empty value is used when the stage does not distinguish phases (e.g. `preprocess`). - Allowed values: prefill decode aggregated "" (empty) + On `dynamo_frontend_ttft_stage_seconds`, uses the same phase values and adds `prefill_decode` for + `backend_overlap`. See [TTFT stage durations](metrics-catalog.mdx#ttft-stage-durations) for the + allowed stage/phase pairs. + + Request gauge values: prefill decode aggregated "" (empty) @@ -103,6 +110,16 @@ Added by an individual metric family. Each label appears only on the metrics not `[Shared]` On `dynamo_frontend_router_queue_backpressure_total` — the configured queue limit that rejected the request. + + On `dynamo_frontend_ttft_detail_degraded_total` and + `dynamo_frontend_ttft_detail_coarse_total`, identifies a fixed timing-coverage condition. Values + come from the timing registry; arbitrary error messages are never labels. These counters have + no model or request-ID label. See [TTFT stage durations](metrics-catalog.mdx#ttft-stage-durations). + + Degraded reasons: `interval_limit`, `invalid_interval`, `invalid_batch`, `invalid_stage`, + `invalid_version`, `clock_mismatch`, `timestamp_overflow`, `missing_timeline`. + + Coarse reasons: `opaque_template`, `unsupported_clock`, `missing_coverage`. diff --git a/docs/fern/pages/reference/observability/metrics-catalog.mdx b/docs/fern/pages/reference/observability/metrics-catalog.mdx index 9092c1fa9249..e117b92757a2 100644 --- a/docs/fern/pages/reference/observability/metrics-catalog.mdx +++ b/docs/fern/pages/reference/observability/metrics-catalog.mdx @@ -159,6 +159,31 @@ The ratio is defined only when the model has an active L1 cache and observed tok Time to first token in seconds. + + Exclusive wall-clock contributions to frontend Time To First Token (TTFT), in seconds. Labeled by + `model`, `stage`, and `phase`. Enabled by default. Every request in the enabled cohort that records + total TTFT records every legal stage/phase pair, including zeros for unused stages. See + [TTFT stage durations](#ttft-stage-durations). + + + + Requests whose first-token breakdown is entirely `unclassified` because reliable detail is + unavailable. Labeled by a fixed `reason`; not labeled by model or request ID. Observed once per + request at the first token in `metrics` and `both` modes. + + + + First-token requests with an opaque operation, unsupported worker clock, or missing finer coverage. Labeled by a + fixed `reason`; not labeled by model or request ID. Observed once per request in `metrics` and + `both` modes. See [coverage states](#ttft-stage-durations). + + + + First-token requests with overlapping independent frontend stages. Has no labels. The fixed + attribution order still preserves the total. Observed at most once per request in `metrics` and + `both` modes, regardless of how many overlaps occurred. + + The frontend also records these request and pipeline metrics: | Metric | Type | Labels | Description | Status | @@ -173,6 +198,191 @@ The frontend also records these request and pipeline metrics: | `dynamo_frontend_detokenize_total_us` | counter | — | Total detokenization time in microseconds. | Current | | `dynamo_frontend_detokenize_token_count` | counter | — | Tokens detokenized. | Current | +### TTFT stage durations + +`dynamo_frontend_ttft_stage_seconds` partitions the same interval as +`dynamo_frontend_time_to_first_token_seconds`: from the HTTP request metrics start to the first +observed nonzero output token count. The total and all contributions share that first-token +timestamp. Durations are clipped to that interval, concurrent work is counted once, and gaps are +assigned to `frontend_overhead`. The contributions sum to the request's total TTFT exactly in +integer durations, subject to floating-point rounding when exported. If timing data is invalid or +exceeds its bound, the whole interval is assigned to `unclassified` instead. + +| `stage` | `phase` | Measured interval | +|---------|---------|-------------------| +| `frontend_overhead` | `""` | Time outside instrumented stages, including request setup and gaps between stages | +| `preprocess` | `""` | Native or Python chat preprocessing, including process-pool dispatch and IPC when used, excluding separately attributed nested stages | +| `preprocess_queue` | `""` | Waiting for the Python preprocessing concurrency semaphore | +| `template_render` | `""` | Template rendering where the renderer exposes a separate call | +| `tokenize` | `""` | Tokenization where the tokenizer exposes a separate call | +| `template_tokenize` | `""` | Opaque third-party calls that combine rendering and tokenization; never recorded alongside separate timings for the same call | +| `structural_tag_build` | `""` | Building and serializing structural-tag or guided-decoding constraints | +| `multimodal_prepare` | `""` | Frontend multimodal input preparation, including media processing and shared-memory or NIXL sender preparation | +| `mm_routing_build` | `""` | Building multimodal routing information from prepared inputs | +| `route` | `prefill`, `decode`, `aggregated` | Worker selection, scheduling, and selection tracking for KV and built-in routing policies | +| `dispatch_prepare` | `prefill`, `decode`, `aggregated` | Work after KV worker selection and before backend dispatch; zero on paths without a separate preparation interval | +| `dispatch` | `prefill`, `decode`, `aggregated` | The existing dispatch boundary to the first backend response, excluding separately attributed preparation | +| `first_token_wait` | `prefill`, `decode`, `aggregated` | First backend response to its first nonempty token output; zero when the first response contains tokens | +| `backend_overlap` | `prefill_decode` | Concurrent prefill and decode backend waits, counted once | +| `first_token_postprocess` | `""` | First decode or aggregated backend token to the HTTP first-token observation, including detokenization, parser buffering, and delivery | +| `unclassified` | `""` | The entire TTFT when bounded collection cannot provide trustworthy attribution | + +Only these legal pairs are exported; the metric does not create a Cartesian product of all stages +and phases. The registry also defines parent stages, attribution priority, and Python availability. + +The existing metric contracts remain unchanged. They answer different questions from this request +view: + +| Existing view | Reuse in TTFT detail | Preserved contract | +| --- | --- | --- | +| `stage_requests{stage="route",phase=...}` | Shared selection lifecycle and canonical `route` stage name | The KV gauge still ends after selection/tracking. Preparation has its own detail interval. | +| `stage_requests{stage="dispatch",phase=...}` | Same dispatch entry and first-response event | The gauge follows the upstream `begin_dispatch` boundary after KV dispatch preparation. Detail records preparation separately before backend dispatch. | +| `stage_requests{stage="preprocess",phase=""}` | Shared lifecycle where boundaries match | Original gauge scopes and cleanup on errors or cancellation remain unchanged. | +| `template_seconds`, `tokenize_seconds` | Existing native timing pairs feed `template_render` and `tokenize` | Inclusive operation durations retain their boundaries and successful-operation sample populations. | +| `stage_duration_seconds{stage=...}` | Native chat `preprocess` reuses the same timing result | Existing stage values, buckets, and samples remain unchanged; no `model` or `phase` label is added. | +| `time_to_first_token_seconds{model=...}` | Same start, first-token observation, and request population | Existing total TTFT remains enabled in all modes. | + +The gauges count concurrent requests; they do not measure duration. Existing operation histograms +remain inclusive and can record multiple samples per HTTP request, including retries according to +their existing rules. The detail histogram removes overlap, clips at the first HTTP token, and +records zero for unused stages. Summing operation histograms would neither remove overlap nor +preserve the total-TTFT denominator. Existing dashboards need no migration. + +Python requests carry the optional timeline separately from the legacy request tracker. Enabling +detail does not create a tracker or add requests to existing router timing metrics. + +The empty `phase` means the stage does not distinguish serving phases. `aggregated` identifies a +single worker serving both prefill and decode. Each dispatch snapshots its phase; later tracker +changes cannot relabel it. `backend_overlap` applies when prefill and decode each have an active +`dispatch` or `first_token_wait`, after higher-priority frontend work is removed. + +The fixed attribution order, from highest to lowest priority, is: + +1. `first_token_postprocess`. +2. `dispatch_prepare`, then `route`, with decode before prefill before aggregated within each. +3. `structural_tag_build`, `template_render`, `tokenize`, then opaque `template_tokenize`. +4. `mm_routing_build`, `multimodal_prepare`, `preprocess_queue`, then residual `preprocess`. +5. `backend_overlap`. +6. `first_token_wait`, then `dispatch`, for decode, prefill, then aggregated. +7. `frontend_overhead` for uncovered time. + +This policy attributes observable frontend work ahead of simultaneous backend waits. It is not a +distributed critical-path calculation. Repeated intervals of the same stage form a union, and +sequential retry intervals remain in the request. Unexpected overlaps between independent frontend stages +use the same fixed priority and increment a diagnostic count. When an attempt is aborted or retried +before HTTP observes a token, its postprocessing interval closes so the replacement attempt keeps +its own route and backend contributions. Tokens held and discarded by migration do not freeze +HTTP TTFT. + +The metric is enabled on the frontend's existing `/metrics` endpoint by default with +`DYN_FRONTEND_TTFT_DETAIL=metrics`. Use `both` to add per-request logs. The `metrics` and `both` modes +collect regardless of the log filter. In `logs` mode, collection also requires the +`dynamo_frontend::ttft` DEBUG target to be enabled. With `off`, or `logs` with that target disabled, +requests allocate no detail timeline or histogram handles, read no additional stage clocks, and +skip Python stage calls and pool timing results. Fixed enablement checks remain; this is not a claim +of zero CPU overhead. The setting is resolved at startup; CLI +`--ttft-detail` takes precedence over the environment. See +[TTFT Detail](../components/frontend-configuration.mdx#ttft-detail). The SGLang and vLLM Python chat processors and native Rust +preprocessor provide preprocessing timings. Chat and text completions carry the HTTP timing context +through the in-process routing host, including KV, round-robin, random, direct, and other built-in +policies. These paths record worker selection, +backend waits, and first-token postprocessing. The `route` label also covers the built-in +policies. Batched text completion children share the parent HTTP timeline, so overlapping child +work is counted once. + +The timing context stays within one frontend process; a standalone router reached over the +network does not receive it. Other HTTP endpoints and uninstrumented operations retain their time +in `frontend_overhead`. A large value does not establish that the frontend consumed that time on +CPU. + +Native Rust rendering and tokenization use their existing separate operation clocks. Python paths +use separate boundaries only where the backend API exposes them: SGLang's explicit text encoder +and tokenizer can be measured independently, while fused `apply_chat_template` calls remain +`template_tokenize`. A vLLM renderer that returns token IDs is also opaque; a renderer that returns +text uses `template_render`, followed by a separately measured tokenizer call. Rendering may fetch +media, so renderer time is not necessarily pure template computation. Later media processing and +transfer preparation contribute to `multimodal_prepare`. The frontend never repeats tokenization +to manufacture a split. + +The SGLang process pool returns a versioned batch with fixed stage IDs and integer nanosecond +intervals. Supported same-host monotonic clocks are checked against the parent's submission and +completion window. The parent reads one Python timestamp and imports elapsed ages in one PyO3 +call; Python monotonic values are never subtracted from a Rust `Instant` epoch. Re-anchoring still +has a bounded call-delay uncertainty. Unsupported clock domains retain the reliable outer +`preprocess` interval and report coarse coverage; remote backend clocks are not aligned. Backend +stages include transport, scheduling, and processing, not isolated GPU compute or KV transfer. A +control response ends `dispatch` without ending `first_token_wait`. + +Collection is bounded to 256 intervals per request and 64 per worker batch. Once the HTTP first +token freezes the result, late intervals and guard cleanup cannot alter it. Normal later calls +check the frozen flag before reading the clock or locking; a call racing with freeze may already +have started. No detail interval is recorded for every output token. + +Coverage has three fixed states: + +| State | Meaning | Attribution | +| --- | --- | --- | +| `complete` | All declared measurable boundaries are valid; this does not mean every internal function is measured | Normal exclusive contributions | +| `coarse` | A known opaque call or unsupported clock prevents finer detail, but the outer window remains reliable | `template_tokenize` or parent residual | +| `degraded` | An interval limit or invalid timing data makes the detailed partition unreliable | Full TTFT in `unclassified`, all other contributions zero | + +Degradation never fabricates frontend CPU time or drops the total-TTFT sample. Existing active +guards can still close safely when a limit is reached. Diagnostics use fixed reason values; +request IDs, attempt IDs, prompt text, and tool schemas are never metric labels. The +[`reason` label reference](metric-labels.mdx#metric-specific-labels) lists the fixed values. +`missing_timeline` makes an enabled request with no attached timeline visible as degraded, +preserving its stage sample count. Opaque `template_tokenize` intervals mark coverage coarse. + +When metrics are enabled, every legal pair for each model has the same sample count and request +population as total TTFT on that enabled frontend. Requests that end, fail, or are canceled before the first output token produce neither total +nor stage TTFT observations. Later tokens do not add TTFT observations. Labels never contain +request IDs. See [Per-Request First-Token Log](logging.mdx#per-request-first-token-log) for the +corresponding per-request event. + +For a stacked chart of mean stage durations in milliseconds, use: + +```promql +1000 * ( + sum by (model, stage, phase) ( + rate(dynamo_frontend_ttft_stage_seconds_sum[$__rate_interval]) + ) + / + sum by (model, stage, phase) ( + rate(dynamo_frontend_ttft_stage_seconds_count[$__rate_interval]) + ) +) +``` + +Set the legend to `{{model}} / {{stage}} / {{phase}}` and select one model per stacked panel. Apply +the same deployment selectors when comparing with mean total TTFT: + +```promql +1000 * ( + sum by (model) ( + rate(dynamo_frontend_time_to_first_token_seconds_sum[$__rate_interval]) + ) + / + sum by (model) ( + rate(dynamo_frontend_time_to_first_token_seconds_count[$__rate_interval]) + ) +) +``` + +Zero observations preserve the common denominator, so the sum of stage means matches mean total +TTFT over the same requests. Select the same enabled instances, model, and time window for both +queries; do not compare detail from a subset of instances with service-wide total TTFT. Stage P95 +or P99 values are not additive: different requests can +determine each percentile, and unused stages contribute zero observations. Use total TTFT +percentiles separately to assess tail latency. A scrape overlapping metric updates or differing +series scrape histories can cause small temporary differences between the sums. + +The default stage histogram has 26 finite buckets, including zero, plus `+Inf`. Set +`DYN_METRICS_TTFT_STAGE_MIN`, `DYN_METRICS_TTFT_STAGE_MAX`, and `DYN_METRICS_TTFT_STAGE_COUNT` before +frontend startup to customize the logarithmic boundaries. Bucket resolution affects percentile +estimates; `_sum` and `_count` retain the observed durations independently of the boundaries. See +[Histogram buckets](../components/frontend-configuration.mdx#histogram-buckets) for defaults, +validation, and cardinality considerations. + ### Multimodal Requests | Metric | Type | Labels | Description | Status | diff --git a/lib/bindings/python/Cargo.toml b/lib/bindings/python/Cargo.toml index fca3c27b40d9..39fbc3674c80 100644 --- a/lib/bindings/python/Cargo.toml +++ b/lib/bindings/python/Cargo.toml @@ -106,13 +106,13 @@ dynamo-generate-format-catalog = { path = "../../generate-format-catalog" } clap = { version = "4.5", features = ["derive"], optional = true } tracing-subscriber = { version = "0.3", features = ["env-filter"], optional = true } -# "extension-module" tells pyo3 we want to build an extension module (skips linking against libpython.so) +# Maturin enables "extension-module" in pyproject.toml for wheel builds. +# Plain cargo tests must link libpython to execute native Python API tests. # "abi3-py311" tells pyo3 (and maturin) to build using the stable ABI with minimum Python version 3.11, which is the minimum version in pyproject.toml pyo3 = { version = "0.23.4", default-features = false, features = [ "macros", "experimental-async", "experimental-inspect", - "extension-module", "py-clone", "abi3-py311" ] } diff --git a/lib/bindings/python/pyproject.toml b/lib/bindings/python/pyproject.toml index 74ee91fbf8e7..2ab218cb1a65 100644 --- a/lib/bindings/python/pyproject.toml +++ b/lib/bindings/python/pyproject.toml @@ -45,6 +45,8 @@ classifiers = [ keywords = ["llm", "genai", "inference", "nvidia", "distributed", "dynamo"] [tool.maturin] +# Skip libpython linkage for extension builds, but retain it for cargo tests. +features = ["pyo3/extension-module"] module-name = "dynamo._core" manifest-path = "Cargo.toml" python-packages = ["dynamo"] diff --git a/lib/bindings/python/rust/context.rs b/lib/bindings/python/rust/context.rs index 42fd51322c4c..d4613f7d2954 100644 --- a/lib/bindings/python/rust/context.rs +++ b/lib/bindings/python/rust/context.rs @@ -12,6 +12,10 @@ use dynamo_backend_common::FirstTokenNotifier; use dynamo_llm::protocols::common::extensions::{SESSION_AFFINITY_CONTEXT_KEY, SessionAffinityId}; +use dynamo_llm::protocols::common::ttft::{ + MAX_TTFT_BATCH_INTERVALS, TTFT_CONTEXT_KEY, TtftCoarseReason, TtftDegradedReason, TtftSpan, + TtftStage, TtftTimings, +}; use dynamo_runtime::logging::DistributedTraceContext; pub use dynamo_runtime::pipeline::AsyncEngineContext; use dynamo_runtime::pipeline::Context as PipelineContext; @@ -20,7 +24,7 @@ use opentelemetry::global::BoxedSpan; use opentelemetry::trace::{Span as OtelSpan, Status, TraceContextExt, Tracer}; use opentelemetry::{KeyValue, global}; use pyo3::prelude::*; -use pyo3::types::{PyBool, PyDict, PyFloat, PyInt, PyList, PyString}; +use pyo3::types::{PyBool, PyDict, PyFloat, PyInt, PyList, PyString, PyTuple}; use std::collections::{BTreeMap, HashMap}; use std::sync::{Arc, Mutex, MutexGuard, OnceLock}; use tracing_opentelemetry::OpenTelemetrySpanExt; @@ -65,6 +69,7 @@ pub struct Context { trace_context: Option, first_token: Option, metadata: Arc>>, + ttft: Option>, session_affinity: Option, /// Captured `engine.generate` span. `None` for Python-instantiated test /// contexts (where no parent span was plumbed in) — `current_span` / @@ -78,6 +83,50 @@ pub struct ContextMetadata { inner: Arc>>, } +fn python_ttft_stage(name: &str) -> PyResult { + TtftStage::from_python(name).ok_or_else(|| { + pyo3::exceptions::PyValueError::new_err(format!("unknown frontend TTFT stage: {name}")) + }) +} + +/// Fixed Python-eligible IDs/names from the same registry used by metrics. +#[pyfunction] +pub fn ttft_stage_registry() -> Vec<(usize, &'static str)> { + TtftStage::ALL + .into_iter() + .filter(|stage| stage.python_enabled()) + .map(|stage| (stage as usize, stage.labels()[0])) + .collect() +} + +/// A small RAII context manager; never creates an OpenTelemetry span or log. +#[pyclass] +pub struct TtftStageGuard { + inner: Option, +} + +#[pymethods] +impl TtftStageGuard { + fn close(&mut self) { + self.inner.take(); + } + + fn __enter__(slf: PyRefMut) -> PyRefMut { + slf + } + + #[pyo3(signature = (_exc_type=None, _exc_value=None, _traceback=None))] + fn __exit__( + &mut self, + _exc_type: Option>, + _exc_value: Option>, + _traceback: Option>, + ) -> bool { + self.close(); + false + } +} + impl ContextMetadata { fn lock_map(&self) -> MutexGuard<'_, BTreeMap> { self.inner @@ -185,11 +234,26 @@ impl Context { trace_context, first_token, metadata: Arc::new(Mutex::new(metadata)), + ttft: None, session_affinity: None, span: None, } } + pub fn with_ttft_from( + mut self, + context: &PipelineContext, + ) -> Result { + self.ttft = context + .get_optional::>(TTFT_CONTEXT_KEY)? + .map(|timings| Arc::clone(timings.as_ref())); + Ok(self) + } + + pub fn ttft(&self) -> Option<&Arc> { + self.ttft.as_ref() + } + pub fn with_session_affinity_from( mut self, context: &PipelineContext, @@ -290,6 +354,7 @@ impl Context { trace_context: None, first_token: None, metadata: Arc::new(Mutex::new(metadata.unwrap_or_default())), + ttft: None, session_affinity: None, span: None, } @@ -308,6 +373,7 @@ impl Context { trace_context: self.trace_context.clone(), first_token: None, metadata: Arc::new(Mutex::new(self.metadata_snapshot())), + ttft: self.ttft.clone(), session_affinity: self.session_affinity.clone(), span: self.span.clone(), } @@ -317,6 +383,170 @@ impl Context { self.inner.is_stopped() } + /// Whether HTTP enabled detail collection for this request. + #[getter] + fn ttft_enabled(&self) -> bool { + self.ttft.is_some() + } + + /// Start a process-local frontend stage; no-op outside an HTTP timeline. + fn start_ttft_stage(&self, stage: &str) -> PyResult { + let stage = python_ttft_stage(stage)?; + Ok(TtftStageGuard { + inner: self.ttft.as_ref().map(|timings| timings.start_span(stage)), + }) + } + + /// Import pool-worker timings without serializing a native request context. + fn record_ttft_stage_ago( + &self, + stage: &str, + start_ago_seconds: f64, + end_ago_seconds: f64, + ) -> PyResult<()> { + let stage = python_ttft_stage(stage)?; + let start = std::time::Duration::try_from_secs_f64(start_ago_seconds) + .map_err(|_| pyo3::exceptions::PyValueError::new_err("invalid start age"))?; + let end = std::time::Duration::try_from_secs_f64(end_ago_seconds) + .map_err(|_| pyo3::exceptions::PyValueError::new_err("invalid end age"))?; + if start < end { + return Err(pyo3::exceptions::PyValueError::new_err( + "start age precedes end age", + )); + } + if let Some(timings) = &self.ttft { + timings.record_ago(stage, start, end); + } + Ok(()) + } + + /// A single same-host Python anchor, expressed as integer nanosecond ages. + /// Python validates the local submit/receive window before this call; Rust + /// independently validates fixed IDs, bounds and the HTTP timeline window. + #[pyo3(signature = (intervals, coarse_reasons=None))] + fn record_ttft_batch_ago( + &self, + intervals: &Bound<'_, PyAny>, + coarse_reasons: Option<&Bound<'_, PyAny>>, + ) -> bool { + let Some(timings) = &self.ttft else { + return false; + }; + if timings.is_frozen() { + return false; + } + // Concrete containers have a truthful fixed size; an arbitrary Python + // iterable can lie in __len__ and grow without bound during extraction. + if !intervals.is_exact_instance_of::() + && !intervals.is_exact_instance_of::() + { + timings.mark_degraded(TtftDegradedReason::InvalidBatch); + return false; + } + let Ok(length) = intervals.len() else { + timings.mark_degraded(TtftDegradedReason::InvalidBatch); + return false; + }; + if length > MAX_TTFT_BATCH_INTERVALS { + timings.mark_degraded(TtftDegradedReason::IntervalLimit); + return false; + } + // Bound conversion before allocating a Vec across the Python boundary. + let Ok(intervals) = intervals.extract::>() else { + timings.mark_degraded(TtftDegradedReason::InvalidBatch); + return false; + }; + let mut batch = Vec::with_capacity(length); + for (id, start_ns, end_ns) in intervals { + let Some(stage) = TtftStage::from_python_id(id) else { + timings.mark_degraded(TtftDegradedReason::InvalidStage); + return false; + }; + if start_ns < end_ns { + timings.mark_degraded(TtftDegradedReason::InvalidInterval); + return false; + } + batch.push(( + stage, + std::time::Duration::from_nanos(start_ns), + std::time::Duration::from_nanos(end_ns), + )); + } + if let Some(reasons) = coarse_reasons { + if (!reasons.is_exact_instance_of::() + && !reasons.is_exact_instance_of::()) + || reasons.len().map_or(true, |len| len > 3) + { + timings.mark_degraded(TtftDegradedReason::InvalidBatch); + return false; + } + let Ok(reasons) = reasons.extract::>>() else { + timings.mark_degraded(TtftDegradedReason::InvalidBatch); + return false; + }; + for reason in reasons { + let Ok(reason) = reason.to_cow() else { + timings.mark_degraded(TtftDegradedReason::InvalidBatch); + return false; + }; + let reason = match reason.as_ref() { + "opaque_template" => TtftCoarseReason::OpaqueTemplate, + "unsupported_clock" => TtftCoarseReason::UnsupportedClock, + "missing_coverage" => TtftCoarseReason::MissingCoverage, + _ => { + timings.mark_degraded(TtftDegradedReason::InvalidBatch); + return false; + } + }; + timings.mark_coarse(reason); + } + } + timings.record_batch_ago(&batch) + } + + /// Fixed quality codes, never arbitrary strings in Prometheus labels. + fn mark_ttft_quality(&self, quality: &str, reason: &str) -> PyResult<()> { + if quality == "coarse" { + let reason = match reason { + "opaque_template" => TtftCoarseReason::OpaqueTemplate, + "unsupported_clock" => TtftCoarseReason::UnsupportedClock, + "missing_coverage" => TtftCoarseReason::MissingCoverage, + _ => { + return Err(pyo3::exceptions::PyValueError::new_err( + "unknown TTFT coarse reason", + )); + } + }; + if let Some(timings) = &self.ttft { + timings.mark_coarse(reason); + } + } else if quality == "degraded" { + let reason = match reason { + "interval_limit" => TtftDegradedReason::IntervalLimit, + "invalid_interval" => TtftDegradedReason::InvalidInterval, + "invalid_batch" => TtftDegradedReason::InvalidBatch, + "invalid_stage" => TtftDegradedReason::InvalidStage, + "invalid_version" => TtftDegradedReason::InvalidVersion, + "clock_mismatch" => TtftDegradedReason::ClockMismatch, + "timestamp_overflow" => TtftDegradedReason::TimestampOverflow, + "missing_timeline" => TtftDegradedReason::MissingTimeline, + _ => { + return Err(pyo3::exceptions::PyValueError::new_err( + "unknown TTFT degraded reason", + )); + } + }; + if let Some(timings) = &self.ttft { + timings.mark_degraded(reason); + } + } else { + return Err(pyo3::exceptions::PyValueError::new_err( + "unknown TTFT quality", + )); + } + Ok(()) + } + fn is_killed(&self) -> bool { self.inner.is_killed() } @@ -645,3 +875,48 @@ pub fn callable_accepts_kwarg( .call_method1("__contains__", (target_name,))? .extract::() } + +#[cfg(test)] +mod ttft_batch_tests { + use super::*; + use std::time::{Duration, Instant}; + + #[test] + fn ttft_batch_rejects_lying_iterables_before_conversion() { + pyo3::prepare_freethreaded_python(); + Python::with_gil(|py| { + let code = std::ffi::CString::new( + "class Liar:\n def __len__(self): return 0\n def __iter__(self): raise AssertionError('must not iterate')\nvalue = Liar()\n", + ).unwrap(); + let module = PyModule::from_code(py, &code, c"timing_test.py", c"timing_test").unwrap(); + let mut context = Context::py_new(None, None); + context.ttft = Some(Arc::new(TtftTimings::new(Instant::now()))); + assert!(!context.record_ttft_batch_ago(&module.getattr("value").unwrap(), None)); + assert_eq!( + context.ttft.unwrap().quality().degraded_reason, + Some(TtftDegradedReason::InvalidBatch) + ); + }); + } + + #[test] + fn ttft_batch_imports_fixed_ids_and_coarse_flags_once() { + pyo3::prepare_freethreaded_python(); + Python::with_gil(|py| { + let mut context = Context::py_new(None, None); + let timings = Arc::new(TtftTimings::new(Instant::now() - Duration::from_secs(1))); + context.ttft = Some(timings.clone()); + let intervals = + PyList::new(py, [(TtftStage::TemplateRender as usize, 100_u64, 50_u64)]).unwrap(); + let reasons = PyTuple::new(py, ["opaque_template"]).unwrap(); + assert!(context.record_ttft_batch_ago(intervals.as_any(), Some(reasons.as_any()))); + assert!(timings.quality().degraded_reason.is_none()); + let result = timings.finish(Instant::now()); + assert_eq!( + result[TtftStage::TemplateRender as usize], + Duration::from_nanos(50) + ); + assert!(!context.record_ttft_batch_ago(intervals.as_any(), None)); + }); + } +} diff --git a/lib/bindings/python/rust/engine.rs b/lib/bindings/python/rust/engine.rs index 8b7434bafb76..567db0ec0366 100644 --- a/lib/bindings/python/rust/engine.rs +++ b/lib/bindings/python/rust/engine.rs @@ -451,6 +451,8 @@ where let py_context = if engine.has_context { Some( Context::new(ctx.clone(), current_trace_context, None, metadata) + .with_ttft_from(&context) + .map_err(anyhow::Error::msg)? .with_session_affinity_from(&context) .map_err(anyhow::Error::msg)?, ) diff --git a/lib/bindings/python/rust/lib.rs b/lib/bindings/python/rust/lib.rs index 57276a2f9524..b21849a9e1c6 100644 --- a/lib/bindings/python/rust/lib.rs +++ b/lib/bindings/python/rust/lib.rs @@ -423,6 +423,8 @@ fn register_core(m: &Bound<'_, PyModule>) -> PyResult<()> { m.add_class::()?; m.add_class::()?; m.add_class::()?; + m.add_class::()?; + m.add_function(wrap_pyfunction!(context::ttft_stage_registry, m)?)?; m.add_class::()?; m.add_class::()?; m.add_class::()?; diff --git a/lib/bindings/python/rust/llm/entrypoint.rs b/lib/bindings/python/rust/llm/entrypoint.rs index d1b2db63128a..d7b5f8ae3559 100644 --- a/lib/bindings/python/rust/llm/entrypoint.rs +++ b/lib/bindings/python/rust/llm/entrypoint.rs @@ -537,7 +537,7 @@ pub(crate) struct EntrypointArgs { impl EntrypointArgs { #[allow(clippy::too_many_arguments)] #[new] - #[pyo3(signature = (engine_type, model_path=None, model_name=None, endpoint_id=None, template_file=None, router_config=None, kv_cache_block_size=None, http_host=None, http_port=None, http_metrics_port=None, tls_cert_path=None, tls_key_path=None, extra_engine_args=None, mocker_engine_args=None, runtime_config=None, namespace=None, namespace_prefix=None, is_prefill=false, is_decode=false, migration_limit=0, migration_max_seq_len=None, chat_engine_factory=None, ais_perf_config=None, *, tls_client_ca_cert_path=None, metrics_prefix=None, enable_anthropic_api=None, enable_systemone_api=None, strip_anthropic_preamble=None, enable_streaming_tool_dispatch=None, enable_streaming_reasoning_dispatch=None, reasoning_field_name=None, tokenizer_backend=None, tokenizer_fallback=None, batch_gateway_url=None))] + #[pyo3(signature = (engine_type, model_path=None, model_name=None, endpoint_id=None, template_file=None, router_config=None, kv_cache_block_size=None, http_host=None, http_port=None, http_metrics_port=None, tls_cert_path=None, tls_key_path=None, extra_engine_args=None, mocker_engine_args=None, runtime_config=None, namespace=None, namespace_prefix=None, is_prefill=false, is_decode=false, migration_limit=0, migration_max_seq_len=None, chat_engine_factory=None, ais_perf_config=None, *, tls_client_ca_cert_path=None, metrics_prefix=None, ttft_detail=None, enable_anthropic_api=None, enable_systemone_api=None, strip_anthropic_preamble=None, enable_streaming_tool_dispatch=None, enable_streaming_reasoning_dispatch=None, reasoning_field_name=None, tokenizer_backend=None, tokenizer_fallback=None, batch_gateway_url=None))] pub fn new( py: Python<'_>, engine_type: EngineType, @@ -565,6 +565,7 @@ impl EntrypointArgs { ais_perf_config: Option, tls_client_ca_cert_path: Option, metrics_prefix: Option, + ttft_detail: Option, enable_anthropic_api: Option, enable_systemone_api: Option, strip_anthropic_preamble: Option, @@ -645,7 +646,22 @@ impl EntrypointArgs { http_port: http_port.unwrap_or(DEFAULT_HTTP_PORT), http_metrics_port, batch_gateway_url, - metrics_config: metrics_prefix.map(|prefix| MetricsConfig::new(Some(prefix))), + metrics_config: { + let detail = ttft_detail + .map(|value| { + value + .parse() + .map_err(pyo3::exceptions::PyValueError::new_err) + }) + .transpose()? + .unwrap_or_else(dynamo_llm::frontend_config::TtftDetail::from_env); + let prefix = metrics_prefix.or_else(|| { + use dynamo_runtime::config::environment_names::llm::metrics::DYN_METRICS_PREFIX; + std::env::var(DYN_METRICS_PREFIX).ok() + }); + let config = MetricsConfig::with_ttft_detail(prefix, detail); + Some(config) + }, frontend_api_config: FrontendApiConfig::from_optional_flags( enable_anthropic_api, enable_systemone_api, diff --git a/lib/bindings/python/rust/llm/routed_engine.rs b/lib/bindings/python/rust/llm/routed_engine.rs index b677cd1ac6dc..d37ff2daa29e 100644 --- a/lib/bindings/python/rust/llm/routed_engine.rs +++ b/lib/bindings/python/rust/llm/routed_engine.rs @@ -1,6 +1,8 @@ // SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. // SPDX-License-Identifier: Apache-2.0 +use std::sync::Arc; + use pyo3::prelude::*; use pythonize::{depythonize, pythonize}; use tokio_stream::StreamExt; @@ -28,6 +30,12 @@ impl RoutedEngine { } } +fn copy_ttft_timeline(parent_context: &crate::context::Context, request: &mut PreprocessedRequest) { + if let Some(ttft) = parent_context.ttft() { + request.ttft = Some(Arc::clone(ttft)); + } +} + fn copy_session_affinity( parent_context: &crate::context::Context, child_context: &mut SingleIn, @@ -47,8 +55,10 @@ impl RoutedEngine { preprocessed: PyObject, context: Option, ) -> PyResult> { - let request: PreprocessedRequest = depythonize(preprocessed.bind(py)).map_err(to_pyerr)?; + let mut request: PreprocessedRequest = + depythonize(preprocessed.bind(py)).map_err(to_pyerr)?; let request_context = if let Some(parent_context) = context.as_ref() { + copy_ttft_timeline(parent_context, &mut request); let parent_metadata = parent_context.metadata_snapshot(); let parent_controller = parent_context.inner(); let mut child_context = SingleIn::with_id_and_metadata( @@ -158,6 +168,46 @@ mod tests { use opentelemetry::trace::{TraceContextExt, TraceId, TracerProvider as _}; use tracing_subscriber::layer::SubscriberExt; + #[test] + fn http_timeline_crosses_python_without_changing_legacy_tracker_population() { + use dynamo_llm::protocols::common::timing::RequestTracker; + use dynamo_llm::protocols::common::ttft::{TTFT_CONTEXT_KEY, TtftTimings}; + + let timeline = Arc::new(TtftTimings::new(std::time::Instant::now())); + let mut source = SingleIn::new(()); + source.insert(TTFT_CONTEXT_KEY, Arc::clone(&timeline)); + let python_context = + crate::context::Context::new(source.context(), None, None, Default::default()) + .with_ttft_from(&source) + .unwrap(); + let mut request: PreprocessedRequest = + serde_json::from_value(serde_json::json!({"token_ids": []})).unwrap(); + copy_ttft_timeline(&python_context, &mut request); + assert!(request.tracker.is_none()); + assert!(Arc::ptr_eq(&timeline, request.ttft_timings().unwrap())); + assert!(Arc::ptr_eq( + &timeline, + request.clone().ttft_timings().unwrap() + )); + // Preserve any existing local tracker (and its other timing state). + let tracker = Arc::new(RequestTracker::new()); + request.tracker = Some(Arc::clone(&tracker)); + copy_ttft_timeline(&python_context, &mut request); + assert!(Arc::ptr_eq(&tracker, request.tracker.as_ref().unwrap())); + assert!(tracker.ttft().is_none()); + assert!(Arc::ptr_eq( + &tracker, + request.clone().tracker.as_ref().unwrap(), + )); + // Process-local telemetry does not alter old/new worker wire schemas. + let serialized = serde_json::to_value(&request).unwrap(); + assert!(serialized.get("tracker").is_none()); + assert!(serialized.get("ttft").is_none()); + let round_trip: PreprocessedRequest = serde_json::from_value(serialized).unwrap(); + assert!(round_trip.tracker.is_none()); + assert!(round_trip.ttft.is_none()); + } + fn preprocessed_request() -> PreprocessedRequest { serde_json::from_value(serde_json::json!({ "token_ids": [] diff --git a/lib/bindings/python/src/dynamo/_core.pyi b/lib/bindings/python/src/dynamo/_core.pyi index 01c707f1addd..ae921525ea35 100644 --- a/lib/bindings/python/src/dynamo/_core.pyi +++ b/lib/bindings/python/src/dynamo/_core.pyi @@ -505,12 +505,54 @@ class FirstTokenSource: def bind(self, context: Context, dp_rank: Optional[int] = None) -> None: ... +class TtftStageGuard: + """Process-local TTFT interval. Closing is idempotent; exceptions propagate.""" + + def close(self) -> None: ... + def __enter__(self) -> TtftStageGuard: ... + def __exit__( + self, _exc_type: Any = None, _exc_value: Any = None, _traceback: Any = None + ) -> bool: ... + + +def ttft_stage_registry() -> list[tuple[int, str]]: + """Fixed Python stage IDs and labels from the canonical Rust registry.""" + ... + + class Context: """ Context wrapper around AsyncEngineContext for Python bindings. Provides tracing and cancellation capabilities for request handling. """ + @property + def ttft_enabled(self) -> bool: + """Whether this request carries an enabled TTFT detail timeline.""" + ... + + def start_ttft_stage(self, stage: str) -> TtftStageGuard: + """Start a frontend stage; no-op if no HTTP TTFT timeline is attached.""" + ... + + def record_ttft_stage_ago( + self, stage: str, start_ago_seconds: float, end_ago_seconds: float + ) -> None: + """Import worker-pool intervals using nonnegative monotonic ages.""" + ... + + def record_ttft_batch_ago( + self, + intervals: list[tuple[int, int, int]], + coarse_reasons: tuple[str, ...] | None = None, + ) -> bool: + """Import at most 64 (stage ID, start age ns, end age ns) intervals.""" + ... + + def mark_ttft_quality(self, quality: str, reason: str) -> None: + """Record a fixed coarse/degraded diagnostic reason.""" + ... + def __init__( self, id: Optional[str] = None, @@ -3185,6 +3227,7 @@ class EntrypointArgs: *, tls_client_ca_cert_path: Optional[str] = None, metrics_prefix: Optional[str] = None, + ttft_detail: Optional[str] = None, enable_anthropic_api: Optional[bool] = None, enable_systemone_api: Optional[bool] = None, strip_anthropic_preamble: Optional[bool] = None, diff --git a/lib/bindings/python/src/dynamo/prometheus_names.py b/lib/bindings/python/src/dynamo/prometheus_names.py index 9ac438771aa8..16c9a033e00e 100644 --- a/lib/bindings/python/src/dynamo/prometheus_names.py +++ b/lib/bindings/python/src/dynamo/prometheus_names.py @@ -165,6 +165,14 @@ class frontend_service: OUTPUT_TOKENS_TOTAL = "output_tokens_total" # Time to first token in seconds TIME_TO_FIRST_TOKEN_SECONDS = "time_to_first_token_seconds" + # Exclusive contributions to HTTP time to first token, labeled by stage and phase. + TTFT_STAGE_SECONDS = "ttft_stage_seconds" + # Requests with untrustworthy detailed TTFT attribution, labeled by fixed reason. + TTFT_DETAIL_DEGRADED_TOTAL = "ttft_detail_degraded_total" + # Requests with known coarse TTFT coverage, labeled by fixed reason. + TTFT_DETAIL_COARSE_TOTAL = "ttft_detail_coarse_total" + # Requests with unexpected overlapping TTFT leaves. + TTFT_DETAIL_UNEXPECTED_OVERLAP_TOTAL = "ttft_detail_unexpected_overlap_total" # Inter-token latency in seconds INTER_TOKEN_LATENCY_SECONDS = "inter_token_latency_seconds" # End-to-end latency of an OpenAI `/v1/embeddings` request, in seconds. diff --git a/lib/llm/src/frontend_config.rs b/lib/llm/src/frontend_config.rs index 37102fc03a17..10e1178a9d16 100644 --- a/lib/llm/src/frontend_config.rs +++ b/lib/llm/src/frontend_config.rs @@ -18,6 +18,45 @@ use dynamo_runtime::config::{ use crate::reasoning_field::ReasoningField; +/// Optional exclusive TTFT diagnostics. Parsed at service startup, never per stage. +#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)] +pub enum TtftDetail { + Off, + #[default] + Metrics, + Logs, + Both, +} + +impl std::str::FromStr for TtftDetail { + type Err = &'static str; + + fn from_str(value: &str) -> Result { + match value { + "off" => Ok(Self::Off), + "metrics" => Ok(Self::Metrics), + "logs" => Ok(Self::Logs), + "both" => Ok(Self::Both), + _ => Err("DYN_FRONTEND_TTFT_DETAIL must be off, metrics, logs, or both"), + } + } +} + +impl TtftDetail { + pub fn from_env() -> Self { + std::env::var(env_llm::DYN_FRONTEND_TTFT_DETAIL) + .map(|value| value.parse().expect("invalid DYN_FRONTEND_TTFT_DETAIL")) + .unwrap_or_default() + } + + pub fn metrics(self) -> bool { + matches!(self, Self::Metrics | Self::Both) + } + + pub fn logs(self) -> bool { + matches!(self, Self::Logs | Self::Both) + } +} /// Process-wide strict-schema policy, initialized before the HTTP service accepts requests. pub(crate) static DISABLE_OPENAI_STRICT_SCHEMA_VALIDATION: LazyLock = LazyLock::new(|| env_is_truthy(env_llm::DYN_DISABLE_OPENAI_STRICT_SCHEMA_VALIDATION)); @@ -31,11 +70,23 @@ pub(crate) static DISABLE_OPENAI_STRICT_SCHEMA_VALIDATION: LazyLock = #[derive(Debug, Clone, PartialEq, Eq)] pub struct MetricsConfig { prefix: Option, + /// None defers the environment fallback to HTTP metrics initialization. + pub ttft_detail: Option, } impl MetricsConfig { pub fn new(prefix: Option) -> Self { - Self { prefix } + Self { + prefix, + ttft_detail: None, + } + } + + pub fn with_ttft_detail(prefix: Option, ttft_detail: TtftDetail) -> Self { + Self { + prefix, + ttft_detail: Some(ttft_detail), + } } pub fn prefix(&self) -> Option { @@ -51,6 +102,7 @@ impl Default for MetricsConfig { fn default() -> Self { Self { prefix: std::env::var(env_metrics::DYN_METRICS_PREFIX).ok(), + ttft_detail: None, } } } diff --git a/lib/llm/src/http/service/metrics.rs b/lib/llm/src/http/service/metrics.rs index 6c51e8b9268f..1ec984c618a5 100644 --- a/lib/llm/src/http/service/metrics.rs +++ b/lib/llm/src/http/service/metrics.rs @@ -30,9 +30,13 @@ use std::{ }; use crate::discovery::{ModelManager, UNKNOWN_METRIC_MODEL}; +use crate::frontend_config::{MetricsConfig, TtftDetail}; use crate::frontend_load::{FrontendLoadFrame, FrontendModelLoad, RequestGauges, RequestTotals}; use crate::local_model::runtime_config::ModelRuntimeConfig; use crate::model_card::ModelDeploymentCard; +use crate::protocols::common::ttft::{ + TTFT_CONTEXT_KEY, TtftDegradedReason, TtftQuality, TtftQualityStatus, TtftStage, TtftTimings, +}; use crate::protocols::{ common::metrics::{ANNOTATION_LLM_METRICS, LLMMetricAnnotation}, openai::chat_completions::NvCreateChatCompletionStreamResponse, @@ -807,6 +811,13 @@ pub struct Metrics { tokenizer_latency: HistogramVec, output_tokens_counter: IntCounterVec, time_to_first_token: HistogramVec, + ttft_stage: HistogramVec, + ttft_detail: TtftDetail, + ttft_degraded: IntCounterVec, + ttft_coarse: IntCounterVec, + ttft_unexpected_overlap: prometheus::IntCounter, + ttft_stage_handles: + dashmap::DashMap>, inter_token_latency: HistogramVec, /// End-to-end latency of an OpenAI `/v1/embeddings` request. Distinct from /// `request_duration` so the buckets can be sized for sub-second pooling @@ -1187,6 +1198,10 @@ pub struct ResponseMetricCollector { // every chunk or output token. Each handle shares the underlying metric with its vec, // so observations are equivalent. time_to_first_token: prometheus::Histogram, + ttft_stage: Option>, + ttft_logs: bool, + ttft_timeline: Option>, + ttft_request_id: Option, inter_token_latency: Option, input_sequence_length: prometheus::Histogram, cached_tokens: prometheus::Histogram, @@ -1304,6 +1319,25 @@ impl Metrics { /// Real constructor. `env` is injected so tests can pin bucket configuration /// without touching the process environment. fn build(metrics_prefix: Option, env: EnvLookup<'_>) -> Self { + let detail = env(dynamo_runtime::config::environment_names::llm::DYN_FRONTEND_TTFT_DETAIL) + .map(|value| value.parse().expect("invalid DYN_FRONTEND_TTFT_DETAIL")) + .unwrap_or_default(); + Self::build_with_detail(metrics_prefix, env, detail) + } + + pub fn with_config(config: &MetricsConfig) -> Self { + let detail = config.ttft_detail.unwrap_or_else(TtftDetail::from_env); + tracing::info!(mode = ?detail, + detail_log_target_enabled = tracing::enabled!(target: "dynamo_frontend::ttft", tracing::Level::DEBUG), + "Frontend TTFT detail configuration"); + Self::build_with_detail(config.prefix(), &system_env, detail) + } + + fn build_with_detail( + metrics_prefix: Option, + env: EnvLookup<'_>, + ttft_detail: TtftDetail, + ) -> Self { // TODO: Remove DYN_METRICS_PREFIX env-var override (added in PR #2432 for // NIM compatibility with the old "nv_llm_http_service_" prefix). No longer // needed — hardcode name_prefix::FRONTEND and drop the sanitize function. @@ -1492,6 +1526,45 @@ impl Metrics { ) .unwrap(); + let (stage_min, stage_max, stage_count) = parse_bucket_config( + env, + env_metrics::DYN_METRICS_TTFT_STAGE, + 0.000001, + 480.0, + 26, + ); + let ttft_stage = HistogramVec::new( + HistogramOpts::new( + frontend_metric_name(frontend_service::TTFT_STAGE_SECONDS), + "Exclusive HTTP TTFT stage duration in seconds; stages sum to HTTP TTFT", + ) + .buckets(generate_log_buckets(stage_min, stage_max, stage_count)), + &["model", "stage", "phase"], + ) + .unwrap(); + + let ttft_degraded = IntCounterVec::new( + Opts::new( + frontend_metric_name(frontend_service::TTFT_DETAIL_DEGRADED_TOTAL), + "First-token requests whose detailed TTFT is unclassified, by fixed reason", + ), + &["reason"], + ) + .unwrap(); + let ttft_coarse = IntCounterVec::new( + Opts::new( + frontend_metric_name(frontend_service::TTFT_DETAIL_COARSE_TOTAL), + "First-token requests with known coarse TTFT coverage, by fixed reason", + ), + &["reason"], + ) + .unwrap(); + let ttft_unexpected_overlap = prometheus::IntCounter::with_opts(Opts::new( + frontend_metric_name(frontend_service::TTFT_DETAIL_UNEXPECTED_OVERLAP_TOTAL), + "First-token requests with unexpected overlapping TTFT leaf intervals", + )) + .unwrap(); + let inter_token_latency_buckets = inter_token_latency_buckets(env); let inter_token_latency = HistogramVec::new( @@ -1734,6 +1807,12 @@ impl Metrics { tokenizer_latency, output_tokens_counter, time_to_first_token, + ttft_stage, + ttft_detail, + ttft_degraded, + ttft_coarse, + ttft_unexpected_overlap, + ttft_stage_handles: dashmap::DashMap::new(), inter_token_latency, embedding_latency, systemone, @@ -1950,6 +2029,12 @@ impl Metrics { registry.register(Box::new(self.tokenizer_latency.clone()))?; registry.register(Box::new(self.output_tokens_counter.clone()))?; registry.register(Box::new(self.time_to_first_token.clone()))?; + if self.ttft_detail.metrics() { + registry.register(Box::new(self.ttft_stage.clone()))?; + registry.register(Box::new(self.ttft_degraded.clone()))?; + registry.register(Box::new(self.ttft_coarse.clone()))?; + registry.register(Box::new(self.ttft_unexpected_overlap.clone()))?; + } registry.register(Box::new(self.inter_token_latency.clone()))?; registry.register(Box::new(self.embedding_latency.clone()))?; registry.register(Box::new(self.images_per_request.clone()))?; @@ -2545,6 +2630,26 @@ impl ResponseMetricCollector { // Resolve the per-model handles once (cheap clones of the vec entries) so the // per-chunk / per-token hot path in `observe_response` does no label hashing. let time_to_first_token = metrics.time_to_first_token.with_label_values(&[&model]); + // Resolve the finite stage label set once per model, not per request/token. + let ttft_stage = metrics.ttft_detail.metrics().then(|| { + metrics + .ttft_stage_handles + .entry(model.clone()) + .or_insert_with(|| { + Arc::new(TtftStage::ALL.map(|stage| { + let [name, phase] = stage.labels(); + metrics + .ttft_stage + .with_label_values(&[model.as_str(), name, phase]) + })) + }) + .clone() + }); + // Check the configured target before allocating a timeline. In logs-only + // mode a disabled filter costs no stage clocks, handles, or Python calls. + let ttft_logs = metrics.ttft_detail.logs() + && tracing::enabled!(target: "dynamo_frontend::ttft", tracing::Level::DEBUG); + let input_sequence_length = metrics.input_sequence_length.with_label_values(&[&model]); let cached_tokens = metrics.cached_tokens.with_label_values(&[&model]); let images_per_request = metrics.images_per_request.with_label_values(&[&model]); @@ -2558,6 +2663,10 @@ impl ResponseMetricCollector { request, model, time_to_first_token, + ttft_stage, + ttft_logs, + ttft_timeline: None, + ttft_request_id: None, inter_token_latency: None, input_sequence_length, cached_tokens, @@ -2591,6 +2700,75 @@ impl ResponseMetricCollector { } } + /// Preserve this collector's exact start across the Python processor bridge. + /// Other paths still emit an additive sample, with uninstrumented time in + /// frontend_overhead, so the stage and total histograms have the same cohort. + pub fn attach_ttft_timeline( + &mut self, + request: &mut dynamo_runtime::pipeline::Context, + ) { + if self.ttft_stage.is_none() && !self.ttft_logs { + return; + } + let timeline = Arc::new(TtftTimings::new(self.start_time)); + request.insert(TTFT_CONTEXT_KEY, timeline.clone()); + self.ttft_timeline = Some(timeline); + if self.ttft_logs { + self.ttft_request_id = Some(request.id().to_owned()); + } + } + + /// One structured event for the same frozen durations sent to Prometheus. + /// DEBUG keeps it off at the default INFO level; enable its dedicated target + /// with DYN_LOG=info,dynamo_frontend::ttft=debug. Metrics are independent, and + /// the tracing macro evaluates numeric fields only when this event is enabled. + fn log_ttft_stages( + &self, + total: Duration, + stages: &[Duration; TtftStage::ALL.len()], + quality: TtftQuality, + ) { + let Some(request_id) = self.ttft_request_id.as_deref() else { + return; + }; + let ms = |stage: TtftStage| stages[stage as usize].as_secs_f64() * 1000.0; + tracing::debug!( + target: "dynamo_frontend::ttft", + request_id, + model = self.model.as_str(), + ttft_ms = total.as_secs_f64() * 1000.0, + quality = quality.status.as_str(), + degraded_reason = quality.degraded_reason.map_or("", |reason| reason.as_str()), + coarse_reason = quality.coarse_reason.map_or("", |reason| reason.as_str()), + unexpected_overlap = quality.unexpected_overlap, + frontend_overhead_ms = ms(TtftStage::FrontendOverhead), + preprocess_ms = ms(TtftStage::Preprocess), + preprocess_queue_ms = ms(TtftStage::PreprocessQueue), + template_tokenize_ms = ms(TtftStage::TemplateTokenize), + template_render_ms = ms(TtftStage::TemplateRender), + tokenize_ms = ms(TtftStage::Tokenize), + structural_tag_build_ms = ms(TtftStage::StructuralTagBuild), + dispatch_prepare_prefill_ms = ms(TtftStage::DispatchPreparePrefill), + dispatch_prepare_decode_ms = ms(TtftStage::DispatchPrepareDecode), + dispatch_prepare_aggregated_ms = ms(TtftStage::DispatchPrepareAggregated), + unclassified_ms = ms(TtftStage::Unclassified), + multimodal_prepare_ms = ms(TtftStage::MultimodalPrepare), + mm_routing_build_ms = ms(TtftStage::MmRoutingBuild), + route_prefill_ms = ms(TtftStage::RoutePrefill), + route_decode_ms = ms(TtftStage::RouteDecode), + route_aggregated_ms = ms(TtftStage::RouteAggregated), + dispatch_prefill_ms = ms(TtftStage::BackendPrefill), + dispatch_decode_ms = ms(TtftStage::BackendDecode), + dispatch_aggregated_ms = ms(TtftStage::BackendAggregated), + first_token_wait_prefill_ms = ms(TtftStage::FirstTokenPrefill), + first_token_wait_decode_ms = ms(TtftStage::FirstTokenDecode), + first_token_wait_aggregated_ms = ms(TtftStage::FirstTokenAggregated), + first_token_postprocess_ms = ms(TtftStage::ResponsePostprocess), + backend_overlap_prefill_decode_ms = ms(TtftStage::BackendOverlap), + "frontend first token" + ); + } + /// Set the worker info for per-worker TTFT/ITL metrics. /// In disaggregated mode, TTFT is attributed to prefill worker, ITL to decode worker. /// Worker types are stored at routing time to avoid expensive MDC lookup when updating metrics. @@ -2754,9 +2932,53 @@ impl ResponseMetricCollector { self.is_first_token = false; // Publish TTFT and store for span recording - let ttft = self.start_time.elapsed().as_secs_f64(); + let first_token_at = Instant::now(); + let duration = first_token_at.duration_since(self.start_time); + let ttft = duration.as_secs_f64(); self.ttft_ms = Some(ttft * 1000.0); self.time_to_first_token.observe(ttft); + if self.ttft_stage.is_some() || self.ttft_logs { + let (stages, quality) = if let Some(timeline) = self.ttft_timeline.take() { + let stages = timeline.finish(first_token_at); + (stages, timeline.quality()) + } else { + let mut stages = [Duration::ZERO; TtftStage::ALL.len()]; + stages[TtftStage::Unclassified as usize] = duration; + ( + stages, + TtftQuality { + status: TtftQualityStatus::Degraded, + degraded_reason: Some(TtftDegradedReason::MissingTimeline), + coarse_reason: None, + unexpected_overlap: false, + }, + ) + }; + // Include zeros so all stages share the exact total-TTFT population. + if let Some(histograms) = &self.ttft_stage { + if let Some(reason) = quality.degraded_reason { + self.metrics + .ttft_degraded + .with_label_values(&[reason.as_str()]) + .inc(); + } + if let Some(reason) = quality.coarse_reason { + self.metrics + .ttft_coarse + .with_label_values(&[reason.as_str()]) + .inc(); + } + if quality.unexpected_overlap { + self.metrics.ttft_unexpected_overlap.inc(); + } + for (histogram, elapsed) in histograms.iter().zip(stages) { + histogram.observe(elapsed.as_secs_f64()); + } + } + if self.ttft_logs { + self.log_ttft_stages(duration, &stages, quality); + } + } // Update per-worker TTFT and input sequence tokens gauges - attributed to prefill worker. // Both gauges are updated atomically from the same request to correlate latency with input size. @@ -3179,6 +3401,693 @@ async fn handler_metrics(State(state): State>) -> impl mod tests { use super::*; + const EXPECTED_TTFT_STAGE_LABELS: &[(&str, &str)] = &[ + ("frontend_overhead", ""), + ("preprocess", ""), + ("preprocess_queue", ""), + ("template_tokenize", ""), + ("template_render", ""), + ("tokenize", ""), + ("structural_tag_build", ""), + ("dispatch_prepare", "prefill"), + ("dispatch_prepare", "decode"), + ("dispatch_prepare", "aggregated"), + ("unclassified", ""), + ("multimodal_prepare", ""), + ("mm_routing_build", ""), + ("route", "prefill"), + ("route", "decode"), + ("route", "aggregated"), + ("dispatch", "prefill"), + ("dispatch", "decode"), + ("dispatch", "aggregated"), + ("first_token_wait", "prefill"), + ("first_token_wait", "decode"), + ("first_token_wait", "aggregated"), + ("backend_overlap", "prefill_decode"), + ("first_token_postprocess", ""), + ]; + + /// Synthetic production instrumentation only; excludes HTTP, GPU, and PyO3. + /// Run explicitly with --ignored --exact and DYNAMO_TTFT_BENCH_MODE set. + #[test] + #[cfg(unix)] + #[ignore = "manual CPU microbenchmark"] + fn ttft_detail_cpu_microbenchmark() { + fn cpu_ns() -> u64 { + let mut value = libc::timespec { + tv_sec: 0, + tv_nsec: 0, + }; + // SAFETY: value is a writable timespec; process CPU clock is read-only. + assert_eq!( + unsafe { libc::clock_gettime(libc::CLOCK_PROCESS_CPUTIME_ID, &mut value) }, + 0 + ); + value.tv_sec as u64 * 1_000_000_000 + value.tv_nsec as u64 + } + let mode = std::env::var("DYNAMO_TTFT_BENCH_MODE").unwrap_or_else(|_| "off".into()); + let detail = if mode == "logs-filtered" { + TtftDetail::Logs + } else { + mode.parse().unwrap() + }; + let filter = if mode == "logs-filtered" { + "info" + } else { + "info,dynamo_frontend::ttft=debug" + }; + let subscriber = tracing_subscriber::fmt() + .with_env_filter(filter) + .with_writer(std::io::sink) + .without_time() + .finish(); + tracing::subscriber::with_default(subscriber, || { + let metrics = Arc::new(Metrics::build_with_detail(None, &fake_env(&[]), detail)); + let run = |count| { + for _ in 0..count { + let mut collector = response_collector(&metrics, "synthetic"); + let mut request = dynamo_runtime::pipeline::Context::new(()); + collector.attach_ttft_timeline(&mut request); + if let Some(timeline) = &collector.ttft_timeline { + let outer = timeline.start_span(TtftStage::Preprocess); + let inner = timeline.start_span(TtftStage::TemplateTokenize); + std::hint::black_box(&inner); + drop(inner); + drop(outer); + drop(timeline.start_span(TtftStage::RouteAggregated)); + drop(timeline.start_span(TtftStage::BackendAggregated)); + } + collector.observe_response(8, 0); + collector.observe_response(8, 1); + std::hint::black_box(&collector); + } + }; + run(1000); + let cpu_start = cpu_ns(); + let wall_start = Instant::now(); + let count = 100_000; + run(count); + println!( + "mode={mode} requests={count} cpu_ns_per_request={} wall_ns_per_request={}", + (cpu_ns() - cpu_start) as f64 / count as f64, + wall_start.elapsed().as_nanos() as f64 / count as f64 + ); + }); + } + + #[test] + fn ttft_detail_modes_and_log_filters_gate_collection_and_outputs() { + for mode in [ + TtftDetail::Off, + TtftDetail::Metrics, + TtftDetail::Logs, + TtftDetail::Both, + ] { + for directive in [ + "info", + "debug", + "info,dynamo_frontend::ttft=debug", + "debug,dynamo_frontend::ttft=off", + ] { + let events = Arc::new(std::sync::Mutex::new(Vec::new())); + let subscriber = TtftLogSubscriber { + filter: directive.parse().unwrap(), + events: events.clone(), + }; + tracing::subscriber::with_default(subscriber, || { + let metrics = Arc::new(Metrics::build_with_detail(None, &fake_env(&[]), mode)); + let logs = mode.logs() + && matches!(directive, "debug" | "info,dynamo_frontend::ttft=debug"); + let mut collector = response_collector(&metrics, "mode-test"); + let mut request = dynamo_runtime::pipeline::Context::new(()); + collector.attach_ttft_timeline(&mut request); + assert_eq!(collector.ttft_stage.is_some(), mode.metrics()); + assert_eq!(collector.ttft_logs, logs); + assert_eq!(collector.ttft_timeline.is_some(), mode.metrics() || logs); + assert_eq!( + request + .get_optional::>(TTFT_CONTEXT_KEY) + .unwrap() + .is_some(), + mode.metrics() || logs + ); + assert_eq!( + metrics.ttft_stage_handles.len(), + usize::from(mode.metrics()) + ); + collector.observe_response(4, 0); + assert!(events.lock().unwrap().is_empty()); + collector.observe_response(4, 1); + collector.observe_response(4, 2); + assert_eq!(events.lock().unwrap().len(), usize::from(logs)); + assert_eq!( + metrics + .time_to_first_token + .with_label_values(&["mode-test"]) + .get_sample_count(), + 1 + ); + if mode.metrics() { + assert_ttft_stage_cohort(&metrics, "mode-test", 1); + } else { + // No lazy child creation even after first token. + assert!( + metrics + .ttft_stage + .collect() + .iter() + .all(|family| family.get_metric().is_empty()) + ); + } + }); + } + } + } + + #[test] + fn ttft_modes_preserve_legacy_metric_schema_buckets_and_sample_counts() { + let mut expected = None; + for mode in [ + TtftDetail::Off, + TtftDetail::Metrics, + TtftDetail::Logs, + TtftDetail::Both, + ] { + let metrics = Arc::new(Metrics::build_with_detail(None, &fake_env(&[]), mode)); + let registry = Registry::new(); + metrics.register(®istry).unwrap(); + // Registries otherwise share this counter's lazily created label sets + // with concurrent error-rendering tests. Keep the same metric schema + // in the snapshot, but give each mode its own counter instance. + registry + .unregister(Box::new(DYNAM_FAILURES_TOTAL.clone())) + .unwrap(); + let failures = new_failure_counter(None); + failures + .with_label_values(&["InvalidRequest", "request.invalid"]) + .inc(); + registry.register(Box::new(failures)).unwrap(); + for emits_token in [false, true] { + let mut collector = response_collector(&metrics, "compatibility"); + let mut request = dynamo_runtime::pipeline::Context::new(()); + collector.attach_ttft_timeline(&mut request); + collector.observe_response(4, 0); + if emits_token { + collector.observe_response(4, 1); + collector.observe_response(4, 2); + } + } + let mut schema = Vec::new(); + for family in registry.gather() { + if family.name().contains("ttft_stage_seconds") + || family.name().contains("ttft_detail_") + { + continue; + } + for metric in family.get_metric() { + let labels: Vec<_> = metric + .get_label() + .iter() + .map(|label| (label.name(), label.value())) + .collect(); + let histogram = metric.get_histogram(); + let buckets: Vec<_> = histogram + .get_bucket() + .iter() + .map(|bucket| bucket.upper_bound()) + .collect(); + schema.push(format!( + "{}|{}|{:?}|{labels:?}|{}|{buckets:?}", + family.name(), + family.help(), + family.get_field_type(), + histogram.get_sample_count() + )); + } + } + schema.sort(); + if let Some(expected) = &expected { + assert_eq!(&schema, expected, "mode={mode:?}"); + } else { + assert!(!schema.is_empty()); + expected = Some(schema); + } + } + } + + #[test] + fn ttft_detail_configuration_defaults_metrics_and_explicit_config_wins() { + assert_eq!( + Metrics::build(None, &fake_env(&[])).ttft_detail, + TtftDetail::Metrics + ); + for (value, expected) in [ + ("off", TtftDetail::Off), + ("metrics", TtftDetail::Metrics), + ("logs", TtftDetail::Logs), + ("both", TtftDetail::Both), + ] { + let pairs = [("DYN_FRONTEND_TTFT_DETAIL", value)]; + let env = fake_env(&pairs); + assert_eq!(Metrics::build(None, &env).ttft_detail, expected); + assert_eq!( + Metrics::build_with_detail(None, &env, TtftDetail::Off).ttft_detail, + TtftDetail::Off + ); + } + assert!("invalid".parse::().is_err()); + } + + fn assert_ttft_stage_cohort(metrics: &Metrics, model: &str, expected_count: u64) { + let total = metrics.time_to_first_token.with_label_values(&[model]); + assert_eq!(total.get_sample_count(), expected_count); + let mut stage_sum = 0.0; + for (stage, phase) in EXPECTED_TTFT_STAGE_LABELS { + let histogram = metrics.ttft_stage.with_label_values(&[model, stage, phase]); + assert_eq!( + histogram.get_sample_count(), + expected_count, + "stage={stage}, phase={phase} must use the total TTFT request population", + ); + stage_sum += histogram.get_sample_sum(); + } + let total_sum = total.get_sample_sum(); + assert!( + (stage_sum - total_sum).abs() <= 1e-12 * total_sum.max(1.0), + "stage sum {stage_sum} differs from actual total TTFT histogram sum {total_sum}", + ); + } + + #[test] + fn ttft_missing_timeline_is_conserved_and_reported_once() { + let metrics = Arc::new(Metrics::build_with_detail( + None, + &fake_env(&[]), + TtftDetail::Metrics, + )); + let mut collector = response_collector(&metrics, "missing"); + collector.observe_response(1, 0); + assert_eq!( + metrics + .ttft_degraded + .with_label_values(&["missing_timeline"]) + .get(), + 0 + ); + collector.observe_response(1, 1); + collector.observe_response(1, 1); + assert_ttft_stage_cohort(&metrics, "missing", 1); + assert_eq!( + metrics + .ttft_degraded + .with_label_values(&["missing_timeline"]) + .get(), + 1 + ); + assert_eq!( + metrics + .ttft_stage + .with_label_values(&["missing", "unclassified", ""]) + .get_sample_sum(), + metrics + .time_to_first_token + .with_label_values(&["missing"]) + .get_sample_sum() + ); + assert_eq!( + metrics + .ttft_stage + .with_label_values(&["missing", "frontend_overhead", ""]) + .get_sample_sum(), + 0.0 + ); + } + + #[test] + fn ttft_stage_histogram_uses_frontend_prefix_and_documented_bucket_configuration() { + let env = fake_env(&[ + ("DYN_METRICS_TTFT_STAGE_MIN", "0.002"), + ("DYN_METRICS_TTFT_STAGE_MAX", "8"), + ("DYN_METRICS_TTFT_STAGE_COUNT", "5"), + ]); + let metrics = Metrics::build(Some("custom_frontend".to_string()), &env); + metrics + .ttft_stage + .with_label_values(&["model", "frontend_overhead", ""]) + .observe(0.1); + let families = metrics.ttft_stage.collect(); + assert_eq!(families[0].name(), "custom_frontend_ttft_stage_seconds"); + let buckets: Vec<_> = families[0].get_metric()[0] + .get_histogram() + .get_bucket() + .iter() + .map(|bucket| bucket.upper_bound()) + .collect(); + assert_eq!(buckets, generate_log_buckets(0.002, 8.0, 5)); + } + + #[test] + fn ttft_stage_cohorts_match_for_zero_tokens_later_tokens_and_cancelled_requests() { + let metrics = Arc::new(Metrics::build_with_detail( + None, + &fake_env(&[]), + TtftDetail::Both, + )); + let model = "ttft-cohort-model"; + let mut expected_count = 0; + + // Both instrumented SGLang and other frontend paths contribute to the + // same population; missing timelines are explicitly unclassified. + for attach_timeline in [false, true] { + let mut collector = response_collector(&metrics, model); + collector.start_time -= Duration::from_secs(1); + let mut request = dynamo_runtime::pipeline::Context::new(()); + if attach_timeline { + collector.attach_ttft_timeline(&mut request); + } + collector.observe_response(20, 0); + assert_ttft_stage_cohort(&metrics, model, expected_count); + collector.observe_response(20, 3); + expected_count += 1; + assert_ttft_stage_cohort(&metrics, model, expected_count); + + // Neither subsequent tokens nor collector drop repeat TTFT samples. + collector.observe_response(20, 0); + collector.observe_response(20, 5); + drop(collector); + assert_ttft_stage_cohort(&metrics, model, expected_count); + + let mut cancelled = response_collector(&metrics, model); + if attach_timeline { + cancelled.attach_ttft_timeline(&mut request); + } + cancelled.observe_response(20, 0); + drop(cancelled); + assert_ttft_stage_cohort(&metrics, model, expected_count); + } + } + + #[test] + fn ttft_shared_request_timeline_is_observed_on_existing_http_registry() { + let metrics = Arc::new(Metrics::build_with_detail( + None, + &fake_env(&[]), + TtftDetail::Both, + )); + let registry = prometheus::Registry::new(); + metrics.register(®istry).unwrap(); + let model = "ttft-shared-timeline-model"; + let mut collector = response_collector(&metrics, model); + let mut request = dynamo_runtime::pipeline::Context::new(()); + collector.attach_ttft_timeline(&mut request); + let shared = request.get::>(TTFT_CONTEXT_KEY).unwrap(); + assert!(Arc::ptr_eq( + shared.as_ref(), + collector.ttft_timeline.as_ref().unwrap(), + )); + + // The same handle travels through the Python bridge and routed engine; + // an open span must be clipped to this collector's first-token instant. + let route_span = shared.start_span(TtftStage::RouteDecode); + std::thread::sleep(Duration::from_millis(1)); + collector.observe_response(20, 1); + assert_ttft_stage_cohort(&metrics, model, 1); + let before = metrics + .ttft_stage + .with_label_values(&[model, "route", "decode"]) + .get_sample_sum(); + assert!(before > 0.0); + drop(route_span); + collector.observe_response(20, 2); + assert_eq!( + metrics + .ttft_stage + .with_label_values(&[model, "route", "decode"]) + .get_sample_sum(), + before, + "late span completion must not change the frozen HTTP TTFT", + ); + + let family = registry + .gather() + .into_iter() + .find(|family| family.name() == "dynamo_frontend_ttft_stage_seconds") + .expect("stage histogram must be exported by the existing HTTP registry"); + assert_eq!(family.get_metric().len(), EXPECTED_TTFT_STAGE_LABELS.len()); + for sample in family.get_metric() { + let labels: std::collections::BTreeMap<_, _> = sample + .get_label() + .iter() + .map(|label| (label.name(), label.value())) + .collect(); + assert_eq!(labels.len(), 3, "no request/worker IDs in stage labels"); + assert_eq!(labels["model"], model); + assert!(EXPECTED_TTFT_STAGE_LABELS.contains(&(labels["stage"], labels["phase"]))); + assert_eq!(sample.get_histogram().get_sample_count(), 1); + } + } + + #[test] + fn ttft_stage_labels_and_cached_histograms_preserve_model_separation() { + let metrics = Arc::new(Metrics::build_with_detail( + None, + &fake_env(&[]), + TtftDetail::Both, + )); + let mut first = response_collector(&metrics, "ttft-model-a"); + let mut first_again = response_collector(&metrics, "ttft-model-a"); + let mut second = response_collector(&metrics, "ttft-model-b"); + assert!(Arc::ptr_eq( + first.ttft_stage.as_ref().unwrap(), + first_again.ttft_stage.as_ref().unwrap() + )); + assert!(!Arc::ptr_eq( + first.ttft_stage.as_ref().unwrap(), + second.ttft_stage.as_ref().unwrap() + )); + first.start_time -= Duration::from_secs(1); + second.start_time -= Duration::from_secs(3); + first.observe_response(10, 1); + first_again.observe_response(10, 1); + second.observe_response(10, 1); + assert_ttft_stage_cohort(&metrics, "ttft-model-a", 2); + assert_ttft_stage_cohort(&metrics, "ttft-model-b", 1); + assert!( + metrics + .ttft_stage + .with_label_values(&["ttft-model-b", "unclassified", ""]) + .get_sample_sum() + >= 3.0, + ); + assert_eq!(metrics.ttft_stage_handles.len(), 2); + } + + #[derive(Default)] + struct TtftLogFields { + numbers: std::collections::BTreeMap<&'static str, f64>, + text: std::collections::BTreeMap<&'static str, String>, + } + + impl tracing::field::Visit for TtftLogFields { + fn record_f64(&mut self, field: &tracing::field::Field, value: f64) { + self.numbers.insert(field.name(), value); + } + + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + self.text.insert(field.name(), value.to_string()); + } + + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + self.text.insert(field.name(), format!("{value:?}")); + } + } + + /// Capture actual tracing events without installing a process-global logger + /// or adding a test-only logging dependency. + #[derive(Clone)] + struct TtftLogSubscriber { + filter: tracing_subscriber::filter::Targets, + events: Arc>>, + } + + impl tracing::Subscriber for TtftLogSubscriber { + fn enabled(&self, metadata: &tracing::Metadata<'_>) -> bool { + metadata.target() == "dynamo_frontend::ttft" + && self + .filter + .would_enable(metadata.target(), metadata.level()) + } + + fn register_callsite( + &self, + _: &'static tracing::Metadata<'static>, + ) -> tracing::subscriber::Interest { + // Tests install independent subscribers on different threads. Do + // not cache one test's enabled/disabled setting for another test. + tracing::subscriber::Interest::sometimes() + } + + fn new_span(&self, _: &tracing::span::Attributes<'_>) -> tracing::span::Id { + tracing::span::Id::from_u64(1) + } + + fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record<'_>) {} + + fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {} + + fn event(&self, event: &tracing::Event<'_>) { + if self.enabled(event.metadata()) { + let mut fields = TtftLogFields::default(); + event.record(&mut fields); + self.events + .lock() + .unwrap() + .push((*event.metadata().level(), fields)); + } + } + + fn enter(&self, _: &tracing::span::Id) {} + + fn exit(&self, _: &tracing::span::Id) {} + } + + #[test] + fn ttft_log_is_once_at_first_token_and_matches_histograms_and_request_identity() { + let events = Arc::new(std::sync::Mutex::new(Vec::new())); + let subscriber = TtftLogSubscriber { + filter: "info,dynamo_frontend::ttft=debug".parse().unwrap(), + events: events.clone(), + }; + let metrics = Arc::new(Metrics::build_with_detail( + None, + &fake_env(&[]), + TtftDetail::Both, + )); + let model = "ttft-log-model"; + tracing::subscriber::with_default(subscriber, || { + let mut collector = response_collector(&metrics, model); + collector.start_time -= Duration::from_secs(1); + let mut request = dynamo_runtime::pipeline::Context::with_id_and_metadata( + (), + "client-request-42".to_string(), + Default::default(), + ); + collector.attach_ttft_timeline(&mut request); + let timeline = request.get::>(TTFT_CONTEXT_KEY).unwrap(); + timeline.record_ago( + TtftStage::Preprocess, + Duration::from_millis(500), + Duration::from_millis(200), + ); + timeline.record_ago( + TtftStage::TemplateTokenize, + Duration::from_millis(400), + Duration::from_millis(300), + ); + let route = timeline.start_span(TtftStage::RouteDecode); + + collector.observe_response(20, 0); + assert!(events.lock().unwrap().is_empty()); + assert_ttft_stage_cohort(&metrics, model, 0); + collector.observe_response(20, 3); + assert_eq!(events.lock().unwrap().len(), 1); + assert_ttft_stage_cohort(&metrics, model, 1); + drop(route); + collector.observe_response(20, 0); + collector.observe_response(20, 4); + drop(collector); + + // A request that never produces tokens must neither log a TTFT nor + // add samples, even though it carries the full request context. + let mut cancelled = response_collector(&metrics, model); + cancelled.attach_ttft_timeline(&mut request); + cancelled.observe_response(20, 0); + drop(cancelled); + assert_ttft_stage_cohort(&metrics, model, 1); + + // Other endpoints still record metrics, but without the attached + // HTTP request context they must not emit an anonymous chat log. + let mut unattached = response_collector(&metrics, "ttft-unattached-model"); + unattached.observe_response(20, 1); + drop(unattached); + }); + + let events = events.lock().unwrap(); + assert_eq!( + events.len(), + 1, + "later tokens/drop/cancellation must not log" + ); + let (level, fields) = &events[0]; + assert_eq!(*level, tracing::Level::DEBUG); + assert_eq!(fields.text["message"], "frontend first token"); + assert_eq!(fields.text["request_id"], "client-request-42"); + assert_eq!(fields.text["model"], model); + assert_eq!( + fields.numbers.len(), + TtftStage::ALL.len() + 1, + "every canonical numeric stage field plus total" + ); + let total_ms = fields.numbers["ttft_ms"]; + let histogram_ttft_ms = metrics + .time_to_first_token + .with_label_values(&[model]) + .get_sample_sum() + * 1000.0; + assert_eq!(total_ms, histogram_ttft_ms); + let mut stage_sum_ms = 0.0; + for (stage, phase) in EXPECTED_TTFT_STAGE_LABELS { + let field = if phase.is_empty() { + format!("{stage}_ms") + } else { + format!("{stage}_{phase}_ms") + }; + let logged_ms = fields.numbers[field.as_str()]; + let histogram_ms = metrics + .ttft_stage + .with_label_values(&[model, stage, phase]) + .get_sample_sum() + * 1000.0; + assert_eq!(logged_ms, histogram_ms, "numeric field {field}"); + stage_sum_ms += logged_ms; + } + assert!((stage_sum_ms - total_ms).abs() <= 1e-9 * total_ms.max(1.0)); + assert!(fields.numbers["template_tokenize_ms"] > 0.0); + assert!(fields.numbers["preprocess_ms"] > 0.0); + } + + #[test] + fn ttft_log_disabled_by_default_or_explicit_filter_does_not_change_metrics() { + for directive in ["info", "debug,dynamo_frontend::ttft=off"] { + let events = Arc::new(std::sync::Mutex::new(Vec::new())); + let subscriber = TtftLogSubscriber { + filter: directive.parse().unwrap(), + events: events.clone(), + }; + let metrics = Arc::new(Metrics::build_with_detail( + None, + &fake_env(&[]), + TtftDetail::Both, + )); + let model = "ttft-disabled-log-model"; + tracing::subscriber::with_default(subscriber, || { + let mut collector = response_collector(&metrics, model); + let mut request = dynamo_runtime::pipeline::Context::new(()); + collector.attach_ttft_timeline(&mut request); + let timeline = request.get::>(TTFT_CONTEXT_KEY).unwrap(); + let route = timeline.start_span(TtftStage::RouteAggregated); + collector.observe_response(20, 0); + collector.observe_response(20, 1); + drop(route); + collector.observe_response(20, 2); + drop(collector); + }); + assert!(events.lock().unwrap().is_empty()); + assert_ttft_stage_cohort(&metrics, model, 1); + } + } + fn response_collector(metrics: &Arc, model: &str) -> ResponseMetricCollector { ResponseMetricCollector::new( metrics.clone(), @@ -5431,6 +6340,14 @@ mod tests { .into_iter() .find(|family| family.name() == "dynamo_frontend_failures_total") .expect("dynamo_frontend_failures_total metric"); + assert_eq!( + family.get_field_type(), + prometheus::proto::MetricType::COUNTER + ); + assert_eq!( + family.help(), + "Total number of terminal semantic request failures" + ); let metric = family .get_metric() .iter() diff --git a/lib/llm/src/http/service/openai.rs b/lib/llm/src/http/service/openai.rs index 42a3dac5d2fe..f4bf003d2399 100644 --- a/lib/llm/src/http/service/openai.rs +++ b/lib/llm/src/http/service/openai.rs @@ -1165,6 +1165,15 @@ fn copy_context_metadata( ); } + if let Ok(timings) = source.get::>( + crate::protocols::common::ttft::TTFT_CONTEXT_KEY, + ) { + target.insert( + crate::protocols::common::ttft::TTFT_CONTEXT_KEY, + Arc::clone(timings.as_ref()), + ); + } + if let Ok(agent_context) = source.get::(AGENT_CONTEXT_CONTEXT_KEY) { target.insert(AGENT_CONTEXT_CONTEXT_KEY, agent_context.as_ref().clone()); } @@ -1346,6 +1355,7 @@ async fn completions_single( let mut response_collector = inflight_guard.response_collector(); inflight_guard.request_metrics().attach_to(&mut request); + response_collector.attach_ttft_timeline(&mut request); // prepare to process any annotations let annotations = request.annotations(); @@ -1642,6 +1652,7 @@ async fn completions_batch( })?; let mut response_collector = inflight_guard.response_collector(); + response_collector.attach_ttft_timeline(&mut request); // prepare to process any annotations let annotations = request.annotations(); @@ -3677,6 +3688,7 @@ async fn chat_completions( let mut response_collector = inflight_guard.response_collector(); inflight_guard.request_metrics().attach_to(&mut request); + response_collector.attach_ttft_timeline(&mut request); let annotations = request.annotations(); @@ -6661,6 +6673,18 @@ mod tests { assert!(err.to_string().contains("unknown field `agent_context`")); } + #[test] + fn completion_batch_child_shares_parent_ttft_timeline() { + use crate::protocols::common::ttft::{TTFT_CONTEXT_KEY, TtftTimings}; + let timeline = Arc::new(TtftTimings::new(std::time::Instant::now())); + let mut source = Context::new(()); + source.insert(TTFT_CONTEXT_KEY, timeline.clone()); + let mut child = Context::new(()); + copy_context_metadata(&source, &mut child); + let copied = child.get::>(TTFT_CONTEXT_KEY).unwrap(); + assert!(Arc::ptr_eq(copied.as_ref(), &timeline)); + } + #[test] fn test_copy_context_metadata_preserves_agent_context() { let mut source = Context::new(()); diff --git a/lib/llm/src/http/service/service_v2.rs b/lib/llm/src/http/service/service_v2.rs index 2ab6341bc292..73f8df37ff0a 100644 --- a/lib/llm/src/http/service/service_v2.rs +++ b/lib/llm/src/http/service/service_v2.rs @@ -677,7 +677,7 @@ impl State { ); Self { manager, - metrics: Arc::new(Metrics::new_with_prefix(config.metrics_config.prefix())), + metrics: Arc::new(Metrics::with_config(&config.metrics_config)), discovery_client, service_observer: Arc::new(ServiceObserver::default()), nvext_enabled: config.nvext_enabled, diff --git a/lib/llm/src/kv_router/routing_host.rs b/lib/llm/src/kv_router/routing_host.rs index 03208064860a..898a2a101f75 100644 --- a/lib/llm/src/kv_router/routing_host.rs +++ b/lib/llm/src/kv_router/routing_host.rs @@ -16,7 +16,6 @@ use dynamo_kv_router::{ }; use dynamo_runtime::{ error::{DynamoError, ErrorType, match_error_chain}, - metrics::frontend_perf::{STAGE_ROUTE, StageGuard}, pipeline::{ AsyncEngine, AsyncEngineContext, AsyncEngineContextProvider, Error, ManyOut, PushRouter, ResponseStream, SingleIn, async_trait, @@ -40,8 +39,10 @@ use crate::{ FinishReason, extensions::SessionAffinityId, llm_backend::LLMEngineOutput, + observation::StageObservation, preprocessor::owned_abort_error, timing::{RequestPhase, RoutingData, WORKER_TYPE_DECODE, WORKER_TYPE_PREFILL}, + ttft::{TtftSpan, TtftStage}, }, session_affinity::{ AffinityCoordinator, AffinityTarget, Hold, SessionAffinityMode, affinity_id, @@ -331,6 +332,7 @@ pub(crate) struct RoutePlan { selection: WorkerSelection, cleanup: KvRequestCleanup, affinity: Option, + dispatch_prepare: Option, /// Carried forward from the [`RoutePreview`] this plan was admitted from, so /// preview, admission and dispatch draw on one budget instead of three. budget: CleanupBudget, @@ -389,6 +391,7 @@ impl RoutePlan { /// Give the route up before dispatch: abort the classifier lifecycle with /// `error` as its cause, release the booking, and drop the affinity hold. pub(crate) async fn abort(mut self, error: Option<&Error>) { + self.dispatch_prepare.take(); if let Some(mut lifecycle) = self.selection.request_lifecycle.take() { lifecycle.abort(error.map(|error| owned_abort_error(error.as_ref()))); } @@ -764,8 +767,7 @@ impl AsyncEngine, ManyOut, ManyOut StageObservation { + StageObservation::new(route_stage(phase), request.ttft_timings()) +} + +fn route_stage(phase: RequestPhase) -> TtftStage { + match phase { + RequestPhase::Prefill => TtftStage::RoutePrefill, + RequestPhase::Decode => TtftStage::RouteDecode, + RequestPhase::Aggregated => TtftStage::RouteAggregated, + } +} + +fn route_selection_finished( + route: StageObservation, + request: &PreprocessedRequest, + phase: RequestPhase, +) -> Option { + drop(route); + start_dispatch_prepare(request, phase) +} + +fn start_dispatch_prepare(request: &PreprocessedRequest, phase: RequestPhase) -> Option { + let stage = route_stage(phase).dispatch_prepare()?; + request + .ttft_timings() + .map(|timings| timings.start_span(stage)) +} + enum ResponseItemOutcome { /// The stream is healthy and must keep running. Healthy, diff --git a/lib/llm/src/kv_router/routing_host/hosted.rs b/lib/llm/src/kv_router/routing_host/hosted.rs index 59a11ef63cf5..3450f44056e1 100644 --- a/lib/llm/src/kv_router/routing_host/hosted.rs +++ b/lib/llm/src/kv_router/routing_host/hosted.rs @@ -187,7 +187,7 @@ impl RoutingHost { F: FnOnce(&mut PreprocessedRequest, AffinityTarget) -> Result, { let phase_label = phase.to_string(); - let route_guard = StageGuard::new(STAGE_ROUTE, &phase_label); + let route_guard = start_route(&request, phase); let explicit = explicit_target(request.content(), phase)?; let has_affinity_session = self.affinity.is_some() && affinity_id(&request)?.is_some(); let is_direct = matches!(&self.policy, RoutingPolicy::Direct); @@ -268,6 +268,7 @@ impl RoutingHost { occupancy_reservation, lora_load, &request, + phase, ); let tracker = request.tracker.clone(); let request_context = request.context().clone(); diff --git a/lib/llm/src/kv_router/routing_host/kv.rs b/lib/llm/src/kv_router/routing_host/kv.rs index 3ab21e4dd2b4..71d7c3769f6f 100644 --- a/lib/llm/src/kv_router/routing_host/kv.rs +++ b/lib/llm/src/kv_router/routing_host/kv.rs @@ -210,8 +210,7 @@ impl RoutingHost { } self.validate_explicit_worker(request.content(), phase)?; - let phase_label = phase.to_string(); - let route_guard = StageGuard::new(STAGE_ROUTE, &phase_label); + let route_guard = start_route(request, phase); let (outcome, _) = self .select_with_session_affinity(request, phase, true, &budget, |target| { self.select_request_outcome( @@ -258,8 +257,7 @@ impl RoutingHost { self.validate_explicit_worker(request.content(), phase)?; } - let phase_label = phase.to_string(); - let route_guard = StageGuard::new(STAGE_ROUTE, &phase_label); + let route_guard = start_route(request, phase); let select = || { self.select_with_session_affinity(request, phase, false, &budget, |target| { let budget = &budget; @@ -281,8 +279,9 @@ impl RoutingHost { let (mut selection, affinity) = self .select_with_request_lifecycle(request, phase, select) .await?; - drop(route_guard); + let dispatch_prepare = route_selection_finished(route_guard, request, phase); Ok(RoutePlan { + dispatch_prepare, phase, cleanup: KvRequestCleanup::new( Arc::clone(self.kv_router()), @@ -330,13 +329,28 @@ impl RoutingHost { cleanup, affinity, budget, + dispatch_prepare, .. } = plan; + drop(dispatch_prepare); + let ttft_route = request + .ttft_timings() + .map(|timings| timings.start_span(route_stage(phase))); let guard = self .track_planned_selection(&request, &mut selection, phase, cleanup, &budget) .await?; - self.dispatch_selection(request, selection, phase, guard, &budget, affinity) - .await + drop(ttft_route); + let dispatch_prepare = start_dispatch_prepare(&request, phase); + self.dispatch_selection( + request, + selection, + phase, + guard, + &budget, + affinity, + dispatch_prepare, + ) + .await } pub(crate) async fn prefill_worker_busy( @@ -505,6 +519,7 @@ impl RoutingHost { /// guard. On success the session-affinity hold, if any, is committed to the /// worker and its lease moves into the guard; a failed send under hard /// affinity invalidates a hold whose target is no longer valid. + #[allow(clippy::too_many_arguments)] pub(super) async fn dispatch_selection( &self, request: SingleIn, @@ -513,6 +528,7 @@ impl RoutingHost { mut guard: RequestGuard, budget: &CleanupBudget, affinity: Option, + dispatch_prepare: Option, ) -> Result>, Error> { let context_id = request.context().id().to_string(); let request_context = request.context().clone(); @@ -526,6 +542,7 @@ impl RoutingHost { backend_input.routing_mut().dp_rank = Some(selection.worker.dp_rank); backend_input.kv_hint = selection.kv_hint; let updated_request = context.map(|_| backend_input); + drop(dispatch_prepare); guard.begin_dispatch(&phase_label, updated_request.content()); let dispatch = self diff --git a/lib/llm/src/kv_router/routing_host/request_guard.rs b/lib/llm/src/kv_router/routing_host/request_guard.rs index 6b47e471638e..8f4e37f45e6b 100644 --- a/lib/llm/src/kv_router/routing_host/request_guard.rs +++ b/lib/llm/src/kv_router/routing_host/request_guard.rs @@ -17,8 +17,10 @@ use crate::{ preprocessor::PreprocessedRequest, protocols::common::{ llm_backend::LLMEngineOutput, + observation::StageObservation, preprocessor::MigrationState, timing::{RequestPhase, RequestTracker}, + ttft::{TtftSpan, TtftStage, TtftTimings}, }, }; use dynamo_kv_router::{ @@ -32,10 +34,7 @@ use dynamo_kv_router::{ services::selection::affinity::AffinityLease, }; use dynamo_runtime::{ - error::DynamoError, - metrics::frontend_perf::{STAGE_DISPATCH, StageGuard}, - pipeline::OccupancyReservation, - protocols::annotated::Annotated, + error::DynamoError, pipeline::OccupancyReservation, protocols::annotated::Annotated, }; pub(super) struct LoraLoadGuard { @@ -278,6 +277,85 @@ impl CanonicalOutputTracker { } } +/// Captures the dispatch phase before prefill and decode can run concurrently. +/// Span handles are consumed at the first response/token, so later tokens do +/// not read the clock or lock the TTFT timeline. +struct DispatchTimings { + phase: RequestPhase, + timings: Option>, + backend: Option, + first_token: Option, + postprocess: Option, +} + +impl DispatchTimings { + fn new(phase: RequestPhase, timings: Option>) -> Self { + Self { + phase, + timings, + backend: None, + first_token: None, + postprocess: None, + } + } + + fn start(&mut self) { + let stage = match self.phase { + RequestPhase::Prefill => TtftStage::BackendPrefill, + RequestPhase::Decode => TtftStage::BackendDecode, + RequestPhase::Aggregated => TtftStage::BackendAggregated, + }; + self.backend = Some(StageObservation::new(stage, self.timings.as_ref())); + } + + fn observe_response(&mut self, has_tokens: bool) { + if let Some(backend) = self.backend.take() { + drop(backend); + // If the first response already carries tokens, there is no + // separate first-response-to-first-token interval. + if !has_tokens && let Some(timings) = &self.timings { + let stage = match self.phase { + RequestPhase::Prefill => TtftStage::FirstTokenPrefill, + RequestPhase::Decode => TtftStage::FirstTokenDecode, + RequestPhase::Aggregated => TtftStage::FirstTokenAggregated, + }; + self.first_token = Some(timings.start_span(stage)); + } + } + } + + fn observe_first_token(&mut self) { + self.first_token.take(); + if self.phase != RequestPhase::Prefill + && let Some(timings) = &self.timings + { + self.postprocess = Some(timings.start_span(TtftStage::ResponsePostprocess)); + } + } + + fn finish(&mut self) { + if let Some(backend) = self.backend.as_mut() { + backend.end_timing(); + } + self.first_token.take(); + // A successful single-token stream can end before Python/HTTP sees it. + // Preserve forwarding time after the dispatch guard is dropped. + if let Some(postprocess) = self.postprocess.take() { + postprocess.leave_open(); + } + } + + fn abort(&mut self) { + if let Some(backend) = self.backend.as_mut() { + backend.end_timing(); + } + self.first_token.take(); + // A terminal frame may contain tokens that are withheld then discarded + // on a migratable error. It must not mask the next attempt's routing/wait. + self.postprocess.take(); + } +} + /// Owns request-scoped timing and metrics state. struct RequestObservability { tracker: Option>, @@ -285,23 +363,25 @@ struct RequestObservability { cumulative_osl: usize, metrics_recorded: bool, first_token_recorded: bool, - dispatch_guard: Option, dispatched: bool, + ttft: DispatchTimings, } impl RequestObservability { fn new( - tracker: Option>, + request: &PreprocessedRequest, request_metrics: Arc, + phase: RequestPhase, ) -> Self { + let timings = request.ttft_timings().cloned(); Self { - tracker, + tracker: request.tracker.clone(), request_metrics, cumulative_osl: 0, metrics_recorded: false, first_token_recorded: false, - dispatch_guard: None, dispatched: false, + ttft: DispatchTimings::new(phase, timings), } } @@ -310,7 +390,8 @@ impl RequestObservability { } fn start_dispatch(&mut self, phase_label: &str) { - self.dispatch_guard = Some(StageGuard::new(STAGE_DISPATCH, phase_label)); + debug_assert_eq!(phase_label, self.ttft.phase.as_str()); + self.ttft.start(); } /// Record prefill start for dispatches that actually run prefill. @@ -337,9 +418,10 @@ impl RequestObservability { self.dispatched = true; } - fn observe_response(&mut self) { - // Taking the guard ends dispatch latency exactly once; later responses see None. - self.dispatch_guard.take(); + fn observe_response(&mut self, has_tokens: bool) { + // The shared dispatch handle closes the legacy gauge and TTFT parent + // on this first response, including tokenless control responses. + self.ttft.observe_response(has_tokens); } fn observe_tokens(&mut self, new_tokens: usize) { @@ -665,7 +747,7 @@ impl RequestGuard { .map(|_| CanonicalOutputTracker::new(request, block_size as u32, chooser.is_eagle())); Self { cleanup: RequestCleanup::Kv(cleanup), - observability: RequestObservability::new(request.tracker.clone(), request_metrics), + observability: RequestObservability::new(request, request_metrics, phase), output_blocks: OutputBlockTracker::new( track_output_blocks, isl_tokens, @@ -689,6 +771,7 @@ impl RequestGuard { occupancy_reservation: Option, lora_load: Option, request: &PreprocessedRequest, + phase: RequestPhase, ) -> Self { request_metrics.requests_started_total.inc(); Self { @@ -699,7 +782,7 @@ impl RequestGuard { }, None => RequestCleanup::Stateless { worker_id }, }, - observability: RequestObservability::new(request.tracker.clone(), request_metrics), + observability: RequestObservability::new(request, request_metrics, phase), // Builtin policies do not track scheduler blocks. Emit one final ITL sample // when the request completes rather than observing every streamed token. output_blocks: OutputBlockTracker::new(false, request.token_ids.len(), 1, None), @@ -784,8 +867,13 @@ impl RequestGuard { /// accounting depends on: liveness, the classifier, the prefill boundary, /// output-block hashes, observability, then output-block load. pub(super) async fn on_item(&mut self, item: &Annotated) { - self.observability.observe_response(); let new_tokens = item.data.as_ref().map_or(0, |data| data.token_ids.len()); + // Detail observes arrival before async work. Keep legacy token metrics + // at their original point below, after scheduler/output processing. + self.observability.observe_response(new_tokens > 0); + if !self.observability.first_token_recorded && new_tokens > 0 { + self.observability.ttft.observe_first_token(); + } self.touch_request_lease(new_tokens); self.observe_classifier(item, new_tokens); self.mark_prefill_on_first_tokens(item).await; @@ -913,6 +1001,7 @@ impl RequestGuard { self.observability .record_metrics(self.record_itl_at_completion); self.cleanup.finish().await; + self.observability.ttft.finish(); } /// The attempt did not finish: the client left, the worker failed, or the @@ -923,6 +1012,7 @@ impl RequestGuard { lifecycle.abort(cause.map(crate::protocols::common::preprocessor::owned_abort_error)); } self.cleanup.finish().await; + self.observability.ttft.abort(); } pub(super) async fn release_for_retry(&mut self) -> bool { @@ -935,6 +1025,7 @@ impl RequestGuard { lifecycle.prepare_retry(); migration_state.store_request_lifecycle(lifecycle); self.cleanup.finish().await; + self.observability.ttft.abort(); true } @@ -1229,8 +1320,7 @@ mod prefill_start_tests { let tracker = Arc::new(RequestTracker::new()); let _permit = tracker.set_phase(phase).await; let request = test_request(tracker.clone(), annotations); - RequestObservability::new(request.tracker.clone(), test_metrics()) - .record_prefill_start(&request); + RequestObservability::new(&request, test_metrics(), phase).record_prefill_start(&request); tracker } @@ -1274,14 +1364,172 @@ mod prefill_start_tests { let request = test_request(tracker.clone(), Vec::new()); let prefill_permit = tracker.set_phase(RequestPhase::Prefill).await; - RequestObservability::new(Some(tracker.clone()), metrics.clone()) + RequestObservability::new(&request, metrics.clone(), RequestPhase::Prefill) .record_prefill_start(&request); let recorded_by_prefill = tracker.prefill_wait_time_ms(); assert!(recorded_by_prefill.is_some()); drop(prefill_permit); let _decode_permit = tracker.set_phase(RequestPhase::Decode).await; - RequestObservability::new(Some(tracker.clone()), metrics).record_prefill_start(&request); + RequestObservability::new(&request, metrics, RequestPhase::Decode) + .record_prefill_start(&request); assert_eq!(tracker.prefill_wait_time_ms(), recorded_by_prefill); } } + +#[cfg(test)] +mod ttft_tests { + use super::*; + use std::time::{Duration, Instant}; + + fn request_without_tracker() -> PreprocessedRequest { + PreprocessedRequest::builder() + .model("test".to_string()) + .token_ids(vec![1]) + .stop_conditions(Default::default()) + .sampling_options(Default::default()) + .output_options(Default::default()) + .build() + .unwrap() + } + + #[tokio::test] + async fn detail_without_tracker_preserves_legacy_ttft_sample_population() { + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let mut request = request_without_tracker(); + request.ttft = Some(timeline.clone()); + let metrics = RouterRequestMetrics::for_test(&dynamo_runtime::MetricsRegistry::new()); + let mut guard = RequestGuard::new_builtin( + metrics.clone(), + 1, + None, + None, + &request, + RequestPhase::Aggregated, + ); + guard.begin_dispatch("aggregated", &request); + guard + .on_item(&Annotated::from_data(LLMEngineOutput { + token_ids: vec![2], + ..Default::default() + })) + .await; + assert!(request.tracker.is_none()); + assert!(guard.observability.tracker.is_none()); + assert_eq!(metrics.time_to_first_token_seconds.get_sample_count(), 0); + let end = Instant::now(); + let stages = timeline.finish(end); + assert!(stages[TtftStage::BackendAggregated as usize] > Duration::ZERO); + assert_eq!(stages.into_iter().sum::(), end - start); + } + + #[test] + fn first_token_keeps_postprocessing_open_after_dispatch_is_dropped() { + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let mut dispatch = DispatchTimings::new(RequestPhase::Decode, Some(timeline.clone())); + dispatch.start(); + dispatch.observe_response(true); + dispatch.observe_first_token(); + dispatch.finish(); + drop(dispatch); + let end = Instant::now() + Duration::from_secs(1); + let stages = timeline.finish(end); + assert_eq!(stages[TtftStage::FirstTokenDecode as usize], Duration::ZERO); + assert!(stages[TtftStage::ResponsePostprocess as usize] >= Duration::from_secs(1)); + assert_eq!(stages.into_iter().sum::(), end - start); + } + + #[test] + fn control_response_starts_a_distinct_wait_for_the_first_token() { + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let mut dispatch = DispatchTimings::new(RequestPhase::Aggregated, Some(timeline.clone())); + dispatch.start(); + dispatch.observe_response(false); + // Freeze while waiting for a token: metadata alone must not begin postprocessing. + let end = Instant::now() + Duration::from_secs(1); + let stages = timeline.finish(end); + assert!(stages[TtftStage::FirstTokenAggregated as usize] >= Duration::from_secs(1)); + assert_eq!( + stages[TtftStage::ResponsePostprocess as usize], + Duration::ZERO + ); + assert_eq!(stages.into_iter().sum::(), end - start); + dispatch.observe_response(true); + dispatch.observe_first_token(); + assert_eq!(timeline.finish(end + Duration::from_secs(1)), stages); + } + + #[tokio::test] + async fn discarded_terminal_tokens_do_not_mask_retry_backend_wait() { + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let tracker = Arc::new(RequestTracker::new()); + tracker.set_ttft(timeline.clone()); + let request = PreprocessedRequest::builder() + .model("test".to_string()) + .token_ids(vec![1]) + .stop_conditions(Default::default()) + .sampling_options(Default::default()) + .output_options(Default::default()) + .tracker(Some(tracker)) + .build() + .unwrap(); + let metrics = RouterRequestMetrics::for_test(&dynamo_runtime::MetricsRegistry::new()); + let mut guard = + RequestGuard::new_builtin(metrics, 1, None, None, &request, RequestPhase::Aggregated); + guard.begin_dispatch("aggregated", &request); + // monitor_response_stream withholds this token-bearing terminal frame; + // a following migratable error discards it before HTTP sees a token. + guard + .on_item(&Annotated::from_data(LLMEngineOutput { + token_ids: vec![2], + finish_reason: Some(crate::protocols::common::FinishReason::Cancelled), + ..Default::default() + })) + .await; + guard.abort(None).await; + // The previous guard can still exist while Migration starts another attempt. + let _retry_route = timeline.start_span(TtftStage::RouteAggregated); + drop(_retry_route); + let _retry_backend = timeline.start_span(TtftStage::BackendAggregated); + let end = Instant::now() + Duration::from_secs(1); + let stages = timeline.finish(end); + assert!(stages[TtftStage::BackendAggregated as usize] >= Duration::from_secs(1)); + assert_eq!(stages.into_iter().sum::(), end - start); + } + + #[tokio::test] + async fn late_prefill_token_uses_dispatch_phase_after_decode_starts() { + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let tracker = Arc::new(RequestTracker::new()); + tracker.set_ttft(timeline.clone()); + drop(tracker.set_phase(RequestPhase::Prefill).await); + let metrics = RouterRequestMetrics::for_test(&dynamo_runtime::MetricsRegistry::new()); + let mut request = request_without_tracker(); + request.tracker = Some(tracker.clone()); + let mut observability = RequestObservability::new(&request, metrics, RequestPhase::Prefill); + observability.start_dispatch("prefill"); + drop(tracker.set_phase(RequestPhase::Decode).await); + observability.observe_response(true); + observability.ttft.observe_first_token(); + // Only the new attribution snapshots the dispatch phase. Legacy timing + // continues to observe the tracker's current phase at its old boundary. + tracker.record_prefill_complete(); + observability.observe_tokens(1); + assert!(tracker.kv_transfer_estimated_latency_secs().is_some()); + let end = Instant::now() + Duration::from_secs(1); + let stages = timeline.finish(end); + assert!(stages[TtftStage::BackendPrefill as usize] > Duration::ZERO); + assert_eq!(stages[TtftStage::BackendDecode as usize], Duration::ZERO); + assert_eq!(stages[TtftStage::FirstTokenDecode as usize], Duration::ZERO); + assert_eq!( + stages[TtftStage::ResponsePostprocess as usize], + Duration::ZERO + ); + assert_eq!(stages.into_iter().sum::(), end - start); + } +} diff --git a/lib/llm/src/kv_router/routing_host/tests.rs b/lib/llm/src/kv_router/routing_host/tests.rs index db392ac1f3b1..4618bb6bd749 100644 --- a/lib/llm/src/kv_router/routing_host/tests.rs +++ b/lib/llm/src/kv_router/routing_host/tests.rs @@ -167,6 +167,7 @@ async fn builtin_host_constructs_only_declared_capabilities() { Some(selection.reservation), None, &request(), + RequestPhase::Aggregated, ); assert_eq!(guard.retarget_worker(1), Some(1)); guard.abort(None).await; @@ -2061,6 +2062,7 @@ async fn kv_cancellation_after_admission_still_stops_the_aggregated_dispatch() { guard, &CleanupBudget::default(), None, + None, ) .await .expect_err("aggregated dispatch must still be cancelled before it is issued"); @@ -2973,6 +2975,7 @@ async fn router_request_counters_follow_admission_and_completion_lifecycle() { failed_dispatch_guard, &CleanupBudget::default(), None, + None, ) .await .is_err() @@ -2989,8 +2992,14 @@ async fn router_request_counters_follow_admission_and_completion_lifecycle() { assert_eq!(metrics.requests_started_total.get(), 3); assert_eq!(metrics.requests_total.get(), 1); - let mut builtin_guard = - RequestGuard::new_builtin(Arc::clone(&metrics), 7, None, None, &request()); + let mut builtin_guard = RequestGuard::new_builtin( + Arc::clone(&metrics), + 7, + None, + None, + &request(), + RequestPhase::Aggregated, + ); assert_eq!(metrics.requests_started_total.get(), 4); builtin_guard.abort(None).await; drop(builtin_guard); @@ -4916,6 +4925,33 @@ async fn hard_parent_group_recovers_when_the_bound_worker_leaves() { runtime.shutdown(); } +#[test] +fn ttft_route_selection_transitions_to_dispatch_preparation() { + use crate::protocols::common::ttft::TtftTimings; + + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let mut timed_request = request(); + timed_request.ttft = Some(timeline.clone()); + let route_guard = start_route(&timed_request, RequestPhase::Decode); + let preparation = route_selection_finished(route_guard, &timed_request, RequestPhase::Decode); + let preparation_started = Instant::now(); + // Preparation wins over a concurrent backend interval in the exclusive view. + let _dispatch = timeline.start_span(TtftStage::BackendDecode); + let end = preparation_started + Duration::from_secs(1); + let stages = timeline.finish(end); + assert!(stages[TtftStage::DispatchPrepareDecode as usize] >= Duration::from_secs(1)); + assert_eq!(stages[TtftStage::BackendDecode as usize], Duration::ZERO); + assert!(stages[TtftStage::RouteDecode as usize] <= preparation_started - start); + assert_eq!(stages.iter().sum::(), end - start); + drop(preparation); + assert_eq!(timeline.finish(end + Duration::from_secs(1)), stages); + + let untimed_request = request(); + let route = start_route(&untimed_request, RequestPhase::Decode); + assert!(route_selection_finished(route, &untimed_request, RequestPhase::Decode).is_none()); +} + /// A prefill `prepare` failure gives the booking back before a guard exists, so /// the request never counts as started and leaves no load behind. #[tokio::test] @@ -5051,3 +5087,49 @@ async fn committed_session_lease_lives_as_long_as_the_response_stream() { drop(router); runtime.shutdown(); } + +#[tokio::test] +#[serial_test::serial] +async fn aborted_prefill_plan_closes_preparation_before_decode_retry() { + use crate::protocols::common::ttft::TtftTimings; + + let (router, runtime) = router(None).await; + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let mut timed_request = request(); + assert_ne!(timed_request.phase(), RequestPhase::Prefill); + timed_request.ttft = Some(timeline.clone()); + let request = Context::new(timed_request); + let plan = router + .plan_kv_route( + &request, + RequestPhase::Prefill, + None, + CleanupBudget::default(), + ) + .await + .unwrap(); + plan.abort(None).await; + + let _retry_backend = timeline.start_span(TtftStage::BackendDecode); + let end = Instant::now() + Duration::from_secs(1); + let stages = timeline.finish(end); + assert!(stages[TtftStage::DispatchPreparePrefill as usize] > Duration::ZERO); + assert_eq!( + stages[TtftStage::DispatchPrepareAggregated as usize], + Duration::ZERO + ); + assert_eq!( + stages[TtftStage::DispatchPrepareDecode as usize], + Duration::ZERO + ); + assert!(stages[TtftStage::BackendDecode as usize] >= Duration::from_secs(1)); + assert_eq!(stages.iter().sum::(), end - start); + assert_eq!( + active_requests_for(&potential_loads(&router).await, 7, 0), + 0 + ); + assert_eq!(router.request_metrics.requests_started_total.get(), 0); + drop(router); + runtime.shutdown(); +} diff --git a/lib/llm/src/preprocessor.rs b/lib/llm/src/preprocessor.rs index 9de3e9649f6a..ecacc53c8099 100644 --- a/lib/llm/src/preprocessor.rs +++ b/lib/llm/src/preprocessor.rs @@ -71,11 +71,13 @@ use crate::model_card::{ModelDeploymentCard, ModelInfo, PromptFormatterArtifact} #[cfg(feature = "mm-routing")] use crate::preprocessor::media::MediaFetcher; use crate::preprocessor::media::{MediaDecoder, MediaLoader, max_data_url_bytes}; +use crate::protocols::common::observation::{StageObservation, observe_operation}; use crate::protocols::common::preprocessor::{ MultimodalData, MultimodalDataMap, MultimodalItemRef, MultimodalUuidMap, PreprocessedRequestBuilder, RoutingHints, }; use crate::protocols::common::timing::RequestTracker; +use crate::protocols::common::ttft::{TTFT_CONTEXT_KEY, TtftStage, TtftTimings}; use crate::tokenizers::Encoding; use dynamo_parsers::{ @@ -1726,6 +1728,16 @@ fn attach_image_cache_scope_from_context( } } +/// Retain the response generator's tracker while sharing the HTTP first-token timeline. +fn attach_ttft_tracker( + tracker: &RequestTracker, + context: &PipelineContext, +) { + if let Ok(timings) = context.get::>(TTFT_CONTEXT_KEY) { + tracker.set_ttft(Arc::clone(timings.as_ref())); + } +} + fn attach_request_context_metadata( request: &mut PreprocessedRequest, context: &PipelineContext<()>, @@ -3475,7 +3487,14 @@ impl OpenAIPreprocessor { off_runtime(|| self.apply_template_and_prefill(request)) .with_context(|| "Failed to apply prompt template")? }; - TEMPLATE_SECONDS.observe(template_start.elapsed().as_secs_f64()); + let template_elapsed = template_start.elapsed(); + observe_operation( + &TEMPLATE_SECONDS, + TtftStage::TemplateRender, + template_start, + template_elapsed, + tracker.and_then(RequestTracker::ttft), + ); let tokenize_start = Instant::now(); let (token_ids, annotations) = { @@ -3484,7 +3503,14 @@ impl OpenAIPreprocessor { .await .with_context(|| "Failed to gather tokens")? }; - TOKENIZE_SECONDS.observe(tokenize_start.elapsed().as_secs_f64()); + let tokenize_elapsed = tokenize_start.elapsed(); + observe_operation( + &TOKENIZE_SECONDS, + TtftStage::Tokenize, + tokenize_start, + tokenize_elapsed, + tracker.and_then(RequestTracker::ttft), + ); let (_mm_routing_entries, image_tokens) = self .gather_multi_modal_data_with_image_tokens( @@ -3492,6 +3518,7 @@ impl OpenAIPreprocessor { &mut builder, formatted_prompt.as_ref().map(RenderedPrompt::as_str), &token_ids, + tracker, ) .await .with_context(|| "Failed to gather multimodal data")?; @@ -3501,9 +3528,15 @@ impl OpenAIPreprocessor { // moves once. builder.token_ids(token_ids); - STAGE_DURATION_SECONDS - .with_label_values(&[STAGE_PREPROCESS]) - .observe(preprocess_start.elapsed().as_secs_f64()); + let preprocess_histogram = STAGE_DURATION_SECONDS.with_label_values(&[STAGE_PREPROCESS]); + let preprocess_elapsed = preprocess_start.elapsed(); + observe_operation( + &preprocess_histogram, + TtftStage::Preprocess, + preprocess_start, + preprocess_elapsed, + tracker.and_then(RequestTracker::ttft), + ); if let Some(nvext) = request.nvext() && let Some(router_params) = &nvext.router @@ -4137,6 +4170,7 @@ impl OpenAIPreprocessor { builder, formatted_prompt, token_ids, + None, ) .await?; Ok(entries @@ -4164,6 +4198,7 @@ impl OpenAIPreprocessor { builder: &mut PreprocessedRequestBuilder, formatted_prompt: Option<&str>, token_ids: &[crate::protocols::TokenIdType], + tracker: Option<&RequestTracker>, ) -> Result<(Vec, Option)> { // `token_ids` is only consumed by exact MM-routing construction below. #[cfg(not(feature = "mm-routing"))] @@ -4217,6 +4252,7 @@ impl OpenAIPreprocessor { return Ok((Vec::new(), None)); }; let has_media_loader = self.media_loader.is_some(); + let mut ttft_multimodal = None; let message_order = self.formatter.media_message_order(request); for index in 0..messages.len() { @@ -4228,6 +4264,11 @@ impl OpenAIPreprocessor { let Some((type_str, url, uuid)) = content_part.media_info() else { continue; }; + if ttft_multimodal.is_none() { + ttft_multimodal = tracker + .and_then(RequestTracker::ttft) + .map(|timings| timings.start_span(TtftStage::MultimodalPrepare)); + } #[cfg(feature = "mm-routing")] if type_str == "image_url" { @@ -4608,6 +4649,11 @@ impl OpenAIPreprocessor { extra_args_obj.extend(backend_extra_args); } + #[cfg(feature = "mm-routing")] + let _ttft_routing = tracker + .and_then(RequestTracker::ttft) + .map(|timings| timings.start_span(TtftStage::MmRoutingBuild)); + // Build and install routing info + worker hashes atomically. If any // mixed-media precondition misses, neither side receives exact keys // and the request cleanly uses text-prefix routing. @@ -8595,7 +8641,9 @@ impl // create a response generator let response_generator = request.response_generator(context.id().to_string()); - let tracker = Some(response_generator.tracker()); + let request_tracker = response_generator.tracker(); + attach_ttft_tracker(&request_tracker, &context); + let tracker = Some(request_tracker); let preprocess_options = PreprocessRequestOptions { preserve_omitted_max_tokens: context .get::(PRESERVE_OMITTED_MAX_TOKENS_CONTEXT_KEY) @@ -8622,11 +8670,19 @@ impl } attach_request_context_metadata(&mut common_request, &context); - let guided_tool_constraint = self.apply_tool_choice_guided_decoding( - &request, - &mut common_request, - prompt_injected_reasoning.clone(), - )?; + let guided_tool_constraint = { + // Constraint construction happens after the legacy preprocess + // operation. Give it its own boundary without extending that metric. + let _structural_tag = tracker + .as_deref() + .and_then(RequestTracker::ttft) + .map(|timings| timings.start_span(TtftStage::StructuralTagBuild)); + self.apply_tool_choice_guided_decoding( + &request, + &mut common_request, + prompt_injected_reasoning.clone(), + )? + }; let tool_processing_route = self.tool_processing_route(&request, &guided_tool_constraint)?; let payload_parsing_options = payload_handle.as_ref().map(|_| { @@ -8793,7 +8849,8 @@ impl dyn AsyncEngine, ManyOut>, Error>, >, ) -> Result>, Error> { - let _stage_guard = StageGuard::new(STAGE_PREPROCESS, ""); + let timings = request.get::>(TTFT_CONTEXT_KEY).ok(); + let _stage_guard = StageObservation::new(TtftStage::Preprocess, timings.as_deref()); // unpack the request let (mut request, context) = request.into_parts(); @@ -8812,7 +8869,9 @@ impl // create a response generator let response_generator = request.response_generator(request_id.clone()); let mut response_generator = Box::new(response_generator); - let tracker = Some(response_generator.tracker()); + let request_tracker = response_generator.tracker(); + attach_ttft_tracker(&request_tracker, &context); + let tracker = Some(request_tracker); // convert the chat completion request to a common completion request let mut builder = self.builder_with_lora( &request, @@ -8833,9 +8892,14 @@ impl } else { // Normal path: tokenize the prompt; embeddings don't need MM routing, // so install tokens on the builder right away. + let _ttft_stage = tracker + .as_deref() + .and_then(RequestTracker::ttft) + .map(|timings| timings.start_span(TtftStage::Tokenize)); let (token_ids, ann) = self .gather_tokens(&request, None, tracker.as_deref()) .await?; + drop(_ttft_stage); builder.token_ids(token_ids); ann }; @@ -9561,7 +9625,7 @@ mod extra_args_media_copy_tests { .output_options(Default::default()); preprocessor - .gather_multi_modal_data_with_image_tokens(&request, &mut builder, None, &[]) + .gather_multi_modal_data_with_image_tokens(&request, &mut builder, None, &[], None) .await .unwrap(); let result = builder.build().unwrap(); @@ -9636,7 +9700,7 @@ mod extra_args_media_copy_tests { .sampling_options(Default::default()) .output_options(Default::default()); preprocessor - .gather_multi_modal_data_with_image_tokens(&request, &mut builder, None, &[]) + .gather_multi_modal_data_with_image_tokens(&request, &mut builder, None, &[], None) .await .unwrap(); let result = builder.build().unwrap(); @@ -14182,7 +14246,7 @@ responses_tools: None, .output_options(Default::default()); let (routing_entries, _) = preprocessor - .gather_multi_modal_data_with_image_tokens(&request, &mut builder, None, &[]) + .gather_multi_modal_data_with_image_tokens(&request, &mut builder, None, &[], None) .await .unwrap(); let preprocessed = builder.build().unwrap(); @@ -20436,6 +20500,106 @@ responses_tools: None, } } +#[cfg(test)] +mod ttft_tests { + use super::*; + use std::time::Duration; + + #[derive(Default)] + struct RecordingBackend(Mutex>>); + + #[async_trait] + impl AsyncEngine, ManyOut>, Error> + for RecordingBackend + { + async fn generate( + &self, + request: SingleIn, + ) -> Result>, Error> { + let wire = serde_json::to_value(request.content()).unwrap(); + assert!(wire.get("tracker").is_none()); + assert!(wire.get("ttft").is_none()); + self.0 + .lock() + .unwrap() + .push(request.tracker.clone().unwrap()); + Ok(ResponseStream::new( + Box::pin(stream::empty()), + request.context(), + )) + } + } + + #[tokio::test] + async fn native_chat_and_completion_share_http_ttft_with_the_router() { + let mdc = ModelDeploymentCard::load_from_disk( + "tests/data/sample-models/mock-llama-3.1-8b-instruct", + None, + ) + .unwrap(); + let preprocessor = OpenAIPreprocessor::new(mdc).unwrap(); + let backend = Arc::new(RecordingBackend::default()); + let next: Arc< + dyn AsyncEngine, ManyOut>, Error>, + > = backend.clone(); + + let chat: NvCreateChatCompletionRequest = serde_json::from_value(serde_json::json!({ + "model": "test-model", + "messages": [{"role": "user", "content": "Hello"}], + "max_tokens": 1 + })) + .unwrap(); + let chat_timeline = Arc::new(TtftTimings::new(Instant::now())); + let mut chat_context = PipelineContext::new(chat); + chat_context.insert(TTFT_CONTEXT_KEY, chat_timeline.clone()); + let chat_stream = Operator::generate(preprocessor.as_ref(), chat_context, next.clone()) + .await + .unwrap(); + drop(chat_stream); + + let completion: NvCreateCompletionRequest = serde_json::from_value(serde_json::json!({ + "model": "test-model", "prompt": "Hello", "max_tokens": 1 + })) + .unwrap(); + let completion_timeline = Arc::new(TtftTimings::new(Instant::now())); + let mut completion_context = PipelineContext::new(completion); + completion_context.insert(TTFT_CONTEXT_KEY, completion_timeline.clone()); + let completion_stream = Operator::generate(preprocessor.as_ref(), completion_context, next) + .await + .unwrap(); + drop(completion_stream); + + let trackers = backend.0.lock().unwrap(); + assert_eq!(trackers.len(), 2); + for (index, (tracker, timeline)) in trackers + .iter() + .zip([chat_timeline, completion_timeline]) + .enumerate() + { + assert!(Arc::ptr_eq(tracker.ttft().unwrap(), &timeline)); + let stages = timeline.finish(Instant::now()); + assert!(stages[TtftStage::Tokenize as usize] > Duration::ZERO); + assert!(stages[TtftStage::Preprocess as usize] > Duration::ZERO); + assert_eq!(stages[TtftStage::TemplateTokenize as usize], Duration::ZERO); + if index == 0 { + assert!(stages[TtftStage::TemplateRender as usize] > Duration::ZERO); + assert!(stages[TtftStage::StructuralTagBuild as usize] > Duration::ZERO); + } else { + assert_eq!(stages[TtftStage::TemplateRender as usize], Duration::ZERO); + assert_eq!( + stages[TtftStage::StructuralTagBuild as usize], + Duration::ZERO + ); + } + assert_eq!( + stages[TtftStage::MultimodalPrepare as usize], + Duration::ZERO + ); + assert_eq!(stages[TtftStage::MmRoutingBuild as usize], Duration::ZERO); + } + } +} + #[cfg(test)] mod beam_route_tests { use super::*; diff --git a/lib/llm/src/preprocessor/mm_routing/image.rs b/lib/llm/src/preprocessor/mm_routing/image.rs index 4ca9c08d5a9e..d1c995867e1a 100644 --- a/lib/llm/src/preprocessor/mm_routing/image.rs +++ b/lib/llm/src/preprocessor/mm_routing/image.rs @@ -701,7 +701,7 @@ mod tests { .sampling_options(Default::default()) .output_options(Default::default()); let (_, image_tokens) = preprocessor - .gather_multi_modal_data_with_image_tokens(&request, &mut builder, None, &ids) + .gather_multi_modal_data_with_image_tokens(&request, &mut builder, None, &ids, None) .await .unwrap(); let result = builder.build().unwrap(); diff --git a/lib/llm/src/protocols/common.rs b/lib/llm/src/protocols/common.rs index 2e79190426a7..f6130fa2a7a5 100644 --- a/lib/llm/src/protocols/common.rs +++ b/lib/llm/src/protocols/common.rs @@ -60,9 +60,11 @@ pub mod input_trigger; pub mod llm_backend; pub mod metadata_upload; pub mod metrics; +pub(crate) mod observation; pub mod postprocessor; pub mod preprocessor; pub mod timing; +pub mod ttft; /// SamplingOptionsProvider is a trait that allows the caller to extract the sampling options from /// the object that implements it. This will mutate the object. diff --git a/lib/llm/src/protocols/common/observation.rs b/lib/llm/src/protocols/common/observation.rs new file mode 100644 index 000000000000..9266e3b0acb1 --- /dev/null +++ b/lib/llm/src/protocols/common/observation.rs @@ -0,0 +1,140 @@ +// SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +//! Adapters for observations that share a lifecycle boundary. +//! +//! The existing inflight gauge and inclusive operation histogram retain their +//! own populations and boundaries. Optional TTFT intervals reuse those events; +//! only the TTFT partition subtracts nested work. + +use std::{ + sync::Arc, + time::{Duration, Instant}, +}; + +use dynamo_runtime::metrics::frontend_perf::StageGuard; +use prometheus::Histogram; + +use super::ttft::{TtftSpan, TtftStage, TtftTimings}; + +/// One shared entry/exit for a legacy gauge and an optional TTFT interval. +/// Diagnostic-only stages have no legacy gauge in the canonical registry. +pub(crate) struct StageObservation { + _legacy: Option, + _ttft: Option, +} + +impl StageObservation { + pub(crate) fn new(stage: TtftStage, timings: Option<&Arc>) -> Self { + let descriptor = stage.descriptor(); + Self { + _legacy: descriptor + .legacy_stage + .map(|legacy| StageGuard::new(legacy, descriptor.labels[1])), + _ttft: timings.map(|timings| timings.start_span(stage)), + } + } + + /// Failed/empty attempts end diagnostic timing before cleanup completes. + /// Keep their legacy gauge alive until its original response/drop boundary. + pub(crate) fn end_timing(&mut self) { + self._ttft.take(); + } +} + +/// Record a completed legacy operation and reuse its measured interval. +/// Call only at the original success boundary, never from a Drop guard: errors +/// must not gain new legacy histogram samples. +pub(crate) fn observe_operation( + histogram: &Histogram, + stage: TtftStage, + start: Instant, + elapsed: Duration, + timings: Option<&Arc>, +) { + histogram.observe(elapsed.as_secs_f64()); + if let Some(timings) = timings { + timings.record_duration(stage, start, elapsed); + } +} + +#[cfg(test)] +mod tests { + use super::*; + use dynamo_runtime::metrics::frontend_perf::STAGE_REQUESTS; + use prometheus::HistogramOpts; + + #[test] + fn ttft_operation_reuses_inclusive_samples_without_changing_buckets() { + let histogram = Histogram::with_opts( + HistogramOpts::new("operation_adapter_test", "test").buckets(vec![0.01, 0.1, 1.0]), + ) + .unwrap(); + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let elapsed = Duration::from_millis(100); + // The same legacy observation is made with detail off and on. + observe_operation(&histogram, TtftStage::TemplateRender, start, elapsed, None); + observe_operation( + &histogram, + TtftStage::TemplateRender, + start, + elapsed, + Some(&timeline), + ); + // Nested work changes only exclusive attribution, not legacy samples. + timeline.record_duration( + TtftStage::StructuralTagBuild, + start + Duration::from_millis(40), + Duration::from_millis(20), + ); + let stages = timeline.finish(start + elapsed); + assert_eq!(histogram.get_sample_count(), 2); + assert_eq!(histogram.get_sample_sum(), 0.2); + assert_eq!( + stages[TtftStage::TemplateRender as usize], + Duration::from_millis(80) + ); + assert_eq!( + stages[TtftStage::StructuralTagBuild as usize], + Duration::from_millis(20) + ); + use prometheus::core::Collector; + let families = histogram.collect(); + let buckets = families[0].get_metric()[0].get_histogram().get_bucket(); + assert_eq!( + buckets + .iter() + .map(|bucket| bucket.upper_bound()) + .collect::>(), + vec![0.01, 0.1, 1.0] + ); + assert_eq!( + buckets + .iter() + .map(|bucket| bucket.cumulative_count()) + .collect::>(), + vec![0, 2, 2] + ); + } + + #[test] + fn ttft_abort_ends_timing_but_preserves_legacy_gauge_until_drop() { + // A unique label isolates the global gauge from concurrent router tests. + let gauge = STAGE_REQUESTS.with_label_values(&["dispatch", "ttft_adapter_abort_test"]); + let start = Instant::now(); + let timeline = Arc::new(TtftTimings::new(start)); + let mut observation = StageObservation { + _legacy: Some(StageGuard::new("dispatch", "ttft_adapter_abort_test")), + _ttft: Some(timeline.start_span(TtftStage::BackendDecode)), + }; + assert_eq!(gauge.get(), 1); + observation.end_timing(); + assert_eq!(gauge.get(), 1); + let end = Instant::now() + Duration::from_secs(1); + let stages = timeline.finish(end); + assert!(stages[TtftStage::FrontendOverhead as usize] >= Duration::from_secs(1)); + drop(observation); + assert_eq!(gauge.get(), 0); + } +} diff --git a/lib/llm/src/protocols/common/preprocessor.rs b/lib/llm/src/protocols/common/preprocessor.rs index d3ca4a7d9258..1ab7772abed4 100644 --- a/lib/llm/src/protocols/common/preprocessor.rs +++ b/lib/llm/src/protocols/common/preprocessor.rs @@ -609,6 +609,12 @@ pub struct PreprocessedRequest { #[serde(skip)] pub tracker: Option>, + /// Optional HTTP diagnostics for Python requests without a legacy tracker. + /// Process-local only: clones share it, and worker payloads never carry it. + #[builder(default)] + #[serde(skip)] + pub ttft: Option>, + /// Set by the runtime's `HealthCheckManager` when this request originated /// from a canary probe. Engines may use it in `generate()` to bypass /// cross-worker coordination (KV transfer, bootstrap handshake, @@ -759,6 +765,12 @@ impl std::fmt::Debug for PreprocessedRequest { } impl PreprocessedRequest { + pub fn ttft_timings(&self) -> Option<&Arc> { + self.ttft + .as_ref() + .or_else(|| self.tracker.as_ref().and_then(|tracker| tracker.ttft())) + } + pub fn phase(&self) -> RequestPhase { self.tracker .as_ref() diff --git a/lib/llm/src/protocols/common/timing.rs b/lib/llm/src/protocols/common/timing.rs index 2a1a5f440160..ccf53f2d7e1a 100644 --- a/lib/llm/src/protocols/common/timing.rs +++ b/lib/llm/src/protocols/common/timing.rs @@ -88,6 +88,8 @@ impl std::fmt::Display for RequestPhase { /// accumulated detokenize timing, where lock-free updates are beneficial. #[derive(Debug)] pub struct RequestTracker { + /// Process-local frontend timeline, shared by preprocessing and routing. + ttft: OnceLock>, /// When the request was received (monotonic clock for duration calculations) request_received: Instant, @@ -237,6 +239,7 @@ impl RequestTracker { .unwrap_or(0); RequestTracker { + ttft: OnceLock::new(), request_received: now, request_received_epoch_ms: epoch_ms, prefill_start_time: OnceLock::new(), @@ -267,6 +270,15 @@ impl RequestTracker { } } + /// Attach the HTTP timeline without replacing an existing request timeline. + pub fn set_ttft(&self, timings: Arc) { + let _ = self.ttft.set(timings); + } + + pub fn ttft(&self) -> Option<&Arc> { + self.ttft.get() + } + /// Record when prefill started. Returns true if this was the first call. pub fn record_prefill_start(&self) -> bool { self.prefill_start_time.set(Instant::now()).is_ok() @@ -785,6 +797,20 @@ mod tests { use std::thread; use std::time::Duration; + #[test] + fn ttft_attachment_preserves_the_original_timeline_and_tracker_state() { + let tracker = RequestTracker::new(); + tracker.record_isl(12, Some(4)); + let timeline = Arc::new(super::super::ttft::TtftTimings::new(Instant::now())); + tracker.set_ttft(timeline.clone()); + tracker.set_ttft(Arc::new(super::super::ttft::TtftTimings::new( + Instant::now(), + ))); + assert!(Arc::ptr_eq(tracker.ttft().unwrap(), &timeline)); + assert_eq!(tracker.isl_tokens(), Some(12)); + assert_eq!(tracker.cached_tokens(), Some(4)); + } + #[test] fn test_record_isl_osl() { let tracker = RequestTracker::new(); diff --git a/lib/llm/src/protocols/common/ttft.rs b/lib/llm/src/protocols/common/ttft.rs new file mode 100644 index 000000000000..325089b11bd6 --- /dev/null +++ b/lib/llm/src/protocols/common/ttft.rs @@ -0,0 +1,979 @@ +// SPDX-FileCopyrightText: Copyright (c) 2025-2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +//! Exclusive wall-clock attribution for the frontend's existing HTTP TTFT interval. +//! +//! Record only stage boundaries. At the first HTTP token, a single event sweep +//! partitions the interval; nested and concurrent spans never double-count time. + +use std::sync::atomic::{AtomicBool, Ordering}; +use std::sync::{Arc, OnceLock}; +use std::time::{Duration, Instant}; + +use dynamo_runtime::metrics::frontend_perf::{STAGE_DISPATCH, STAGE_PREPROCESS, STAGE_ROUTE}; +use parking_lot::Mutex; + +/// Local pipeline context entry, shared with the Python processor and routed engine. +pub const TTFT_CONTEXT_KEY: &str = "frontend_ttft_timings"; + +/// Hard bounds apply before allocation and are independent of retry count. +pub const MAX_TTFT_INTERVALS: usize = 256; +pub const MAX_TTFT_BATCH_INTERVALS: usize = 64; + +/// Metadata shared by the legacy lifecycle adapter and exclusive attribution. +/// A diagnostic child has no legacy gauge of its own; its parent names the +/// operation whose residual it subtracts from in the TTFT view only. +#[derive(Debug, Clone, Copy)] +pub struct TtftStageDescriptor { + pub labels: [&'static str; 2], + pub parent: Option, + pub priority: u8, + pub python_enabled: bool, + pub legacy_stage: Option<&'static str>, +} + +macro_rules! stages { + ($( $variant:ident => ($label:expr, $phase:literal, $parent:expr, $priority:literal, $python:literal, $legacy:expr) ),+ $(,)?) => { + #[derive(Debug, Clone, Copy, PartialEq, Eq)] + #[repr(usize)] + pub enum TtftStage { $( $variant, )+ } + + impl TtftStage { + pub const ALL: [Self; <[()]>::len(&[$(stages!(@unit $variant)),+])] = [$(Self::$variant),+]; + + pub const fn descriptor(self) -> TtftStageDescriptor { + match self { + $(Self::$variant => TtftStageDescriptor { + labels: [$label, $phase], parent: $parent, + priority: $priority, python_enabled: $python, legacy_stage: $legacy, + }),+ + } + } + } + }; + (@unit $variant:ident) => { () }; +} + +// This is the sole stage/phase registry. Numeric IDs are the fixed order below; +// Python receives this table from the binding, never a separate whitelist. +// Keep existing IDs stable and append new entries. Greater priority wins. +stages! { + FrontendOverhead => ("frontend_overhead", "", None, 0, false, None), + Preprocess => (STAGE_PREPROCESS, "", None, 30, true, Some(STAGE_PREPROCESS)), + PreprocessQueue => ("preprocess_queue", "", Some(TtftStage::Preprocess), 31, true, None), + TemplateTokenize => ("template_tokenize", "", Some(TtftStage::Preprocess), 34, true, None), + MultimodalPrepare => ("multimodal_prepare", "", Some(TtftStage::Preprocess), 32, true, None), + MmRoutingBuild => ("mm_routing_build", "", Some(TtftStage::MultimodalPrepare), 33, true, None), + RoutePrefill => (STAGE_ROUTE, "prefill", None, 41, false, Some(STAGE_ROUTE)), + RouteDecode => (STAGE_ROUTE, "decode", None, 42, false, Some(STAGE_ROUTE)), + RouteAggregated => (STAGE_ROUTE, "aggregated", None, 40, false, Some(STAGE_ROUTE)), + BackendPrefill => (STAGE_DISPATCH, "prefill", None, 13, false, Some(STAGE_DISPATCH)), + BackendDecode => (STAGE_DISPATCH, "decode", None, 15, false, Some(STAGE_DISPATCH)), + BackendAggregated => (STAGE_DISPATCH, "aggregated", None, 11, false, Some(STAGE_DISPATCH)), + FirstTokenPrefill => ("first_token_wait", "prefill", None, 14, false, None), + FirstTokenDecode => ("first_token_wait", "decode", None, 16, false, None), + FirstTokenAggregated => ("first_token_wait", "aggregated", None, 12, false, None), + ResponsePostprocess => ("first_token_postprocess", "", None, 60, false, None), + BackendOverlap => ("backend_overlap", "prefill_decode", None, 20, false, None), + TemplateRender => ("template_render", "", Some(TtftStage::Preprocess), 36, true, None), + Tokenize => ("tokenize", "", Some(TtftStage::Preprocess), 35, true, None), + StructuralTagBuild => ("structural_tag_build", "", Some(TtftStage::Preprocess), 37, true, None), + DispatchPreparePrefill => ("dispatch_prepare", "prefill", Some(TtftStage::BackendPrefill), 51, false, None), + DispatchPrepareDecode => ("dispatch_prepare", "decode", Some(TtftStage::BackendDecode), 52, false, None), + DispatchPrepareAggregated => ("dispatch_prepare", "aggregated", Some(TtftStage::BackendAggregated), 50, false, None), + Unclassified => ("unclassified", "", None, 0, false, None), +} + +impl TtftStage { + pub const fn labels(self) -> [&'static str; 2] { + self.descriptor().labels + } + + pub const fn python_enabled(self) -> bool { + self.descriptor().python_enabled + } + + pub fn from_python(stage: &str) -> Option { + Self::ALL + .into_iter() + .find(|item| item.python_enabled() && item.labels()[0] == stage) + } + + pub fn from_python_id(id: usize) -> Option { + Self::ALL + .get(id) + .copied() + .filter(|stage| stage.python_enabled()) + } + + /// Preserve the phase captured at dispatch creation, including retries. + pub const fn dispatch_prepare(self) -> Option { + match self { + Self::RoutePrefill | Self::BackendPrefill | Self::FirstTokenPrefill => { + Some(Self::DispatchPreparePrefill) + } + Self::RouteDecode | Self::BackendDecode | Self::FirstTokenDecode => { + Some(Self::DispatchPrepareDecode) + } + Self::RouteAggregated | Self::BackendAggregated | Self::FirstTokenAggregated => { + Some(Self::DispatchPrepareAggregated) + } + _ => None, + } + } +} + +macro_rules! reasons { + ($name:ident { $($variant:ident => $label:literal),+ $(,)? }) => { + #[derive(Debug, Clone, Copy, PartialEq, Eq)] + pub enum $name { $($variant),+ } + impl $name { + pub const ALL: [Self; <[()]>::len(&[$(stages!(@unit $variant)),+])] = [$(Self::$variant),+]; + pub const fn as_str(self) -> &'static str { + match self { $(Self::$variant => $label),+ } + } + } + }; +} + +reasons! { TtftDegradedReason { + IntervalLimit => "interval_limit", + InvalidInterval => "invalid_interval", + InvalidBatch => "invalid_batch", + InvalidStage => "invalid_stage", + InvalidVersion => "invalid_version", + ClockMismatch => "clock_mismatch", + TimestampOverflow => "timestamp_overflow", + MissingTimeline => "missing_timeline", +} } +reasons! { TtftCoarseReason { + OpaqueTemplate => "opaque_template", + UnsupportedClock => "unsupported_clock", + MissingCoverage => "missing_coverage", +} } +reasons! { TtftQualityStatus { + Complete => "complete", + Coarse => "coarse", + Degraded => "degraded", +} } + +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct TtftQuality { + pub status: TtftQualityStatus, + pub degraded_reason: Option, + pub coarse_reason: Option, + pub unexpected_overlap: bool, +} + +impl Default for TtftQuality { + fn default() -> Self { + Self { + status: TtftQualityStatus::Complete, + degraded_reason: None, + coarse_reason: None, + unexpected_overlap: false, + } + } +} + +#[derive(Debug)] +struct Interval { + stage: TtftStage, + start: Duration, + end: Option, +} + +#[derive(Debug)] +struct TimelineState { + intervals: Vec, + quality: TtftQuality, +} + +impl TimelineState { + fn degrade(&mut self, reason: TtftDegradedReason) { + self.quality.status = TtftQualityStatus::Degraded; + self.quality.degraded_reason.get_or_insert(reason); + } + + fn push(&mut self, interval: Interval) -> Option { + if self.quality.degraded_reason.is_some() { + return None; + } + if self.intervals.len() >= MAX_TTFT_INTERVALS { + self.degrade(TtftDegradedReason::IntervalLimit); + return None; + } + if interval.stage == TtftStage::TemplateTokenize { + self.coarsen(TtftCoarseReason::OpaqueTemplate); + } + let index = self.intervals.len(); + self.intervals.push(interval); + Some(index) + } + + fn coarsen(&mut self, reason: TtftCoarseReason) { + self.quality.coarse_reason.get_or_insert(reason); + if self.quality.status == TtftQualityStatus::Complete { + self.quality.status = TtftQualityStatus::Coarse; + } + } +} + +#[derive(Debug, Clone, Copy)] +struct FrozenTimeline { + durations: [Duration; TtftStage::ALL.len()], + quality: TtftQuality, +} + +/// Timing context for one HTTP request. No clocks or labels are updated per token. +#[derive(Debug)] +pub struct TtftTimings { + start: Instant, + state: Mutex, + finished: AtomicBool, + result: OnceLock, +} + +impl TtftTimings { + pub fn new(start: Instant) -> Self { + Self { + start, + state: Mutex::new(TimelineState { + intervals: Vec::with_capacity(16), + quality: TtftQuality::default(), + }), + finished: AtomicBool::new(false), + result: OnceLock::new(), + } + } + + fn elapsed(&self) -> Duration { + #[cfg(test)] + CLOCK_READS.with(|reads| reads.set(reads.get() + 1)); + self.start.elapsed() + } + + pub fn is_frozen(&self) -> bool { + self.finished.load(Ordering::Acquire) + } + + pub fn quality(&self) -> TtftQuality { + if let Some(result) = self.result.get() { + return result.quality; + } + self.state.lock().quality + } + + pub fn mark_degraded(&self, reason: TtftDegradedReason) { + if self.is_frozen() { + return; + } + let mut state = self.state.lock(); + if !self.is_frozen() { + state.degrade(reason); + } + } + + pub fn mark_coarse(&self, reason: TtftCoarseReason) { + if self.is_frozen() { + return; + } + let mut state = self.state.lock(); + if !self.is_frozen() { + state.coarsen(reason); + } + } + + pub fn start_span(self: &Arc, stage: TtftStage) -> TtftSpan { + if self.is_frozen() { + return TtftSpan::inactive(); + } + let start = self.elapsed(); + let mut state = self.state.lock(); + if self.is_frozen() { + return TtftSpan::inactive(); + } + let Some(index) = state.push(Interval { + stage, + start, + end: None, + }) else { + return TtftSpan::inactive(); + }; + TtftSpan { + timings: Some(Arc::clone(self)), + index, + } + } + + /// Reuse an existing operation's start and elapsed result. The inclusive + /// histogram keeps its own population; only this view subtracts nested work. + pub fn record_duration(&self, stage: TtftStage, start: Instant, elapsed: Duration) { + if self.is_frozen() { + return; + } + let Some(end) = start.checked_add(elapsed) else { + self.mark_degraded(TtftDegradedReason::TimestampOverflow); + return; + }; + self.record_interval(stage, start, end); + } + + pub fn record_interval(&self, stage: TtftStage, start: Instant, end: Instant) { + if self.is_frozen() { + return; + } + let mut state = self.state.lock(); + if self.is_frozen() { + return; + } + if start > end { + state.degrade(TtftDegradedReason::InvalidInterval); + return; + } + state.push(Interval { + stage, + start: start.saturating_duration_since(self.start), + end: Some(end.saturating_duration_since(self.start)), + }); + } + + /// Import a bounded batch with one Rust clock read. The caller verifies the + /// source clock domain and submission window before converting integer ages. + /// This never compares Python's monotonic epoch with Rust's Instant epoch. + pub fn record_batch_ago(&self, batch: &[(TtftStage, Duration, Duration)]) -> bool { + if self.is_frozen() { + return false; + } + if batch.len() > MAX_TTFT_BATCH_INTERVALS { + self.mark_degraded(TtftDegradedReason::InvalidBatch); + return false; + } + if batch.is_empty() { + return true; + } + let now = self.elapsed(); + let mut state = self.state.lock(); + if self.is_frozen() || state.quality.degraded_reason.is_some() { + return false; + } + if batch.iter().any(|(stage, _, _)| !stage.python_enabled()) { + state.degrade(TtftDegradedReason::InvalidStage); + return false; + } + // Validate the whole batch before accepting any of it. Clipping an + // untrusted, pre-request timestamp would hide a bad clock domain. + if batch + .iter() + .any(|(_, start, end)| start < end || *start > now) + { + state.degrade(TtftDegradedReason::InvalidInterval); + return false; + } + if state.intervals.len() + batch.len() > MAX_TTFT_INTERVALS { + state.degrade(TtftDegradedReason::IntervalLimit); + return false; + } + for &(stage, start_ago, end_ago) in batch { + state.push(Interval { + stage, + start: now - start_ago, + end: Some(now - end_ago), + }); + } + true + } + + pub fn record_ago(&self, stage: TtftStage, start_ago: Duration, end_ago: Duration) { + self.record_batch_ago(&[(stage, start_ago, end_ago)]); + } + + /// Freeze at the HTTP first-token timestamp, including spans still in flight. + /// Repeated calls return the original result, regardless of their timestamp. + pub fn finish(&self, end: Instant) -> [Duration; TtftStage::ALL.len()] { + if let Some(result) = self.result.get() { + return result.durations; + } + let mut state = self.state.lock(); + if let Some(result) = self.result.get() { + return result.durations; + } + self.finished.store(true, Ordering::Release); + let total = end.saturating_duration_since(self.start); + let durations = if state.quality.degraded_reason.is_some() { + let mut durations = [Duration::ZERO; TtftStage::ALL.len()]; + durations[TtftStage::Unclassified as usize] = total; + durations + } else { + let (durations, overlap) = partition_with_quality(&state.intervals, total); + state.quality.unexpected_overlap = overlap; + durations + }; + let _ = self.result.set(FrozenTimeline { + durations, + quality: state.quality, + }); + durations + } +} + +/// Close a stage on scope exit, or leave it active until HTTP observes a token. +#[derive(Debug)] +pub struct TtftSpan { + timings: Option>, + index: usize, +} + +impl TtftSpan { + fn inactive() -> Self { + Self { + timings: None, + index: 0, + } + } + + pub fn leave_open(mut self) { + self.timings.take(); + } +} + +impl Drop for TtftSpan { + fn drop(&mut self) { + let Some(timings) = &self.timings else { + return; + }; + if timings.is_frozen() { + return; + } + let end = timings.elapsed(); + let mut state = timings.state.lock(); + if !timings.is_frozen() { + // Slots are never reused, even after a limit or validation failure. + state.intervals[self.index].end = Some(end); + } + } +} + +#[cfg(test)] +fn partition(intervals: &[Interval], total: Duration) -> [Duration; TtftStage::ALL.len()] { + partition_with_quality(intervals, total).0 +} + +fn partition_with_quality( + intervals: &[Interval], + total: Duration, +) -> ([Duration; TtftStage::ALL.len()], bool) { + let mut events = Vec::with_capacity(intervals.len() * 2); + for interval in intervals { + let start = interval.start.min(total); + let end = interval.end.unwrap_or(total).min(total); + if start < end { + events.push((start, interval.stage, true)); + events.push((end, interval.stage, false)); + } + } + events.sort_unstable_by_key(|event| event.0); + let mut durations = [Duration::ZERO; TtftStage::ALL.len()]; + let mut active = [0usize; TtftStage::ALL.len()]; + let mut previous = Duration::ZERO; + let mut unexpected_overlap = false; + for (time, stage, enters) in events { + if time > previous { + durations[attribute(&active) as usize] += time - previous; + unexpected_overlap |= has_unexpected_overlap(&active); + } + if enters { + active[stage as usize] += 1; + } else { + active[stage as usize] -= 1; + } + previous = time; + } + if total > previous { + durations[attribute(&active) as usize] += total - previous; + unexpected_overlap |= has_unexpected_overlap(&active); + } + (durations, unexpected_overlap) +} + +fn attribute(active: &[usize; TtftStage::ALL.len()]) -> TtftStage { + use TtftStage::*; + let prefill = active[BackendPrefill as usize] > 0 || active[FirstTokenPrefill as usize] > 0; + let decode = active[BackendDecode as usize] > 0 || active[FirstTokenDecode as usize] > 0; + let overlap = prefill && decode; + TtftStage::ALL + .into_iter() + .filter(|stage| { + *stage != Unclassified + && (active[*stage as usize] > 0 || (*stage == BackendOverlap && overlap)) + }) + .max_by_key(|stage| stage.descriptor().priority) + .unwrap_or(FrontendOverhead) +} + +fn is_ancestor(parent: TtftStage, mut child: TtftStage) -> bool { + while let Some(next) = child.descriptor().parent { + if parent == next { + return true; + } + child = next; + } + false +} + +fn has_unexpected_overlap(active: &[usize; TtftStage::ALL.len()]) -> bool { + // Frontend work should be sequential or nested. Concurrent backend waits + // have lower precedence and are intentionally permitted (including P/D). + for (index, stage) in TtftStage::ALL.into_iter().enumerate() { + if stage.descriptor().priority < TtftStage::Preprocess.descriptor().priority + || active[index] == 0 + { + continue; + } + for other in TtftStage::ALL.into_iter().skip(index + 1) { + if other.descriptor().priority >= TtftStage::Preprocess.descriptor().priority + && active[other as usize] > 0 + && !is_ancestor(stage, other) + && !is_ancestor(other, stage) + { + return true; + } + } + } + false +} + +#[cfg(test)] +thread_local! { + static CLOCK_READS: std::cell::Cell = const { std::cell::Cell::new(0) }; +} + +#[cfg(test)] +mod tests { + use super::*; + use TtftStage::*; + + fn ms(value: u64) -> Duration { + Duration::from_millis(value) + } + + fn interval(stage: TtftStage, start: u64, end: u64) -> Interval { + Interval { + stage, + start: ms(start), + end: Some(ms(end)), + } + } + + fn assert_total(durations: &[Duration; TtftStage::ALL.len()], expected: u64) { + assert_eq!(durations.iter().sum::(), ms(expected)); + } + + #[test] + fn reused_operation_timing_is_clipped_nested_and_frozen() { + let start = Instant::now(); + let timings = TtftTimings::new(start); + timings.record_duration(Preprocess, start, ms(20)); + timings.record_duration(TemplateTokenize, start + ms(2), ms(7)); + timings.record_duration(MultimodalPrepare, start + ms(7), ms(20)); + let result = timings.finish(start + ms(15)); + assert_total(&result, 15); + assert_eq!(result[TemplateTokenize as usize], ms(7)); + assert_eq!(result[MultimodalPrepare as usize], ms(6)); + timings.record_duration(RouteDecode, start, ms(100)); + assert_eq!(timings.finish(start + ms(100)), result); + } + + #[test] + fn nested_preprocessing_is_exclusive_and_preserves_gaps() { + let result = partition( + &[ + interval(Preprocess, 2, 18), + interval(PreprocessQueue, 3, 7), + interval(TemplateTokenize, 9, 15), + ], + ms(20), + ); + assert_eq!(result[FrontendOverhead as usize], ms(4)); + assert_eq!(result[Preprocess as usize], ms(6)); + assert_eq!(result[PreprocessQueue as usize], ms(4)); + assert_eq!(result[TemplateTokenize as usize], ms(6)); + assert_eq!(result[MultimodalPrepare as usize], Duration::ZERO); + assert_total(&result, 20); + } + + #[test] + fn routing_metadata_is_exclusive_within_multimodal_preparation() { + let result = partition( + &[ + interval(Preprocess, 0, 20), + interval(MultimodalPrepare, 2, 18), + interval(MmRoutingBuild, 6, 12), + ], + ms(20), + ); + assert_eq!(result[Preprocess as usize], ms(4)); + assert_eq!(result[MultimodalPrepare as usize], ms(10)); + assert_eq!(result[MmRoutingBuild as usize], ms(6)); + assert_total(&result, 20); + } + + #[test] + fn overlapping_backend_phases_count_once_and_yield_to_routing() { + let result = partition( + &[ + interval(BackendPrefill, 2, 10), + interval(FirstTokenPrefill, 10, 20), + interval(BackendDecode, 6, 14), + interval(FirstTokenDecode, 14, 22), + interval(RouteDecode, 8, 12), + interval(ResponsePostprocess, 21, 24), + ], + ms(24), + ); + assert_eq!(result[FrontendOverhead as usize], ms(2)); + assert_eq!(result[BackendPrefill as usize], ms(4)); + assert_eq!(result[BackendDecode as usize], Duration::ZERO); + assert_eq!(result[FirstTokenPrefill as usize], Duration::ZERO); + assert_eq!(result[FirstTokenDecode as usize], ms(1)); + assert_eq!(result[BackendOverlap as usize], ms(10)); + assert_eq!(result[RouteDecode as usize], ms(4)); + assert_eq!(result[ResponsePostprocess as usize], ms(3)); + assert_total(&result, 24); + } + + #[test] + fn repeated_and_overlapping_attempts_of_one_stage_count_their_union() { + let result = partition( + &[ + interval(RouteAggregated, 1, 4), + interval(RouteAggregated, 3, 6), + interval(RouteAggregated, 7, 9), + interval(BackendAggregated, 6, 7), + ], + ms(10), + ); + assert_eq!(result[RouteAggregated as usize], ms(7)); + assert_eq!(result[BackendAggregated as usize], ms(1)); + assert_eq!(result[FrontendOverhead as usize], ms(2)); + assert_total(&result, 10); + } + + #[test] + fn intervals_are_clipped_to_http_ttft_and_unused_stages_are_zero() { + let result = partition( + &[ + interval(MultimodalPrepare, 0, 4), + interval(MmRoutingBuild, 4, 30), + interval(RoutePrefill, 20, 30), + ], + ms(10), + ); + assert_eq!(result[MultimodalPrepare as usize], ms(4)); + assert_eq!(result[MmRoutingBuild as usize], ms(6)); + for stage in TtftStage::ALL { + if stage != MultimodalPrepare && stage != MmRoutingBuild { + assert_eq!(result[stage as usize], Duration::ZERO); + } + } + assert_total(&result, 10); + assert_eq!( + partition(&[], Duration::ZERO), + [Duration::ZERO; TtftStage::ALL.len()] + ); + assert_eq!(partition(&[], ms(10))[FrontendOverhead as usize], ms(10)); + } + + #[test] + fn finish_freezes_open_spans_and_ignores_late_writes() { + let start = Instant::now(); + let timings = Arc::new(TtftTimings::new(start)); + timings.state.lock().intervals.push(Interval { + stage: BackendDecode, + start: ms(2), + end: None, + }); + let span = TtftSpan { + timings: Some(Arc::clone(&timings)), + index: 0, + }; + let result = timings.finish(start + ms(10)); + drop(span); + drop(timings.start_span(RouteDecode)); + timings.record_ago(MultimodalPrepare, ms(3), ms(1)); + assert_eq!(timings.state.lock().intervals.len(), 1); + assert!(timings.state.lock().intervals[0].end.is_none()); + assert_eq!(timings.finish(start + ms(100)), result); + assert_eq!(result[BackendDecode as usize], ms(8)); + assert_total(&result, 10); + } + + #[test] + fn leaving_a_span_open_does_not_retain_the_context() { + let timings = Arc::new(TtftTimings::new(Instant::now())); + let span = timings.start_span(ResponsePostprocess); + assert_eq!(Arc::strong_count(&timings), 2); + span.leave_open(); + assert_eq!(Arc::strong_count(&timings), 1); + assert!(timings.state.lock().intervals[0].end.is_none()); + } + + #[test] + fn python_stage_names_are_fixed_and_invalid_ages_are_rejected() { + for stage in [ + Preprocess, + PreprocessQueue, + TemplateTokenize, + MultimodalPrepare, + MmRoutingBuild, + ] { + assert_eq!(TtftStage::from_python(stage.labels()[0]), Some(stage)); + } + assert_eq!(TtftStage::from_python("request_id"), None); + assert_eq!(TtftStage::from_python("backend_first_response"), None); + let timings = TtftTimings::new(Instant::now()); + timings.record_ago(Preprocess, ms(1), ms(2)); + assert!(timings.state.lock().intervals.is_empty()); + } + + #[test] + fn imported_ages_preserve_duration_and_reject_before_request_start() { + let timings = TtftTimings::new(Instant::now() - ms(100)); + timings.record_ago(TemplateTokenize, ms(7), ms(2)); + timings.record_ago(MultimodalPrepare, Duration::MAX, Duration::MAX); + let state = timings.state.lock(); + let intervals = &state.intervals; + assert_eq!(intervals[0].end.unwrap() - intervals[0].start, ms(5)); + assert_eq!(intervals.len(), 1); + } + + #[test] + fn registry_ids_labels_and_legacy_mappings_are_unique() { + let mut labels = std::collections::HashSet::new(); + for (id, stage) in TtftStage::ALL.into_iter().enumerate() { + assert_eq!(stage as usize, id); + assert!(labels.insert(stage.labels())); + assert_eq!( + TtftStage::from_python_id(id), + stage.python_enabled().then_some(stage) + ); + if let Some(legacy_stage) = stage.descriptor().legacy_stage { + assert_eq!(legacy_stage, stage.labels()[0]); + } + if let Some(parent) = stage.descriptor().parent { + assert!(stage.descriptor().priority > parent.descriptor().priority); + } + } + assert!(TtftStage::from_python_id(TtftStage::ALL.len()).is_none()); + assert_eq!( + BackendDecode.dispatch_prepare(), + Some(DispatchPrepareDecode) + ); + assert_eq!(TemplateRender.dispatch_prepare(), None); + } + + #[test] + fn prepare_is_removed_from_dispatch_without_moving_legacy_boundary() { + let result = partition( + &[ + interval(BackendDecode, 2, 20), + interval(DispatchPrepareDecode, 2, 7), + interval(RouteDecode, 0, 4), + interval(ResponsePostprocess, 18, 22), + ], + ms(22), + ); + assert_eq!(result[RouteDecode as usize], ms(2)); + assert_eq!(result[DispatchPrepareDecode as usize], ms(5)); + assert_eq!(result[BackendDecode as usize], ms(11)); + assert_eq!(result[ResponsePostprocess as usize], ms(4)); + assert_total(&result, 22); + } + + #[test] + fn real_template_tokenize_and_structural_tag_boundaries_are_separate() { + let start = Instant::now(); + let timings = TtftTimings::new(start); + timings.record_duration(Preprocess, start, ms(20)); + timings.record_duration(TemplateRender, start + ms(2), ms(3)); + timings.record_duration(Tokenize, start + ms(5), ms(7)); + // Structural tags are built after the preprocessing operation returns. + timings.record_duration(StructuralTagBuild, start + ms(20), ms(4)); + let result = timings.finish(start + ms(25)); + assert_eq!(result[Preprocess as usize], ms(10)); + assert_eq!(result[TemplateRender as usize], ms(3)); + assert_eq!(result[Tokenize as usize], ms(7)); + assert_eq!(result[StructuralTagBuild as usize], ms(4)); + assert_eq!(result[FrontendOverhead as usize], ms(1)); + assert_total(&result, 25); + assert_eq!(timings.quality(), TtftQuality::default()); + } + + #[test] + fn interval_limit_degrades_without_reusing_live_guard_slots() { + let start = Instant::now(); + let timings = Arc::new(TtftTimings::new(start)); + let span = timings.start_span(BackendDecode); + for _ in 1..MAX_TTFT_INTERVALS { + timings.record_duration(TemplateRender, start, ms(1)); + } + drop(timings.start_span(RouteDecode)); + assert_eq!(timings.state.lock().intervals.len(), MAX_TTFT_INTERVALS); + drop(span); + assert!(timings.state.lock().intervals[0].end.is_some()); + let result = timings.finish(start + ms(10)); + assert_eq!(result[Unclassified as usize], ms(10)); + assert_total(&result, 10); + assert_eq!( + timings.quality().degraded_reason, + Some(TtftDegradedReason::IntervalLimit) + ); + for stage in TtftStage::ALL { + if stage != Unclassified { + assert_eq!(result[stage as usize], Duration::ZERO); + } + } + } + + #[test] + fn imported_batch_has_one_anchor_and_is_validated_atomically() { + let timings = TtftTimings::new(Instant::now() - ms(100)); + let before = CLOCK_READS.with(|reads| reads.get()); + assert!(timings.record_batch_ago(&[ + (TemplateRender, ms(20), ms(15)), + (Tokenize, ms(15), ms(7)), + (StructuralTagBuild, ms(7), ms(1)), + ])); + assert_eq!(CLOCK_READS.with(|reads| reads.get()) - before, 1); + let state = timings.state.lock(); + assert_eq!(state.intervals[0].end, Some(state.intervals[1].start)); + assert_eq!(state.intervals[1].end, Some(state.intervals[2].start)); + drop(state); + assert!( + !timings.record_batch_ago(&[(TemplateRender, ms(6), ms(3)), (Tokenize, ms(1), ms(2)),]) + ); + assert_eq!(timings.state.lock().intervals.len(), 3); + assert_eq!( + timings.quality().degraded_reason, + Some(TtftDegradedReason::InvalidInterval) + ); + } + + #[test] + fn batch_limit_and_overflow_are_bounded_degradation() { + let timings = TtftTimings::new(Instant::now()); + let batch = + vec![(TemplateRender, Duration::ZERO, Duration::ZERO); MAX_TTFT_BATCH_INTERVALS + 1]; + assert!(!timings.record_batch_ago(&batch)); + assert!(timings.state.lock().intervals.is_empty()); + assert_eq!( + timings.quality().degraded_reason, + Some(TtftDegradedReason::InvalidBatch) + ); + let timings = TtftTimings::new(Instant::now()); + timings.record_duration(Tokenize, Instant::now(), Duration::MAX); + assert_eq!( + timings.quality().degraded_reason, + Some(TtftDegradedReason::TimestampOverflow) + ); + } + + #[test] + fn opaque_fallback_is_coarse_but_conserves_time() { + let start = Instant::now(); + let timings = TtftTimings::new(start); + timings.record_duration(TemplateTokenize, start, ms(3)); + let result = timings.finish(start + ms(4)); + assert_total(&result, 4); + assert_eq!(result[TemplateTokenize as usize], ms(3)); + assert_eq!(timings.quality().status, TtftQualityStatus::Coarse); + assert_eq!( + timings.quality().coarse_reason, + Some(TtftCoarseReason::OpaqueTemplate) + ); + } + + #[test] + fn sibling_overlap_is_deterministic_and_nested_work_is_expected() { + let intervals = [ + interval(Preprocess, 0, 10), + interval(Tokenize, 2, 8), + interval(TemplateRender, 3, 6), + ]; + let (result, overlap) = partition_with_quality(&intervals, ms(10)); + assert!(overlap); + assert_eq!(result[TemplateRender as usize], ms(3)); + assert_eq!(result[Tokenize as usize], ms(3)); + assert_total(&result, 10); + let reversed: Vec<_> = intervals.into_iter().rev().collect(); + assert_eq!(partition_with_quality(&reversed, ms(10)), (result, overlap)); + let (_, overlap) = partition_with_quality( + &[ + interval(Preprocess, 0, 10), + interval(MultimodalPrepare, 2, 8), + interval(MmRoutingBuild, 3, 6), + ], + ms(10), + ); + assert!(!overlap); + } + + #[test] + fn frozen_entries_and_drop_read_no_clocks_or_locks() { + let start = Instant::now(); + let timings = Arc::new(TtftTimings::new(start)); + let span = timings.start_span(Preprocess); + let frozen = timings.finish(start + ms(10)); + let before = CLOCK_READS.with(|reads| reads.get()); + // Holding the lock also verifies the ordinary frozen paths avoid it. + let _state = timings.state.lock(); + drop(span); + drop(timings.start_span(TemplateRender)); + timings.record_duration(Tokenize, start, Duration::MAX); + timings.record_interval(Tokenize, start, start); + timings.record_ago(Tokenize, Duration::ZERO, Duration::ZERO); + timings.mark_degraded(TtftDegradedReason::InvalidBatch); + timings.mark_coarse(TtftCoarseReason::MissingCoverage); + assert_eq!(timings.finish(start + ms(100)), frozen); + assert_eq!(timings.quality(), TtftQuality::default()); + assert_eq!(CLOCK_READS.with(|reads| reads.get()), before); + } + + #[test] + fn concurrent_finish_and_import_freeze_one_conserved_snapshot() { + let start = Instant::now() - ms(100); + let timings = Arc::new(TtftTimings::new(start)); + let barrier = Arc::new(std::sync::Barrier::new(2)); + let imported = Arc::clone(&timings); + let worker_barrier = Arc::clone(&barrier); + let worker = std::thread::spawn(move || { + worker_barrier.wait(); + imported.record_batch_ago(&[(TemplateRender, ms(20), ms(10))]); + }); + barrier.wait(); + let result = timings.finish(start + ms(100)); + worker.join().unwrap(); + assert_total(&result, 100); + assert_eq!(timings.finish(start + ms(200)), result); + } + + #[test] + fn dense_retry_timelines_conserve_integer_time_independent_of_insertion_order() { + for seed in 0..32u64 { + let mut intervals = Vec::new(); + for index in 0..MAX_TTFT_INTERVALS { + let stage = TtftStage::ALL[(index + seed as usize) % TtftStage::ALL.len()]; + if stage == Unclassified { + continue; + } + let start = (index as u64 * 17 + seed * 13) % 120; + let end = start + (index as u64 * 7 + seed) % 40; + intervals.push(interval(stage, start, end)); + } + let result = partition(&intervals, ms(100)); + assert_total(&result, 100); + intervals.reverse(); + assert_eq!(partition(&intervals, ms(100)), result); + } + } +} diff --git a/lib/llm/tests/http_metrics.rs b/lib/llm/tests/http_metrics.rs index 7ff123614917..292d1fee4093 100644 --- a/lib/llm/tests/http_metrics.rs +++ b/lib/llm/tests/http_metrics.rs @@ -10,12 +10,14 @@ use dynamo_llm::{ preprocessor::LLMMetricAnnotation, protocols::{ Annotated, + common::ttft::TtftStage, openai::chat_completions::{ NvCreateChatCompletionRequest, NvCreateChatCompletionStreamResponse, }, openai::completions::{NvCreateCompletionRequest, NvCreateCompletionResponse}, }, }; +use dynamo_runtime::config::environment_names::llm::DYN_FRONTEND_TTFT_DETAIL; use dynamo_runtime::metrics::prometheus_names::frontend_service::METRICS_PREFIX_ENV; use dynamo_runtime::{ CancellationToken, @@ -737,6 +739,89 @@ async fn test_unknown_model_uses_sentinel_label() { .await; } +/// Read only the fixed test labels; no user-provided strings or escaped label +/// values are involved. Matching a set avoids depending on exposition order. +fn metric_sample(body: &str, name: &str, expected_labels: &[(&str, &str)]) -> f64 { + let expected_labels: Vec<_> = expected_labels + .iter() + .map(|(name, value)| format!("{name}=\"{value}\"")) + .collect(); + let samples: Vec = body + .lines() + .filter_map(|line| { + let (labels, value) = line + .strip_prefix(name)? + .strip_prefix('{')? + .split_once("} ")?; + let labels: Vec<_> = labels.split(',').collect(); + (labels.len() == expected_labels.len() + && expected_labels + .iter() + .all(|label| labels.contains(&label.as_str()))) + .then(|| value.parse().expect("metric sample must be numeric")) + }) + .collect(); + assert_eq!( + samples.len(), + 1, + "expected one {name}{expected_labels:?} sample" + ); + assert!(samples[0].is_finite(), "metric sample must be finite"); + samples[0] +} + +/// The default detail view must use the same first-token cohort as total TTFT, +/// including stages this mock engine never visits. Return the frozen sums so +/// the caller also checks that later chunks do not change the observation. +fn assert_ttft_detail_cohort(body: &str) -> (f64, Vec) { + let model_labels = [("model", "gatedmodel")]; + assert_eq!( + metric_sample( + body, + "dynamo_frontend_time_to_first_token_seconds_count", + &model_labels + ), + 1.0 + ); + let total = metric_sample( + body, + "dynamo_frontend_time_to_first_token_seconds_sum", + &model_labels, + ); + let mut contributions = Vec::with_capacity(TtftStage::ALL.len()); + for stage in TtftStage::ALL { + let [stage, phase] = stage.labels(); + let labels = [("model", "gatedmodel"), ("stage", stage), ("phase", phase)]; + assert_eq!( + metric_sample(body, "dynamo_frontend_ttft_stage_seconds_count", &labels), + 1.0 + ); + contributions.push(metric_sample( + body, + "dynamo_frontend_ttft_stage_seconds_sum", + &labels, + )); + } + let series = body + .lines() + .filter(|line| { + line.starts_with("dynamo_frontend_ttft_stage_seconds_count{") + && line.contains("model=\"gatedmodel\"") + }) + .count(); + assert_eq!( + series, + TtftStage::ALL.len(), + "only canonical stage/phase pairs are exported" + ); + let sum: f64 = contributions.iter().sum(); + assert!( + (sum - total).abs() <= 1e-9 + total.abs() * 1e-12, + "exclusive contributions {sum} must sum to total TTFT {total}" + ); + (total, contributions) +} + /// #11349: a non-streaming handler must observe metrics before the /// backend-error preflight. The preflight buffers leading data-less /// annotation frames until the first data-bearing event, so an observer @@ -753,7 +838,11 @@ async fn assert_non_streaming_observes_metrics_before_preflight( path: &str, request: serde_json::Value, ) { - temp_env::async_with_vars([(METRICS_PREFIX_ENV, None::<&str>)], async { + let vars = [ + (METRICS_PREFIX_ENV, None::<&str>), + (DYN_FRONTEND_TTFT_DETAIL, None::<&str>), + ]; + temp_env::async_with_vars(vars, async { let (listener, port) = bind_random_port().await; let service = HttpService::builder() .port(port) @@ -822,6 +911,9 @@ async fn assert_non_streaming_observes_metrics_before_preflight( .unwrap(); } + // This data-less frame reports a real output token, so both total and + // detailed TTFT settle here, before the held content is released. + let first_token_details = assert_ttft_detail_cohort(&metrics_body); gate.notify_one(); let response = request_task.await.unwrap().unwrap(); @@ -878,6 +970,11 @@ async fn assert_non_streaming_observes_metrics_before_preflight( ); } + assert_eq!( + assert_ttft_detail_cohort(&metrics_body), + first_token_details + ); + cancel_token.cancel(); task.await.unwrap().unwrap(); }) diff --git a/lib/runtime/src/config/environment_names.rs b/lib/runtime/src/config/environment_names.rs index 916860944b3b..1df3072faede 100644 --- a/lib/runtime/src/config/environment_names.rs +++ b/lib/runtime/src/config/environment_names.rs @@ -371,6 +371,8 @@ pub mod kvbm { /// LLM (Language Model) inference environment variables pub mod llm { + /// Exclusive frontend TTFT detail: off, metrics (default), logs, or both. + pub const DYN_FRONTEND_TTFT_DETAIL: &str = "DYN_FRONTEND_TTFT_DETAIL"; /// Delay between tokens emitted by the token echo engine, in milliseconds. pub const DYN_TOKEN_ECHO_DELAY_MS: &str = "DYN_TOKEN_ECHO_DELAY_MS"; @@ -611,6 +613,8 @@ pub mod llm { /// See [`DYN_METRICS_REQUEST_DURATION`]. pub const DYN_METRICS_TTFT: &str = "DYN_METRICS_TTFT"; /// See [`DYN_METRICS_REQUEST_DURATION`]. + pub const DYN_METRICS_TTFT_STAGE: &str = "DYN_METRICS_TTFT_STAGE"; + /// See [`DYN_METRICS_REQUEST_DURATION`]. pub const DYN_METRICS_ITL: &str = "DYN_METRICS_ITL"; /// Comma-separated inter-token latency histogram bucket boundaries. pub const DYN_METRICS_ITL_BUCKETS: &str = "DYN_METRICS_ITL_BUCKETS"; @@ -1260,6 +1264,7 @@ mod tests { llm::metrics::DYN_METRICS_INPUT_SEQUENCE, llm::metrics::DYN_METRICS_OUTPUT_SEQUENCE, llm::metrics::DYN_METRICS_TTFT, + llm::metrics::DYN_METRICS_TTFT_STAGE, llm::metrics::DYN_METRICS_ITL, llm::metrics::DYN_METRICS_ITL_BUCKETS, llm::metrics::DYN_METRICS_EMBEDDING_LATENCY, diff --git a/lib/runtime/src/metrics/prometheus_names.rs b/lib/runtime/src/metrics/prometheus_names.rs index be7a21ae0c04..58e25f8f88b1 100644 --- a/lib/runtime/src/metrics/prometheus_names.rs +++ b/lib/runtime/src/metrics/prometheus_names.rs @@ -279,6 +279,15 @@ pub mod frontend_service { /// Time to first token in seconds pub const TIME_TO_FIRST_TOKEN_SECONDS: &str = "time_to_first_token_seconds"; + /// Exclusive contributions to HTTP time to first token, labeled by stage and phase. + pub const TTFT_STAGE_SECONDS: &str = "ttft_stage_seconds"; + /// Requests with untrustworthy detailed TTFT attribution, labeled by fixed reason. + pub const TTFT_DETAIL_DEGRADED_TOTAL: &str = "ttft_detail_degraded_total"; + /// Requests with known coarse TTFT coverage, labeled by fixed reason. + pub const TTFT_DETAIL_COARSE_TOTAL: &str = "ttft_detail_coarse_total"; + /// Requests with unexpected overlapping TTFT leaves. + pub const TTFT_DETAIL_UNEXPECTED_OVERLAP_TOTAL: &str = "ttft_detail_unexpected_overlap_total"; + /// Inter-token latency in seconds pub const INTER_TOKEN_LATENCY_SECONDS: &str = "inter_token_latency_seconds";