Skip to content

[Core] Split input wait out of vllm_queued_ms in StageRequestStats - #9050

Open
MinhaoLi0318 wants to merge 5 commits into
vllm-project:mainfrom
MinhaoLi0318:metrics/stage-input-wait
Open

MinhaoLi0318 wants to merge 5 commits into
vllm-project:mainfrom
MinhaoLi0318:metrics/stage-input-wait

Conversation

@MinhaoLi0318

Copy link
Copy Markdown
Contributor

Contributor intent (required human answers)

1. What outcome do you want to achieve?

Let people who investigate downstream-stage latency see how long a request waited for its input and how long it waited for scheduling after the input was ready, so that queueing bottlenecks are misjudged less often.

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

Whether the time at which the input gate releases the request can be recorded accurately. Without this boundary, the two kinds of waiting can only stay mixed together.

3. How will this work move that variable?

It records the time when the input gate first releases the request, passes it to the stats side, and splits the existing queued time into two parts. When the split cannot be made reliably, the new fields are left empty, and the original field stays unchanged.

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

Mainly developers and operators who troubleshoot latency in multi-stage inference. They need it to decide whether to look next at upstream input delivery or at downstream scheduling.

Is a PR needed? Yes. This boundary has to be recorded by the scheduler and passed to the stats side; changing the docs alone cannot produce the data. The related code, tests and documentation belong together in one PR.

Purpose

This is the follow-up suggested in #8575 (merged as 0d4d09c), which added the engine-core phase split to StageRequestStats and left input wait inside vllm_queued_ms.

Before. On a downstream stage that waits for its input, vllm_queued_ms (QUEUED to first SCHEDULED) also counts the time before that input arrives:

  • async_chunk: the orchestrator submits a chunk-receiving stage together with stage 0, and the input gate holds the request in WAITING_FOR_CHUNK until the first upstream chunk lands.
  • requires_full_payload_input: the request stays in WAITING_FOR_INPUT until the connector delivers the payload.

So a large vllm_queued_ms does not say whether the stage waited for upstream input or for a scheduling slot. One case from a 2026-10-16 H100 run, taken with #8575's code before this PR: Qwen3-TTS (Qwen/Qwen3-TTS-12Hz-1.7B-CustomVoice, --async-chunk --enforce-eager). The first request after server start reported a stage-1 vllm_queued_ms of 86,443 ms. The server log shows the request reaching stage 1 at 06:41:18 and stage 1 polling for its input until stage 0 enqueued its first chunk at 06:42:44, about 86 s later, so almost all of it was input wait. That request was a cold start that included a one-time FlashInfer JIT build (Building JIT module sampling); the next eight requests reported 53-421 ms. From vllm_queued_ms alone, the cold request looks the same as a scheduling backlog.

After. With --log-stats, the scheduler of a stage with an input gate records, once per request, the first step in which the request is left WAITING in a waiting queue after the gate ran. The time is sent with the engine-core events, and the output processor splits vllm_queued_ms:

Field Interval
vllm_input_wait_ms QUEUED event to the step in which the stage's input gate first saw the input ready
vllm_ready_queued_ms That step to first SCHEDULED event
  • When both are set, they add up to vllm_queued_ms.
  • Precision is one scheduler step: the recorded time is the step that saw the input, not the arrival itself. The AR scheduler stamps before upstream schedule() takes its SCHEDULED time. The generation scheduler stamps with the SCHEDULED timestamp it takes before its gates run, so a request scheduled in the step its input arrived reports vllm_ready_queued_ms = 0.
  • Both fields are None (not measured, as opposed to a measured 0) on stage 0, on a downstream stage without an input gate, with --log-stats off, and when the recorded time falls outside the queued interval, for example an AR streaming-input split that covers a later segment.
  • With active_stream_window, a request without an active-stream slot receives no chunks, so its wait for a slot counts as input wait.

