Skip to content

[Bugfix][Metrics] Measure the codec stage TTFT and phase split after talker first audio - #9097

Open
MinhaoLi0318 wants to merge 2 commits into
vllm-project:mainfrom
MinhaoLi0318:fix/stage-stats-async-chunk-phase
Open

MinhaoLi0318 wants to merge 2 commits into
vllm-project:mainfrom
MinhaoLi0318:fix/stage-stats-async-chunk-phase

Conversation

@MinhaoLi0318

@MinhaoLi0318 MinhaoLi0318 commented Oct 19, 2026 •

Copy link
Copy Markdown
Contributor

Contributor intent (required human answers)

1. What outcome do you want to achieve?

I want the codec stage of Qwen3-TTS, under the default async-chunk deployment, to record TTFT correctly and to provide a usable prefill/decode latency split, so that users can use it to analyze performance and locate bottlenecks.

2. What is the highest-leverage variable for that outcome?

Whether the prefill boundary of the native stats is accurate. In particular, the codec's first output that is recorded with stats must be handled as prefill; the first-audio frame that arrives before it without stats must not end that phase early.

3. How will this work move that variable?

I keep a separate prefill state for the native stats, which only an output carrying IterationStats clears, and which is reset together with them on a streaming update. This way the first-audio frame no longer ends the prefill phase in the stats, and the existing meaning of is_prefilling stays unchanged.

4. Whose customer or user needs does this address, and what are those needs?

Mainly users who run the default Qwen3-TTS deployment and use --log-stats to investigate latency. They need reliable codec TTFT and prefill/decode data to tell which phase the time goes to, and to compare before and after an optimization.

Is a PR needed? Yes. This is a real stats bug on the default deployment path, reproduced on an H100, and the fix comes with regression tests, so it should go upstream as a follow-up bugfix to #8575. The PR states the validation scope as it is: the fix has not been re-run on GPU yet, and the histogram part was verified only in unit tests, without scraping /metrics.

Purpose

Follow-up to #8575 (merged as 0d4d09cf7), which added the queue/prefill/decode split to StageRequestStats.

