Repository navigation
[Frontend] Emit per-turn --log-stats tables for native duplex - #6892
guozhihao-224 wants to merge 8 commits into
Conversation
|
Codex usage limits have been reached for code reviews. Please check with the admins of this repo to increase the limits by adding credits. |
|
This PR appears to belong to: docs/design/module/observability.md. Module owners: @lishunyang12 @vraiti @guozhihao-224, 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. |
Omni ReviewBot triage noteAutomated triage of commit
These are automated triage suggestions only — the final decision belongs to the maintainers. |
f40ac21 to
db00e28
Compare
Self-reviewChecked against the Phase-1 slice of #6614 (log tables only; Prometheus / audio TTFP are follow-ups).
|
|
Reviewed at
Question rather than a finding: Non-goals in #6614 look respected: keyed on |
|
@ZacheryAU PTAL |
Thanks for the review — addressed in
L1: 57 passed ( |
|
Verified at Debug is fine for the unmapped keys — your noise point is right, a per-turn warning would be worse. If you want it visible without the spam, |
|
Reviewed ce11c40 against the Phase-1 slice of #6614. The skeleton is right: one assistant turn (
Please also take these:
|
|
@natureofnature @Sy0307 PTAL |
|
@amy-why-3459 is right, and my earlier suggestion pointed at the wrong site. Confirmed at |
Sy0307
left a comment
There was a problem hiding this comment.
Three targeted findings below. The duplicate [OmniTiming] issue is already covered by the existing thread.
ce11c40 to
381f9c3
Compare
|
Thanks @amy-why-3459 @Sy0307 @ZacheryAU @shiy1022 — this update is the Phase-1 review follow-up. It does not close #6614 (
Prometheus / audio TTFP / session rollup stay out of this PR. |
Native duplex keeps one long-lived stage-0 request, so chat generate() never finalizes a turn. Key the aggregator by response_id and log the same tables as /v1/chat/completions on done, barge-in, close, and abort. Related to vllm-project#6614 (PR1: log tables only) Signed-off-by: guozhihao-224 <guozhihaoemail@gmail.com>
Keep barge-in/cancel/close distinct from abort in log tables, and use stage_submit_ts for wall-clock first-ts so duplex matches chat. Signed-off-by: guozhihao-224 <guozhihaoemail@gmail.com>
|
Reviewed 166bfe9 against the Phase-1 slice of #6614 and the earlier request-changes thread. The landing path caught up:
Also: |
Signed-off-by: guozhihao-224 <guozhihaoemail@gmail.com>
166bfe9 to
226b43d
Compare
|
Thanks @amy-why-3459 — addressed on this push. CI. test_abort_emits_table_once_then_close_is_noop now stubs abort_async(return_value=[]). _abort still leaves request_states so generate() can consume the synthetic abort; the test asserts the turn table is emitted once and a second finalize is a no-op. Dump titles. Stage / E2E / Transfer titles now include the engine resource request_id plus response= / turn= / reason=, so grep request_id=duplex-s hits the tables. Row keys stay response_id. TTFO / OmniTiming. Duplex dumps omit serving_time_to_first_output_ms (still an epoch-ms clock; Prometheus audio TTFP stays PR2+). [OmniTiming] skips total= / engine= when there is no preprocess_ms; chat without timing_identity is unchanged. Also in this pass. Native append stamps arrival_ts before begin_response and on_begin forwards it. Chat completions no longer fill duplex_turn_pending. Token-weighted vllm_tpot_ms is pinned in test_stats.py. Docs record wall vs compute, listen-before-speak attribution to the first speak table, and that listen-only still emits no table. Local CUDA L1 Other Test: abort / dump / tpot cases passed. Remaining 8 failures (test_serve_cli, transcript helpers, torch profiler excel) are unrelated to this PR. |
Keep turn-metrics on the graduated duplex_request_client path after vllm-project#6196. Co-authored-by: Cursor <cursoragent@cursor.com> Signed-off-by: guozhihao-224 <guozhihaoemail@gmail.com>
|
RFC #6494 tracks this as Phase 1 under #6895/#6614. The current scope is per-turn log tables with stable reason/timestamp/aggregation semantics; Prometheus, audio TTFP, and session rollups remain Phase 2. Please keep #6614 open until those follow-ups have an owner and a separate implementation path. |
|
@guozhihao-224 CUDA CI is still red on GHA / DCO / Intel / NPU / RTD are green. This is the remaining merge gate. Your Please re-run the CI command, not only the five files in the body: pytest -n 0 -s -v -m "core_model and cpu" --ignore=tests/diffusion --ignore=tests/model_executor AMD #11429 (3/19) is a different pipeline. Do not treat it as this PR, and do not use it to explain away the CUDA red. Paste the two CUDA node ids after they are green. |
|
@guozhihao-224 This PR currently has merge conflicts with |
…log-metrics # Conflicts: # tests/entrypoints/openai_api/test_duplex_handler.py # vllm_omni/entrypoints/client_request_state.py # vllm_omni/entrypoints/duplex/protocol.py # vllm_omni/entrypoints/duplex/serving.py Signed-off-by: guozhihao-224 <guozhihaoemail@gmail.com>
finalize_turn_metrics is now safe to call for any aborted request id. Cleanup of the per-turn aggregator is restricted to native duplex stage resource ids (mirroring begin_turn_metrics), so ordinary AR aborts no longer dereference missing turn state on their request states. Fixes the persistent Buildkite "Simple · Engine&Entrypoints" failures (test_abort_* failing on SimpleNamespace request states) and adds a regression test. Signed-off-by: guozhihao-224 <guozhihaoemail@gmail.com>
|
Root-caused the persistent Buildkite failures by reproducing the CI locally (vllm 0.29.0 +
Remaining local-only failures ( |
| request_id="", | ||
| final_output_type=final_output_type, | ||
| ) | ||
| req_state.duplex_turn_pending.append( |
There was a problem hiding this comment.
Collapse pending listen metrics per stage instead of retaining every snapshot.
| wall_start = float(req_state.duplex_turn_arrival_ts) | ||
| if wall_start <= 0: | ||
| wall_start = time.time() | ||
| turn = DuplexTurnMetrics( |
There was a problem hiding this comment.
Skip per-turn metric collection when log_stats is disabled.
Omni ReviewBot: CI is red on this head@guozhihao-224 required checks failed on Please fix the failure and push again; this note is updated in place when the head goes green or moves. |
Omni ReviewBot: no human activity for 14 days@guozhihao-224 this pull request has had no human commit, comment or review since 2026-09-15. Please consider marking this PR as draft until work can resume. The author or a maintainer decides whether to change the PR state. To keep it moving, any one of these is enough: push an update, reply to the open blocker, or post the current plan and timeline. |
|
@guozhihao-224 this PR is labeled Could you please take a look and push an update to get CI green? Once the checks pass we can proceed with review/merge. Thanks! |
Omni ReviewBot routing recordAssigned Strict on cursor (cursor-grok-4.6-high) under experiment |
|
@guozhihao-224 gentle ping — this high-priority PR has seen no updates for 24 days and review feedback is waiting. Could you share a status or ETA when you get a chance? Thanks! |
Omni ReviewBot attempt recordReview attempt ended as timeout (Strict attempt outlived its budget; falling back to direct/cursor/auto). |
vllm-omni-review-bot
left a comment
There was a problem hiding this comment.
Omni ReviewBot review
Changes since the previous review
- 3 new inline finding(s); 2 finding(s) below.
CI at
5f33fbfb2069(2026-10-09T21:56:54.462422+00:00): verification incomplete; required-check status is unknown. Observed Buildkite:buildkite/vllm-omni-npu-ci(passed),buildkite/vllm-omni-amd-ci(failed),buildkite/vllm-omni(failed), and 1 more.
Note: The assigned review arm
strict/cursor/cursor-grok-4.6-highcould not complete this review, so it was produced by the fallback armdirect/cursor/auto. It is excluded from the routing experiment.
Full review analysis
PR description
With --log-stats, native full-duplex now prints the same end-to-end, stage, and transfer tables once per assistant turn. A long-lived stage-0 session request stays open; begin_response / end_response open and finalize a separate aggregator keyed by response_id, including buffered stage snapshots that arrive before the response starts. Chat generate() cleanup is unchanged. Cancel, close, barge-in, and abort each print one table with a distinct reason, and the stage title carries the engine request id plus response, turn, and reason.
Change flow
flowchart LR
A["[EXISTING] Native duplex append / response"]:::existing
B["[CHANGED] Session begin and end hooks"]:::changed
C["[CHANGED] OmniBase stage ingest"]:::changed
D["[NEW] Per-turn aggregator"]:::new
E["[CHANGED] log-stats table dump"]:::changed
A --> B
A --> C
C --> D
B --> D
D --> E
classDef existing fill:#e5e7eb,stroke:#6b7280,color:#111827
classDef changed fill:#fef3c7,stroke:#d97706,color:#451a03,stroke-width:2px
classDef new fill:#dcfce7,stroke:#16a34a,color:#052e16,stroke-width:2px
classDef removed fill:#fee2e2,stroke:#dc2626,color:#450a0a,stroke-width:2px
Findings
- [P2] Duplex turn metrics are collected when log-stats is off —
vllm_omni/entrypoints/omni_base.py:460
Existing thread: #6892 (comment)
Evidence for Duplex turn metrics are collected when log-stats is off
OmniBase defaults log_stats to false, but _accumulate_duplex_turn_metrics only checks is_duplex_resource_request_id. Every stage-0/TTS snapshot for a duplex resource id is copied into duplex_turn_pending or the open turn aggregator, and begin_turn_metrics still builds that aggregator. --log-stats off therefore pays per-chunk copy and list growth on the native output path and only skips build_and_log_summary. Return before queue_turn_stage_metrics when log_stats is false, and skip begin_turn_metrics the same way.
Evidence for Pre-response snapshots are retained one-for-one
Before begin_response, queue_turn_stage_metrics appends every StageRequestStats copy to duplex_turn_pending. A listen-only auto-response never opens a turn, so this list grows for the whole session until close() drops request_states. Finalize does not clear it when duplex_turn is still none. Collapse into one merged row per stage with _merge_stage_metric_event as each snapshot arrives so a long listen cannot retain every chunk.
🤖 This review was generated by InferMatrix Copilot, an open-source repo-maintenance agent for PR review, CI debugging and issue triage. Try it on your own repo, and ⭐ star it if it helped!
| emitted = finalize_duplex_turn_metrics(turn, reason=reason) | ||
| req_state.duplex_turn = None | ||
| req_state.duplex_turn_pending = [] | ||
| req_state.duplex_turn_arrival_ts = None |
There was a problem hiding this comment.
[P1] Turn finalize wipes the next turn's arrival stamp
Evidence and suggested fix
On a normal auto-response handoff, start_native_append stamps duplex_turn_arrival_ts before the append, then _end_active_response_before_future_model_turn ends the open response and the speak path calls begin_response. finalize_turn_metrics sets duplex_turn_arrival_ts = None after logging the old turn. on_begin then calls mark_turn_arrival, sees an empty stamp, and stores time.time() at speak. The commit/append t0 collected for the next turn is discarded in that same call, so e2e_total_ms starts at begin_response instead of the first append. begin_turn_metrics already clears the stamp it consumes; finalize should leave a stamp that was set after the current turn opened.
| elif event_type == "response.cancel": | ||
| cancel_reason = "client_cancelled" | ||
| else: | ||
| cancel_reason = "cancel" |
There was a problem hiding this comment.
[P2] input.cancel now changes the audio.cancelled reason
Evidence and suggested fix
input.cancel used to pass reason="barge_in" into _cancel_active_response. The else branch now passes "cancel". That string is both mapped to the log finished_reason and copied into audio.cancelled.reason (serving.py sends "reason": reason). _signal_runtime_session for this same branch still signals the engine with "barge_in". Clients that treat audio.cancelled.reason == "barge_in" as user cancel now see cancel, which this PR does not describe as a wire change. Keep the existing event reason and map it only through finished_reason_for_cancel.
| from vllm_omni.outputs import OmniRequestOutput | ||
| from vllm_omni.outputs.duplex import attach_duplex_output_decision | ||
|
|
||
| pytestmark = [pytest.mark.core_model, pytest.mark.cpu] |
There was a problem hiding this comment.
[P1] Reported L1 commands do not match the CPU guard selectors
Evidence and suggested fix
Changed entrypoint and metrics paths are guarded by .buildkite/cuda/test-ready.yml (the merge pipeline uses the same commands). Simple · Engine&Entrypoints Test runs pytest -sv tests/entrypoints tests/engine -m 'core_model and cpu'. Simple · Other Test runs pytest -sv tests/ -m 'core_model and cpu' --ignore=tests/diffusion --ignore=tests/model_executor --ignore=tests/entrypoints --ignore=tests/engine, which includes tests/metrics. The PR Test Result reports only tests/metrics/test_duplex_turn_metrics.py, tests/metrics/test_stats.py, tests/entrypoints/test_async_omni_duplex.py, and two test_duplex_handler.py cases. It states that L2 protocol smoke and the auto_response L3 rerun were skipped, not that these CPU marker jobs were skipped. Re-run those two selectors or record that gap in the test result.
Omni ReviewBot: finding feedback[p1] Reported L1 commands do not match the CPU guard selectors — See the review for details. If you are the PR author and disagree, react 👎 here; the maintainer will see your disagreement. |
Omni ReviewBot: finding feedback[p1] Turn finalize wipes the next turn's arrival stamp — See the review for details. If you are the PR author and disagree, react 👎 here; the maintainer will see your disagreement. |
Purpose
Implements the Phase-1 slice of #6614. Does not close that issue (
Related to #6614); Prometheus / audio TTFP / session rollup remain PR2+.Chat
/v1/chat/completionsalready printsOverall Summary/RequestE2EStats/[OmniTiming]/StageRequestStatswhen--log-statsis on. Native full-duplex (/v1/realtime?duplex=1) did not, because work rides a long-lived stage-0 request throughappend_duplex_input_asyncinstead ofgenerate().This PR treats one assistant turn (
response_id) as one chat completion:DuplexSession.begin_response/end_responsedrivebegin_turn/finalize_turnon the request clientresponse_idbegin_responseare buffered and flushed at begin;arrival_tsis commit/first-append (or first bufferedstage_submit_ts)_cancel_active_responsemaps native sources onto log reasons (session_close/disconnect*→close,timeout/new_response/input.cancel→cancel, real barge-in staysbarge_in)vllm_tpot_msis token-weighted (weight = max(num_tokens_out - 1, 1)); one[OmniTiming]row per turn includesreason_abort(before pop), idempotentrequest_idcolumn is the turn'sresponse_idgenerate()/_log_summary_and_cleanupare unchangedchatcmpl-*) and existing fake duplex test ids do not duplex-finalize (is_duplex_resource_request_idrequiresduplex-s.+ 8-part resource format)request_statesOut of scope (RFC PR2+): Prometheus, audio TTFP, session rollup,
protocollabel, listen counter.Test Plan
vLLM Version: 0.27.1 (aligned with Omni 0.27.0rc2; torch 2.13.0+cu130)
vLLM-Omni Commit: (fill after push)
Test Result
tests/metrics/test_duplex_turn_metrics.py+tests/metrics/test_stats.py+ cancel mapping tests +tests/entrypoints/test_async_omni_duplex.py: passed locally after the review follow-upresponse_requiredrun): 1 passed; auto_response path not re-run in this follow-upL1 coverage: resource-id filter, turn accumulate/collapse with token-weighted tpot, two turns → two tables, log_stats off, auto_response metrics flushed at begin, session_close cancel →
reason=closethen laterclose()silent, barge-in / abort finalize before pop, one[OmniTiming]identity row, session TX copied into the turn aggregator, chat_log_summary_and_cleanupdoes not use duplex_turn, listen snapshots are not double-counted, hook / summary exceptions do not break protocol state.Known pre-existing stats quirk, not in this PR: serving_time_to_first_output_ms looks like epoch-ms. Prometheus / audio TTFP are RFC PR2.
Not run: L2 MiniCPM-o protocol smoke (handshake only; it does not assert turn tables).