Contract. docs/design/metrics.md, section "LLM-stage phase split in StageRequestStats": two table rows; the sentence about matching upstream FinishedRequestStats now covers only the first four fields; two new paragraphs on the semantics, the precision and the None cases; and the sentence "The split does not separate input wait." is removed. docs/design/module/observability.md (draft) has no per-field content and is unchanged.

What users see. Two more rows in the per-request [StageRequestStats] table (DEBUG, --log-stats), and two more keys in every stage row of build_and_log_summary()["stage_table"] (None where not measured).

Compatibility.

  • Existing fields keep their values; the new keys are only added.
  • OmniEngineCoreOutput gets input_ready_ts: float | None = None, set only on outputs that carry engine-core events. When unset it adds one byte per output on the msgpack wire (vLLM's MsgpackEncoder: 28 to 29 bytes for one default output, 107 to 110 for a batch of three in OmniEngineCoreOutputs), as the earlier is_coalesced and num_generation_tokens fields do.
  • The debug table leaves out a field that is 0 or None on every stage (existing behavior), so a measured vllm_ready_queued_ms of 0 appears only in the summary.

Not changed. The values of vllm_queued_ms, vllm_prefill_ms, vllm_decode_ms and vllm_num_preemptions; waits for later chunks (still inside vllm_decode_ms with async_chunk); diffusion stages; Prometheus families and labels; the stage_metrics snapshot, so the benchmark JSON; the duplex per-response table, which leaves the new fields out like the rest of the split.

Related.

Questions for reviewers:

  1. Where to record the time. This PR scans the waiting queues once per step after the gates run (_stamp_input_ready): one place, only in the schedulers, covering the coordinator and both chunk-adapter gate paths. Stamping next to each _waiting_since.pop in OmniSchedulingCoordinator and OmniChunkTransferAdapter would sit closer to the gate decision, but touches five call sites in two files. Which do you prefer?
  2. Names. [Core] Add LLM-stage queue/prefill/decode split to StageRequestStats #8575's vllm_queued_ms, vllm_prefill_ms and vllm_decode_ms are intervals between engine-core events, while the input-ready time here is recorded by the Omni scheduler. Keep vllm_input_wait_ms / vllm_ready_queued_ms, or rename?
  3. Is it fine to land this before the [RFC]: Request-scoped stream-edge first-event telemetry #6472 receiver boundary settles, or should it wait for [Core] Add request-owned stream-edge first-event recording #8531?

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._C absent).

vLLM-Omni Commit: 9913d9f2019ecba9e5987157763eaa1352d7b8eb (4 commits on upstream/main 303b8df65)

Environment: macOS 26.6 (arm64), Python 3.12.14, torch 2.13.0 CPU, pytest 9.1.1, msgspec 0.22.0. 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. janus, soundfile, wcwidth and torchaudio are not available. Where noted, the first three are replaced by empty stub modules so that a file can be collected; a test that really used one of them would fail.

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

# 1. New and changed tests
pytest -q tests/core/sched/test_omni_scheduler_input_ready.py \
  tests/core/sched/test_omni_sched_deferred_free_fence.py \
  tests/metrics/test_stats.py tests/engine/test_output_processor.py \
  -k "not logged_stage_table"
# 2. Input-ready time through the chunk adapter gate
pytest -q tests/core/sched/test_omni_scheduler_input_ready.py \
  tests/distributed/omni_connectors/test_chunk_transfer_adapter.py \
  -k "input_ready or active_stream_slot"
# 3. Stage table rendering (a cached wcwidth wheel added to PYTHONPATH)
pytest -q tests/metrics/test_stats.py
# 4. Stage-pool wiring (janus stubbed)
pytest -q tests/engine/test_orchestrator.py -k "stage_pool_metrics or image_ttfo"
# 5. Duplex table exclusion (janus, soundfile and wcwidth stubbed)
pytest -q tests/engine/duplex/test_engine_session.py
# 6. Neighbouring suites
pytest -q tests/engine/test_output_processor.py tests/metrics/ tests/core/sched/ \
  tests/distributed/omni_connectors/test_chunk_transfer_adapter.py \
  --ignore=tests/metrics/test_stat_logger.py \
  --ignore=tests/core/sched/test_omni_ar_scheduler_kv_transfer.py \
  --ignore=tests/core/sched/test_omni_ar_scheduler_payloadless_outputs.py \
  --ignore=tests/core/sched/test_omni_ar_scheduler_streaming.py \
  --ignore=tests/core/sched/test_omni_scheduling_coordinator.py
# 7. Three of the files ignored in run 6 (janus, soundfile and wcwidth stubbed)
pytest -q tests/metrics/test_stat_logger.py \
  tests/core/sched/test_omni_ar_scheduler_kv_transfer.py \
  tests/core/sched/test_omni_scheduling_coordinator.py

# Runs 1-5 again on upstream/main production code with this branch's test files
git worktree add --detach ../base 303b8df65
for f in $(git diff --name-only 303b8df65 HEAD -- tests); do cp "$f" "../base/$f"; done
# Runs 6-7 again on upstream/main with its own test files

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, tools/pre_commit/mypy.py 3.10, and tools/pre_commit/{check_test_marks,check_spdx_header,check_forbidden_imports,check_torch_cuda}.py.

Test Result

Run This branch (9913d9f20) upstream/main (303b8df65)
1. New and changed tests 128 passed, 2 deselected 34 failed, 94 passed; the 34 failures are exactly the new test cases
2. Chunk adapter gate 23 passed 22 failed, 1 passed
3. test_stats.py 9 passed 2 failed, 7 passed
4. test_orchestrator.py stage-pool tests 6 passed 4 failed, 2 passed
5. test_engine_session.py 70 passed 70 passed
6. Neighbouring suites 714 passed, 29 failed 677 passed, 29 failed
7. Three more files 65 passed 65 passed
  • Run 6: the 29 failures are the same list on both sides, all from this environment: missing janus (14), soundfile (5) and wcwidth (2), and 8 SharedMemoryConnector tests that need /dev/shm, which macOS does not have. The 2 tests deselected in run 1 render the table and need wcwidth; run 3 covers them.
  • Mutation checks on scratch copies of the source: stamping only waiting and not kv_holding_waiting, sending the input-ready time on outputs without engine-core events, and treating a sender-only async_chunk stage as gated each make one test fail.
  • Lint: ruff, typos, the four tools/pre_commit checks and git diff --check are clean; markdownlint reports 0 issues. mypy adds no errors: the 5 in output_processor.py and the 3 in test_engine_session.py are also on upstream/main.

Not run:

  • GPU runs, real models, multi-GPU or multi-node. There are no vllm_input_wait_ms / vllm_ready_queued_ms numbers from a served model on this branch yet; the H100 case above used [Core] Add LLM-stage queue/prefill/decode split to StageRequestStats #8575's code.
  • Served throughput or TTFP with --log-stats on vs off.
  • The requires_full_payload_input path with real connector delivery; only CPU unit tests cover it.
  • The generation scheduler's fallback to upstream schedule(), and a gate that releases a request whose first chunk carries no token (the generation fast path would then skip it, so the stamp would be early and the extra time would land in vllm_ready_queued_ms). Both are reasoned from the code, not tested.
  • tests/core/sched/test_omni_ar_scheduler_payloadless_outputs.py and tests/core/sched/test_omni_ar_scheduler_streaming.py, which need torchaudio.
  • A single full pre-commit run; the hooks above were run one by one, and trailing newlines, line endings and debug statements in the changed files were checked by hand. shellcheck and the Buildkite check do not apply to these files.

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.

On a downstream stage that waits for its input, vllm_queued_ms (QUEUED to
first SCHEDULED, added in vllm-project#8575) also counts the time before that input
arrives:

- async_chunk: the orchestrator pre-submits chunk-receiving stages together
  with stage 0, and the input gate keeps the request out of the waiting
  queue (WAITING_FOR_CHUNK) until the first upstream chunk lands.
- requires_full_payload_input: the request waits in WAITING_FOR_INPUT until
  the connector delivers the payload.

The scheduler of such a stage now records, once per request, the step in
which the request is first left WAITING in a waiting queue after its input
gate ran. The time is sent with the engine-core events, and the output
processor splits vllm_queued_ms into vllm_input_wait_ms (QUEUED to input
ready) and vllm_ready_queued_ms (input ready to first SCHEDULED). Both are
None on stage 0, on stages without an input gate, and when the time does
not fall inside the queued interval, for example an AR streaming split that
covers a later segment. The generation scheduler stamps with the timestamp
it uses for SCHEDULED, because that timestamp is taken before the gates run.

Existing fields keep their values. The new fields sit next to the phase
split in the [StageRequestStats] table, stay out of the duplex per-response
table, and are not added to the stage_metrics snapshot.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
The metrics design doc said the phase-split intervals match upstream
FinishedRequestStats. That holds for vllm_queued_ms, vllm_prefill_ms,
vllm_decode_ms and vllm_num_preemptions, but not for vllm_input_wait_ms and
vllm_ready_queued_ms, which split vllm_queued_ms at a time recorded by the
Omni scheduler and have no upstream counterpart. Say so.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
…dy time

_stamp_input_ready visits kv_holding_waiting as well as waiting, but no test
put a request in kv_holding_waiting, so dropping that queue went unnoticed.
Add one.

The input-ready tests only went through OmniSchedulingCoordinator. Add tests
on OmniChunkTransferAdapter, the async_chunk gate of the v1 model runner:
the time is the step that sees the first chunk, in ar and generation mode,
and is kept afterwards; with active_stream_window, a request without an
active-stream slot is not stamped, so its slot wait counts as input wait.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
The gate-flag tests faked the model and vLLM configs with SimpleNamespace,
and the engine-output test faked the request. Build them the way the
native data-plane test in the same file already does: OmniModelConfig and
VllmConfig through object.__new__, a stand-in OmniChunkTransferAdapter
through object.__new__, and a vLLM Request whose events list holds the
engine-core events. The tests check the same cases.

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

chatgpt-codex-connector Bot commented Oct 18, 2026 •

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 ✅ Completed 2026-10-18T01:38:56.067739Z 9913d9f 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.

@vllm-omni-review-bot

Copy link
Copy Markdown

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

Module owners: @lishunyang12 @vraiti @Gaohan123

Routing: @lishunyang12 via module of the changed files, module named in the PR description, CODEOWNERS; @vraiti via module of the changed files, module named in the PR description; @Gaohan123 via module of the changed files, CODEOWNERS

@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.

@vllm-omni-review-bot

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

Copy link
Copy Markdown

Omni ReviewBot triage note

Automated triage of commit e018b37d86f0 produced:

  • Priority: high. Prompt maintainer attention is suggested.

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

@MinhaoLi0318

Copy link
Copy Markdown
Contributor Author

Self-review (author). What I checked:

  • Scope: 74 production lines added, 3 removed, in 8 files; the rest is tests and docs/design/metrics.md. The core is _stamp_input_ready in omni_scheduler_mixin.py and the split in _native_phase_metrics (output_processor.py).
  • Off by default: the stamp returns early unless log_stats is on and the stage is after stage 0 with an input coordinator or a chunk-receiving adapter. input_ready_ts is sent only on outputs that carry engine-core events, so other outputs and stage 0 are unchanged.
  • Cost when on: one pass over kv_holding_waiting and waiting per scheduler step on gated stages. It only reads status and one attribute, and writes the time once per request.
  • No invented values: the split is written only when queued_ts <= input_ready_ts <= scheduled_ts. Otherwise both fields stay None, and vllm_queued_ms is never changed.
  • Against current main: re-checked today on 8da036a81, 23 commits past the base. The branch merges cleanly. I rebased it locally (not pushed) and re-ran runs 1-4 from the description: the new tests pass, and the only failures are the same 9 /dev/shm tests in test_chunk_transfer_adapter.py that also fail on unmodified 8da036a81 on macOS. ruff check and format are clean.
  • Not done: a GPU run on this branch. The H100 case in the description was taken with [Core] Add LLM-stage queue/prefill/decode split to StageRequestStats #8575's code.

The three questions in the description are where I most need a decision: where to stamp (scheduler scan vs. the five _waiting_since.pop sites), the field names, and whether this should wait for the #6472 receiver boundary (#8531).

AI assistance: drafted with Claude Code; I reviewed it before posting.

@EchoHayate

Copy link
Copy Markdown
Contributor

@MinhaoLi0318 I reviewed 9913d9f2019ecba9e5987157763eaa1352d7b8eb from the #6472 RFC side, including the scheduler observation, engine-core transport, output processor, stage aggregation, and the added tests/documentation.

Dependency: I do not see an RFC-level dependency requiring this bounded, receiver-local queue split to wait for #6472/#8531. Our earlier discussion deferred receiver integration into the cross-stage first-event contract. This PR does not implement that integration or complete the RFC.

The distinctions I would preserve are:

  • input_ready_ts is the scheduler step's observation of readiness, not consumer_first_accept (a meaningful payload decoded and committed to consumer admission). In particular, the generation path deliberately uses its existing step timestamp.
  • Both duration endpoints belong to the receiving engine-core clock. These local durations do not need the RFC's shared request origin; they must not be relabeled as request-relative milestones, cross-host transfer latency, or added to overlapping upstream/transfer intervals as an E2E decomposition.
  • This splits the initial queued interval, not every chunk wait or resumable segment. Active-stream-slot waiting can be included in input wait. Unobserved/out-of-interval observations remain absent, measured zero remains zero, and the original vllm_queued_ms stays unchanged.
  • These remain internal StageRequestStats diagnostics, not an automatic extension of the public snapshots in [Bugfix][Bench] Save per-request stage metrics in detailed results #6464, benchmark JSON, or Prometheus.

Collection point and names: the scan is consistent with the documented scheduler-observation semantics on the paths I inspected; moving the stamp to gate-release sites would be a separate precision/maintenance choice. I have no RFC-side objection to the current names with those qualifications kept explicit. Scheduler/metrics owners should make the final collection-point and naming decision; this is not maintainer approval.

Next step: please keep this PR focused and retain the untested-path/runtime limitations listed in your description. I will keep the #6472 first-event identity/lifecycle/schema coordination separate; #8531 implementation and its review fixes remain with its author. No receiver-event or public-schema expansion is requested here.

I found no concrete newly introduced P0-P2 defect in this static review. I did not run this fork's tests, a served model, or GPU validation; the earlier #8575 H100 example does not validate this branch. This comment is coordination, not a formal approval or a request to merge.

AI assistance: TRAE assisted with the source/RFC inspection and drafting.

@MinhaoLi0318

Copy link
Copy Markdown
Contributor Author

Thanks @EchoHayate, this answers the dependency question. I'll keep the PR scoped as you describe: input_ready_ts stays a scheduler-step observation on the receiving engine-core clock, it only splits the initial queued interval, and the fields stay internal to StageRequestStats (no change to #6464 snapshots, benchmark JSON or Prometheus). The untested paths and the missing GPU run on this branch stay listed in the description.

That leaves the two questions for the scheduler and metrics owners: stamp in the scheduler scan or at the gate-release sites, and the field names. @tzhouam @lishunyang12, could one of you decide these two? I'll change the code to match either choice.

AI assistance: drafted with Claude Code; I reviewed it before posting.

@hsliuustc0106 hsliuustc0106 added the high priority high priority issue, needs to be done asap label Oct 20, 2026
…-wait

# Conflicts:
#	tests/distributed/omni_connectors/test_chunk_transfer_adapter.py
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

core related to core module: cache, scheduler, engine, worker, modelrunner 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