Before. With talker first audio (#8163), the codec stage (stage 1) reports vllm_ttft_ms as 0.0 and no vllm_prefill_ms / vllm_decode_ms for every request. This is the default Qwen3-TTS deploy: vllm_omni/deploy/qwen3_tts.yaml sets model_runner: v2, async_chunk: true and talker_first_audio: true. qwen3_tts_mrv2.yaml, qwen3_omni_moe_mrv2.yaml and the three qwen3_tts_high_concurrency*.yaml deploys also enable talker_first_audio, so they should take the same path; I did not run them.

On one H100 with Qwen/Qwen3-TTS-12Hz-1.7B-CustomVoice (--async-chunk --log-stats --enforce-eager), this held for 18 of 18 requests over two server boots. With --no-async-chunk, all fields were present (9 of 9). These numbers were measured with an earlier head of #8575 (07dfd2ee8, whose vllm_omni/ and docs diff is identical to the merged 0d4d09cf7) on base 198c21059, which already contains #8163, not on current main. vllm_omni/engine/orchestrator.py changed by 714 lines between that base and current main 2c72dea3a (575 added, 139 removed, including #8675, which made event-driven orchestration the default). This change has not been run on GPU.

Cause. Orchestrator._flush_upstream_first_audio feeds the talker's first audio frame into the codec stage's output processor without IterationStats (orchestrator.py L1043 on main; the regular path at L938-L943 passes one). That output records no stats, but it still clears req_state.is_prefilling: in _process_mm_only_outputs (vllm_omni/outputs/output_processor.py L794) on the multimodal path, and unconditionally in vLLM's process_outputs on the text path. _update_stats_from_output then reads was_prefilling as False (L837) for the codec's first engine-core output and records it as a decode step. Its first-token timestamp is never set, vllm_ttft_ms keeps its 0.0 default, and the split is left out. #8575 reported the missing interval as None and had a test expecting that, but the interval is measurable.

The IterationStats passed to the stat logger for the codec stage have been affected in the same way since #8163: no TTFT sample, an ITL measured from a last-token timestamp of 0, a negative prefill time, and a decode time measured from a first-token timestamp of 0. I checked this only at the IterationStats level in the unit tests below, not on a /metrics scrape.

After. OmniRequestState gets native_is_prefilling, a prefill flag for native_text_stats. Only an output recorded with stats clears it, and a streaming update resets it together with the native stats. req_state.is_prefilling keeps its upstream meaning. When every output carries stats, the two flags are equal at every step, so stages without first audio report the same values as before. The codec stage's split, vllm_ttft_ms and histogram samples now start at its own first engine-core output.

Contract. docs/design/metrics.md, section "LLM-stage phase split in StageRequestStats":

  • The vllm_prefill_ms row drops "(the first token for an AR stage)".
  • New sentences: under Model Runner V2 + async_chunk, a non-final AR stage (for example the Qwen3-TTS talker) emits one output when it stops, so its vllm_prefill_ms also covers its decode steps; the first-audio frame does not end the codec stage's prefill.
  • New sentences (second commit): codec outputs that arrive before the first-audio frame keep the engine-core timestamps of their batches, so the split and the ITLs leave out the wait for the frame; vllm_ttft_ms and its histogram sample include that wait, because TTFT is taken when the output processor handles the first output.

Field names, the debug table and the Prometheus families are unchanged, so no user guide or example changes.

Codec outputs that arrive before the first-audio frame (second commit, from review). The orchestrator holds such outputs in pending_first_audio_outputs (orchestrator.py L1009-L1017) and, after the frame, processes each one in a new OmniEngineCoreOutputs (L1057-L1071). That wrapper had no timestamp, so EngineCoreOutputs.__post_init__ stamped it with time.monotonic() at replay time: in this order the codec's vllm_prefill_ms and the wrapped prefill histogram included the wait for the frame, and outputs replayed back to back had ITLs of about 0. Each held output now keeps the engine-core timestamp of the batch it arrived in, and the replay passes it on; the in-order path is unchanged. vllm_ttft_ms is still taken at replay: as in vLLM, TTFT runs from the wall-clock arrival time to the time the output processor handles the first output, and engine-core timestamps come from time.monotonic().

Related.

Test Plan

vLLM Version: v0.31.0 (db9527a468, the VLLM_VERSION in docker/Dockerfile.ci), used as a source tree on PYTHONPATH without compiled extensions.

vLLM-Omni Commit: 74d2606ef (2 commits on upstream/main 2c72dea3a)

Environment: macOS 26.6 (arm64), Python 3.12.14, torch 2.13.0 CPU, pytest 9.1.1. No GPU; not the CI image. Other dependencies come from an existing local virtualenv and from wheels already unpacked in the local uv cache, put on PYTHONPATH; nothing was installed for these runs.

export PYTHONPATH=$PWD:<vllm v0.31.0 source>:<local wheels> HF_HUB_OFFLINE=1 VLLM_TARGET_DEVICE=cpu

# 1. Changed tests and neighbouring suites
pytest -q tests/engine/test_output_processor.py tests/metrics \
  tests/engine/duplex/test_engine_session.py tests/engine/test_orchestrator.py \
  tests/engine/test_orchestrator_first_audio.py
# 2. Broad CPU suite
pytest -q -m "core_model and cpu" tests/engine tests/metrics
# 3. This branch's test files on main's production code
# 4. Main's test files on this branch's production code
pytest -q tests/engine/test_output_processor.py tests/engine/test_orchestrator_first_audio.py
# 5. #9050 rebased on 2c72dea3a plus this commit, conflict resolved by keeping both sides
pytest -q <run 1 files> tests/core/sched/test_omni_scheduler_input_ready.py \
  tests/core/sched/test_omni_sched_deferred_free_fence.py \
  tests/distributed/omni_connectors/test_chunk_transfer_adapter.py

Runs 1 and 2 were repeated on upstream/main 2c72dea3a, and run 5 on #9050 alone (rebased on 2c72dea3a).

Lint with the versions pinned in .pre-commit-config.yaml, on the changed files: ruff 0.14.10 check and format --check, typos 1.49.0, markdownlint-cli2 0.23.2 on docs/design/metrics.md, mypy 1.11.1 through tools/pre_commit/mypy.py 3.10, tools/pre_commit/{check_test_marks,check_spdx_header,check_forbidden_imports,check_torch_cuda}.py, and git diff --check.

Test Result

Run This branch Base
1. Changed tests and neighbouring suites 518 passed 515 passed
2. Broad CPU suite 2289 passed, 21 failed, 23 errors, 2 skipped 2286 passed, 21 failed, 23 errors, 2 skipped
3. Branch tests on main's code 8 failed, 112 passed
4. Main's tests on branch code 1 failed, 116 passed
5. With #9050 724 passed, 8 failed #9050 alone: 721 passed, 8 failed
  • Run 2: the 44 failures and errors are the same test IDs on both sides, all from this environment: no cached Hugging Face snapshots while offline, the macOS limit on POSIX shared-memory names (Errno 63), Model Runner V2 requiring Triton, no Omni AR worker class on this CPU platform (NotImplementedError), and no /bin/true on macOS.
  • Run 3: the 3 new tests (4 IDs) fail at their assertion on the split, because vllm_prefill_ms and vllm_decode_ms are left out. So do 4 IDs of 3 older tests: they no longer set req_state.is_prefilling by hand, because it no longer affects the native stats, and they now expect the code under test to clear the flag.
  • Run 4: the one failure is [Core] Add LLM-stage queue/prefill/decode split to StageRequestStats #8575's test_first_output_without_stats_leaves_prefill_and_decode_out, which expected the split to be missing and is replaced here.
  • Run 5: the 8 failures are the same SharedMemoryConnector tests in test_chunk_transfer_adapter.py on both sides, and they also fail on main. They need /dev/shm, which macOS does not have.
  • Second commit: test_codec_outputs_parked_for_first_audio_keep_engine_core_timestamps also fails on the first commit alone (1505d9505): vllm_prefill_ms is the replay-time time.monotonic() minus the SCHEDULED time, and vllm_decode_ms is left out as negative. Run 1 on 1505d9505: 517 passed. Run 2 on this branch has the same 44 failing and erroring test IDs as on 1505d9505.
  • Lint: ruff, typos, the four tools/pre_commit checks and git diff --check are clean, and markdownlint reports 0 issues. mypy reports the same 14 errors on this branch and on main for the first commit's files; for the second commit's files it reports 1 error, at an unchanged line of test_orchestrator_first_audio.py (L267) that has the same error on main.

Not run:

  • GPU runs. There are no numbers from a served model with this change. The H100 numbers above come from the older base described in Purpose.
  • A /metrics scrape of the stage-1 histograms.
  • The other deploys that enable talker_first_audio.

AI assistance: I used Claude Code to implement and test this change and to draft this description; I reviewed every change and can explain it.

…rst audio

With talker first audio (the default Qwen3-TTS deploy: MRV2 + async_chunk),
the orchestrator feeds the talker's first audio frame into the codec stage's
output processor without IterationStats. Processing that frame clears
req_state.is_prefilling but records no stats, so the codec stage's first
engine-core output was recorded as a decode step: no first-token timestamp,
vllm_ttft_ms left at its default 0.0, and vllm_prefill_ms / vllm_decode_ms
(vllm-project#8575) missing. On an H100 run of Qwen3-TTS (--async-chunk --log-stats)
this held for all 18 requests of two server boots; --no-async-chunk was
complete.

The same path affects the IterationStats passed to the stat logger for the
codec stage: no TTFT sample, an ITL measured from a last-token timestamp of
0, a negative prefill time, and a decode time measured from a first-token
timestamp of 0. This part was verified only in unit tests, at the
IterationStats level, not on a /metrics scrape.

Give the native stats their own prefill flag, cleared only by an output that
is recorded with stats. Replace the vllm-project#8575 test that expected the split to be
missing with tests on both output paths and through the orchestrator's
first-audio flush. Older tests that set req_state.is_prefilling by hand no
longer affected the native stats: they now set native_is_prefilling where
they need the decode path, and otherwise leave the flag to the code under
test. In the metrics doc, say that a non-final AR stage under MRV2 +
async_chunk (the Qwen3-TTS talker) emits one output at stop, so its prefill
covers its decode steps, and that the first-audio frame does not end the
codec stage's prefill.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
@chatgpt-codex-connector

Copy link
Copy Markdown

Codex Review Summary

This comment shows the latest Codex review activity on this pull request.

Review Status Commit Review trigger
📝 Code Review ⚠️ Failed 2026-10-19T07:32:21.447821Z 1505d95 PR opened
ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review" or "@codex security review".

Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings.

@chatgpt-codex-connector

Copy link
Copy Markdown

Codex usage limits have been reached for code reviews. Please check with the admins of this repo to increase the limits by adding credits.
Credits must be used to enable repository wide code reviews.

@vllm-omni-review-bot

Copy link
Copy Markdown

This PR appears to belong to: docs/design/module/engine_orchestration.md, docs/design/module/input_output_modality_contracts.md, docs/design/module/entrypoints.md.

Module owners: @Gaohan123 @alex-jw-brooks @amy-why-3459

Routing: @Gaohan123 via module of the changed files, CODEOWNERS; @alex-jw-brooks via module of the changed files; @amy-why-3459 via module of the changed files

@MinhaoLi0318, please review your own changes and leave a short self-review comment describing what you checked. PRs without author self-review may not be assigned a reviewer.

Please take a look when you have a chance. If you would like an automated review, mention @vllm-omni-review-bot in a comment.

@amy-why-3459 amy-why-3459 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, a separate native_is_prefilling flag is a clean way to keep the stats-less first-audio flush (_flush_upstream_first_audio calls process_llm_raw_outputs(replica_id, OmniEngineCoreOutputs(outputs=[first_output])) with no iteration_stats) from ending the codec stage's prefill, and resetting it in apply_streaming_update together with native_text_stats keeps multi-segment requests consistent.

One gap on the path where codec outputs overtake the first-audio frame, see inline.

Comment thread docs/design/metrics.md Outdated
The first engine-core output ends prefill even when it carries no token. A generation stage that emits one output when it stops therefore reports its whole run as `vllm_prefill_ms`, with a measured `vllm_decode_ms` of `0`.
For an AR stage that emits an output every step, the first engine-core output carries its first token. The first engine-core output ends prefill even when it carries no token. A generation stage that emits one output when it stops therefore reports its whole run as `vllm_prefill_ms`, with a measured `vllm_decode_ms` of `0`. The same holds for an AR stage that does not emit per-step outputs: with Model Runner V2 and `async_chunk`, a non-final AR stage (for example the Qwen3-TTS talker) emits one output when it stops, so its `vllm_prefill_ms` also covers its decode steps, and its `vllm_ttft_ms` is the time to that output.

With talker first audio (`talker_first_audio`), the orchestrator feeds the upstream stage's first audio frame into the codec stage's output processor. That frame is not an engine-core output of the codec stage and does not end its prefill: the codec stage's split, its `vllm_ttft_ms`, and the samples it adds to the wrapped vLLM histograms start at the codec's own first engine-core output.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This holds for the in-order case the new tests cover, but not when codec outputs arrive before the first-audio frame. _route_upstream_first_audio parks those in req_state.pending_first_audio_outputs, and _flush_upstream_first_audio later replays each one as OmniEngineCoreOutputs(outputs=[output]). That wrapper has no timestamp, so EngineCoreOutputs.__post_init__ stamps it with time.monotonic() at replay time and the engine-core timestamp of the batch it originally arrived in is lost.

With this change the first replayed output is now the one that ends prefill, so in this case:

  • vllm_prefill_ms (and the wrapped prefill histogram) includes the wait for the upstream frame, while QUEUED/SCHEDULED keep their original event times;
  • several parked outputs replayed back-to-back get near-identical timestamps, so their ITLs are ~0 and the real gap lands on whichever output comes next.

vllm_ttft_ms is measured at replay regardless, since _process_llm_stage_outputs creates the IterationStats then; that may be the intended user-facing meaning, but it would help to say so here.

Could the original raw_outputs.timestamp be stored with each parked output and passed through on replay (OmniEngineCoreOutputs(outputs=[output], timestamp=ts)), plus a test where the codec's first output arrives before the first-audio frame?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Confirmed on the previous head: the output parked by _route_upstream_first_audio lost its batch's timestamp, and the wrapper built in _flush_upstream_first_audio was stamped at replay time. So when codec outputs overtook the first-audio frame, prefill included the wait for the frame and outputs replayed back to back had ITLs of about 0.

Fixed in 74d2606ef:

  • Each parked output is stored with raw_outputs.timestamp and replayed as OmniEngineCoreOutputs(outputs=[output], timestamp=ts). I kept one wrapper per parked output, as before, so replay order and terminal handling do not change. The in-order path is untouched.
  • docs/design/metrics.md now says that held outputs keep the engine-core timestamps of their batches, and: "vllm_ttft_ms and its histogram sample include that wait: as in vLLM, TTFT runs from the request's arrival to the time the output processor handles the first output, which for a held output is after the frame." TTFT can't use the engine-core timestamp anyway: it is measured against the wall-clock arrival time, and engine-core timestamps come from time.monotonic().
  • New test test_codec_outputs_parked_for_first_audio_keep_engine_core_timestamps: the codec's first two outputs (engine-core times 1.75 and 2.25, SCHEDULED at 1.25) arrive before the first-audio frame, and a terminal output at 3.0 arrives after it. It checks prefill 500 ms, decode 1250 ms, ITLs of 500 ms and 750 ms, and a TTFT of 4 s taken at replay (with the wall clock patched). It passes with the fix. On the previous head it fails: vllm_prefill_ms is the replay-time time.monotonic() minus the SCHEDULED time, and vllm_decode_ms is left out as negative.

Local CPU run, not the CI image: pytest tests/engine/test_output_processor.py tests/metrics tests/engine/duplex/test_engine_session.py tests/engine/test_orchestrator.py tests/engine/test_orchestrator_first_audio.py gives 518 passed (517 on the previous head).

Thanks for the careful read.

AI assistance: drafted with Claude Code; I reviewed the change and this reply.

@vllm-omni-review-bot

vllm-omni-review-bot commented Oct 19, 2026 •

Copy link
Copy Markdown

Omni ReviewBot triage note

Automated triage of commit 74d2606ef180 produced:

  • Priority: high. Prompt maintainer attention is suggested.

These are automated triage suggestions only — the final decision belongs to the maintainers.

… for first audio

When codec outputs overtake the talker's first-audio frame, the
orchestrator parks them in pending_first_audio_outputs and, after the
frame, replays each one in a new OmniEngineCoreOutputs. That wrapper had
no timestamp, so EngineCoreOutputs.__post_init__ stamped it with
time.monotonic() at replay time. Since the previous commit the first
replayed output ends the codec stage's native prefill, so in this order
vllm_prefill_ms and the wrapped prefill histogram included the wait for
the frame, while QUEUED/SCHEDULED kept their engine-core times. Parked
outputs replayed back to back also got near-identical timestamps: their
ITLs were about 0 and the real gap moved to the next output.

Park each output with the timestamp of the batch it arrived in and pass
that timestamp to the replay wrapper. Keep one wrapper per parked output
as before, so replay order and terminal handling do not change; outputs
from the same batch get the same timestamp either way. The in-order path
is unchanged.

vllm_ttft_ms is still taken at replay: IterationStats is created there,
and, as in vLLM, TTFT runs from arrival to the time the output processor
handles the first output. Say so in docs/design/metrics.md.

Add a test where the codec's first two outputs arrive before the
first-audio frame. On the previous commit it fails: vllm_prefill_ms is
the replay-time monotonic clock minus the SCHEDULED time, and
vllm_decode_ms is left out as negative.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
@MinhaoLi0318
MinhaoLi0318 requested a review from tzhouam as a code owner October 19, 2026 08:48

@amy-why-3459 amy-why-3459 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the follow-up. Looked at 74d2606 (the delta since my last review):

  • Each parked output now carries raw_outputs.timestamp of the batch it arrived in and the replay wrapper is built with OmniEngineCoreOutputs(outputs=[output], timestamp=timestamp), so EngineCoreOutputs.__post_init__ no longer re-stamps it with replay-time time.monotonic(). The prefill end and the ITLs now come from engine-core time, and same-batch outputs share a timestamp as they would on the in-order path.
  • The tuple shape change is consistent: the append in _route_upstream_first_audio and the unpack in _flush_upstream_first_audio are the only producer/consumer of pending_first_audio_outputs.
  • The new test covers the out-of-order case I asked about (two codec outputs parked before the frame) and checks prefill 500 ms, ITLs [500, 750] ms, and TTFT measured at replay (4000 ms), which matches the clarified wording in docs/design/metrics.md.

No further concerns on this delta.

@hsliuustc0106 hsliuustc0106 added benchmark/profiler/metrics/logger Codes related to benchmarks, profiler, metrics and logger system bug Something isn't working high priority high priority issue, needs to be done asap labels Oct 19, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

benchmark/profiler/metrics/logger Codes related to benchmarks, profiler, metrics and logger system bug Something isn't working high priority high priority issue, needs to be done asap

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants