Skip to content

[Core][Metrics] Leave unobserved diffusion timings out of per-request metrics - #9049

Open
MinhaoLi0318 wants to merge 5 commits into
vllm-project:mainfrom
MinhaoLi0318:metrics/rfc8671-pr2-diffusion-rows
Open

MinhaoLi0318 wants to merge 5 commits into
vllm-project:mainfrom
MinhaoLi0318:metrics/rfc8671-pr2-diffusion-rows

Conversation

@MinhaoLi0318

Copy link
Copy Markdown
Contributor

Contributor intent (required human answers)

1. What outcome do you want to achieve?

Make the per-request diffusion timing records tell "not measured" apart from "measured as 0", implementing the RFC's missing-value rule. For now, the log display, the responses and the Prometheus samples stay unchanged.

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

Whether a timing field is present, and whether its presence accurately reflects that the interval was measured this time. Once a missing value is written as 0 at record time, the two cases can no longer be told apart later.

3. How will this work move that variable?

Both fields are now written only after an actual measurement, and a measured 0 is still kept. The tests cover clearing the timing between consecutive outputs, and the docs describe each field's timing interval and when it is left out.

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

Mainly developers who maintain or use per-request timing data. They need to know which phases were actually measured to interpret the data correctly; this change does not directly change what end users see.

Is a PR needed? Yes, and a small scope is enough. Fixing the missing-value rule requires changing the code that actually records the data; even though the current display does not change, it is worth merging as a separate, verifiable fix.

Purpose

Part of #8671 (PR 2: diffusion rows + missing-value rule). PR 1 landed as #8804.

Before: DiffusionEngine.step_streaming wrote preprocess_time_ms: 0.0 when the model has no pre-processor, and output_ready_wait_time_ms: 0.0 when an output came back without an asynchronous wait. OrchestratorAggregator.accumulate_diffusion_metrics carried both zeros into StageRequestStats.diffusion_metrics (as preprocess_time_s and output_ready_wait_time_s), so the per-request record could not tell "not measured" from "measured as 0".

After: each of the two keys is written only after its interval was measured, and a measured 0 is kept. As on main, the output-ready wait is reset for every output (now to None instead of 0.0), so a synchronous output after an async one gets no wait key; a new test pins this. The other keys are unchanged: scheduler_queue_wait_ms was already left out when None, diffusion_engine_exec_time_ms and postprocess_time_ms are always written, kv_recv_time_ms is still left out at 0, and forward_time_ms / vae_decode_time_ms were already left out when not measured. The production change is vllm_omni/diffusion/diffusion_engine.py (+10/-6) and vllm_omni/metrics/utils.py (+5).

Contract: this implements the missing-value rule of #8671: a diffusion field that was not observed is left out of the per-request record instead of being written as 0.0. docs/design/metrics.md gets a new section, "Diffusion-stage timings in StageRequestStats", after the LLM-stage split section from #8575. It gives each key's interval and when the key is left out, and says that only final-output diffusion stages have these timings, that only the output finishing the stage is counted, and that the rows overlap and must not be added together.

What users see: nothing changes today.

  • The [StageRequestStats] DEBUG table already hides a row whose values are all zero or missing (vllm_omni/metrics/stats.py:1062-1078), so these rows look the same. The one exception: if a request has two final-output diffusion stages and only one of them measured the interval, the other cell is now blank instead of 0.000.
  • Responses and the stage_metrics snapshot do not carry the engine's diffusion metrics: OmniRequestOutput._copy_content_from does not copy them, omni_base.py builds response_metrics from the stage events, and _merge_stage_metric_event does not read diffusion_metrics.
  • vllm_omni:diffusion_preprocess_s keeps its 0 sample for a request without a pre-processor: observe_diffusion_finalize records 0 when preprocess_time_s is absent and diffusion_engine_exec_time_s is present (vllm_omni/metrics/utils.py:131-135). [RFC]: Diffusion-phase and per-request transfer attribution fields (companion to #6472) #8671 leaves this sample to the metrics owners; if they want it dropped, deleting those lines does it.

Compatibility: no new field, no new collection, no new flag, no public schema change. Code that indexes diffusion_metrics["preprocess_time_s"] or diffusion_metrics["output_ready_wait_time_s"] directly would now need .get(). Nothing in the repo does: the accumulator and the table builder copy whatever keys are present, and observe_diffusion_finalize uses .get().

Not changed:

  • docs/usage/metrics.md:72 still describes vllm_omni:diffusion_postprocess_s as "Diffusion output postprocessing (VAE decode)". That label does not match the interval documented here (the model's post-processor, the move to CPU under model-level CPU offload, and output formatting). I left it for a separate change.
  • The DEBUG step_streaming breakdown log line still prints 0.00 ms for an interval that was not measured. It is a log line, not a record.
  • The histogram sample above, and the transfer rows (PR 3 of [RFC]: Diffusion-phase and per-request transfer attribution fields (companion to #6472) #8671).

Test Plan

vLLM Version: 0.31.0, CPU only: vLLM source (git archive v0.31.0) on PYTHONPATH, torch 2.13.0 (CPU), pytest 9.1.1, Python 3.12.14, VLLM_TARGET_DEVICE=cpu, Apple M5 Pro. Not the CI image.

vLLM-Omni Commit: dddc2af81 (this PR, rebased on main 303b8df65).

  • tests/diffusion/test_diffusion_step_streaming_metrics.py (new) drives step_streaming with a stubbed scheduler stream and executor, then follows the keys through OrchestratorAggregator into the per-request record. tests/metrics/test_modality.py adds accumulator and preprocess-histogram cases.
  • The same tests against main's production code, to show they catch the old behavior.
  • The surrounding metrics, diffusion-engine and orchestrator tests on this PR and on main.
  • The pre-commit hooks on the changed files.

Test Result

python -m pytest -q tests/diffusion/test_diffusion_step_streaming_metrics.py \
  tests/diffusion/test_diffusion_engine_metrics.py tests/metrics/test_modality.py

python -m pytest -q tests/metrics tests/diffusion/test_diffusion_engine_metrics.py \
  tests/diffusion/test_diffusion_engine.py tests/diffusion/test_diffusion_engine_cleanup.py \
  tests/diffusion/test_diffusion_scheduler.py tests/diffusion/test_stage_diffusion_proc.py \
  tests/diffusion/test_inline_stage_diffusion_client.py tests/diffusion/test_stage_diffusion_client.py \
  tests/diffusion/test_async_output_timeout.py tests/diffusion/test_result_pump.py \
  tests/engine/test_output_processor.py tests/engine/duplex/test_engine_session.py \
  tests/engine/test_orchestrator.py tests/diffusion/test_diffusion_step_streaming_metrics.py
  • The three test files: 74 passed at dddc2af81. The same files with main's production code (303b8df65): 6 failed, 68 passed. The failures are the four step_streaming tests that check that a key is absent (two of them across consecutive outputs), test_timing_metric_key_naming_consistency, and test_preprocess_histogram_keeps_zero_sample_without_preprocessor.
  • Moving the output_ready_wait_time = None reset out of the per-output loop fails test_output_ready_wait_does_not_carry_to_the_next_output (1 failed, 73 passed).
  • Wider suite: 763 passed, 1 failed at dddc2af81; 753 passed, 1 failed on main 303b8df65 (without the new test file, which main does not have). The failure is the same on both: tests/diffusion/test_diffusion_engine.py::test_move_tensor_tree_moves_nested_cuda_tensors_to_cpu needs CUDA (Torch not compiled with CUDA enabled). The 10 extra passes are this PR's new tests.
  • Pre-commit hooks on the changed files, at the pinned versions: ruff 0.14.10 check and format, typos 1.49.0, markdownlint-cli2 0.23.2 (docs/design/metrics.md), check-mark, check-spdx-header, check-forbidden-imports and check-torch-cuda-call pass, and git diff --check is clean. mypy-3.10 (mypy 1.11.1) reports 10 errors, the same 10 as main on these files, none on a changed line (CI skips this hook).

Overhead (#8671 asks each PR to report it). This PR adds no collection: each output does two is not None checks and two or 0.0 for the DEBUG log line, and writes up to two fewer dict keys; finalize adds a couple of None checks. In a CPU microbenchmark (Apple M5 Pro, median of 15 × 2000 requests, 2 runs each), this PR is not slower than main on any path (table below): it is lower in both runs on the engine path and the Prometheus-off path, and within main's two runs on the Prometheus-on path. So collection does not need to become opt-in.

Benchmark table and script

µs per request, run 1 / run 2:

path main 303b8df65 this PR dddc2af81
DiffusionEngine.step_streaming, stubbed stream and executor, one sync output, no pre-processor 2.20 / 2.45 2.15 / 2.16
accumulate_diffusion_metrics + on_stage_metrics + observe_modality_at_finalize, Prometheus modality observation on (aggregator log_stats always on) 6.02 / 5.72 5.85 / 5.78
same, Prometheus modality observation off (aggregator log_stats always on) 2.59 / 2.48 2.37 / 2.31

In the script, log_stats_on / log_stats_off is OmniModalityMetrics(log_stats=...); the OrchestratorAggregator has log_stats=True in both. Run once per checkout, with that checkout first on PYTHONPATH: python bench_pr2.py <label>.

"""CPU micro-benchmark for RFC #8671 PR 2 (run once per worktree via PYTHONPATH).

engine: DiffusionEngine.step_streaming per request (1 output, stubbed scheduler
        stream and executor; sync output, no pre-processor = the case PR 2 changes).
orch:   accumulate_diffusion_metrics + on_stage_metrics + observe_modality_at_finalize
        per request, with OmniModalityMetrics(log_stats=on/off).
"""
import asyncio, statistics, sys, time
from types import SimpleNamespace
from vllm_omni.diffusion.data import DiffusionOutput
from vllm_omni.diffusion.diffusion_engine import DiffusionEngine
from vllm_omni.diffusion.request import OmniDiffusionRequest
from vllm_omni.inputs.data import OmniDiffusionSamplingParams
from vllm_omni.metrics import OrchestratorAggregator
from vllm_omni.metrics.modality import OmniModalityMetrics, observe_modality_at_finalize
from vllm_omni.metrics.stats import StageRequestStats, StageStats

def make_engine():
    e = DiffusionEngine.__new__(DiffusionEngine)
    e.od_config = SimpleNamespace(); e.pre_process_func = None; e._scheduler_num_waiting_reqs = 0
    async def nl(): return None
    async def stream(_rid):
        yield DiffusionOutput()
    e._check_and_start_background_loop = nl
    e._add_prepared_request = lambda r: r.request_id
    e.get_output_stream = stream
    e.postprocess_output = lambda r, o: [SimpleNamespace(metrics={})]
    e.executor = SimpleNamespace()
    return e

async def engine_loop(n):
    e = make_engine()
    req = OmniDiffusionRequest(prompt="p", sampling_params=OmniDiffusionSamplingParams(num_inference_steps=4), request_id="r")
    req.scheduler_queue_wait_ms = 1.0
    out = None
    t0 = time.perf_counter_ns()
    for _ in range(n):
        async for batch in e.step_streaming(req):
            out = batch
    return (time.perf_counter_ns() - t0) / n, out[0].metrics

def orch_loop(n, mod, engine_metrics):
    agg = OrchestratorAggregator(num_stages=1, log_stats=True, wall_start_ts=0.0, final_stage_id_for_e2e=0)
    outs = [SimpleNamespace(metrics=dict(engine_metrics))]
    t0 = time.perf_counter_ns()
    for i in range(n):
        rid = f"r{i}"
        st = StageRequestStats(batch_id=1, batch_size=1, num_tokens_in=0, num_tokens_out=0, stage_gen_time_ms=40.0,
                               rx_transfer_bytes=0, rx_decode_time_ms=0.0, rx_in_flight_time_ms=0.0, stage_stats=StageStats(),
                               num_inference_steps=4, output_unit_type="image")
        agg.accumulate_diffusion_metrics("diffusion", rid, outs)
        agg.on_stage_metrics(0, rid, st, "image")
        observe_modality_at_finalize(mod, output_type="image", stage_id=0, replica_id=0, stage_metrics=st, engine_outputs=outs[0])
    return (time.perf_counter_ns() - t0) / n

def main():
    label = sys.argv[1]
    n, reps = 2000, 15
    eng = []; metrics = None
    for _ in range(reps):
        ns, metrics = asyncio.run(engine_loop(n)); eng.append(ns)
    res = {"engine_ns_per_req": statistics.median(eng), "engine_min": min(eng), "engine_max": max(eng)}
    for flag in (True, False):
        mod = OmniModalityMetrics(model_name=f"bench-{label}-{flag}", log_stats=flag)
        xs = [orch_loop(n, mod, {k: v for k, v in metrics.items() if k != "scheduler_num_waiting_reqs"}) for _ in range(reps)]
        res[f"orch_ns_per_req_log_stats_{'on' if flag else 'off'}"] = statistics.median(xs)
        res[f"orch_range_{'on' if flag else 'off'}"] = (round(min(xs)), round(max(xs)))
    print(label, sorted(metrics.keys()))
    for k, v in res.items():
        print(f"{label}\t{k}\t{v if isinstance(v, tuple) else round(v)}")
main()

Not covered:

  • No GPU, no real model, no served run. The step_streaming tests use a stub executor that returns DiffusionOutput directly, so the async-output path through shared memory and the result pump is not exercised.
  • Served throughput and TTFP on vs off, including the ~12.5 Hz pipeline that [RFC]: Diffusion-phase and per-request transfer attribution fields (companion to #6472) #8671 asks for: not measured; only the CPU microbenchmark above.
  • Not run in the CI image, and no full pre-commit run --all-files (shellcheck not run; no shell file changed).

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.

@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:35:36.605683Z dddc2af 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/observability.md, docs/design/module/diffusion/index.md, docs/design/module/diffusion/diffusion_runtime.md.

Module owners: @david6666666 @Isotr0py @princepride

Routing: @david6666666 via module of the changed files, module named in the PR description, CODEOWNERS; @Isotr0py via module of the changed files, module named in the PR description; @princepride via module of the changed files, module named in the PR description

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

@MinhaoLi0318

Copy link
Copy Markdown
Contributor Author

Self-review (author). What I checked:

  • Scope: 15 production lines added, 6 removed, in vllm_omni/diffusion/diffusion_engine.py and vllm_omni/metrics/utils.py; the rest is tests and a new section in docs/design/metrics.md.
  • Only two keys change: preprocess_time_ms is written only when a pre-processor ran, and output_ready_wait_time_ms only when the output waited on an async result. A measured 0 is still written. The other keys in metrics_update are unchanged.
  • No stale value: the output-ready wait is still reset for each output (now to None), and a test checks that a sync output after an async one gets no wait key.
  • Readers: nothing in the repo indexes these two keys directly. The accumulator copies the keys that are present, and observe_diffusion_finalize uses .get(). The diffusion_preprocess_s histogram keeps its 0 sample on purpose (utils.py), pending the metrics owners' answer in [RFC]: Diffusion-phase and per-request transfer attribution fields (companion to #6472) #8671.
  • 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 the three test files from the description: 74 passed. ruff check and format are clean.
  • Not done: a GPU or served run. The async-output path through shared memory and the result pump is not exercised by these tests.

One decision for review: keep or drop the 0 sample in vllm_omni:diffusion_preprocess_s for requests without a pre-processor. Dropping it means deleting the 5 lines in observe_diffusion_finalize.

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

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

@MinhaoLi0318

  • Update this branch against current main and resolve the merge conflicts. GitHub now reports mergeable=false / dirty at head dddc2af817c9f22cb81d9e51d17f5faf649b916d, so the earlier locally clean merge is no longer sufficient. Push the resulting fix SHA and rerun the three focused metrics test files, reporting the command, environment and result. Acceptance: GitHub reports a clean merge at the updated head and the affected metrics regressions still pass.

This is a merge-readiness blocker, not a new runtime-defect finding.

… metrics

DiffusionEngine.step_streaming wrote preprocess_time_ms = 0.0 when the model
has no pre-processor and output_ready_wait_time_ms = 0.0 when the output
needed no async wait. Those zeros were stored in
StageRequestStats.diffusion_metrics as if they had been measured. Write each
key only when its interval was observed; a measured 0 is still written.

Nothing user-visible changes today. The [StageRequestStats] debug table
already hides a field whose values are all zero or missing, the stage_metrics
snapshot and responses do not carry these keys, and the
vllm_omni:diffusion_preprocess_s histogram keeps its 0 sample for requests
without a pre-processor, so its population does not change. The internal
record now tells a missing interval from a measured 0, so a later schema
decision can map a missing value to null.

The output stream now records the async-output wait on
DiffusionOutput.output_ready_wait_time (vllm-project#6580). Its default changes from
0.0 to None, so an output the stream did not wait for keeps the field
unset and step_streaming leaves output_ready_wait_time_ms out; the stream
still sets the measured value, including a measured 0.

Implements the diffusion-row missing-value rule of RFC vllm-project#8671 (PR 2).

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
Describe each diffusion engine timing kept per request in
StageRequestStats.diffusion_metrics: its interval, when it is left out,
which stages report it, and how the rows overlap.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
…t output

Add the reverse order to the per-output wait test: an async output followed
by a synchronous one. The existing order (sync, then async) passes even if
the wait variable is initialized once before the output loop. Also describe
the table check as the stage_table rows that build_and_log_summary returns,
which is what the test asserts.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
Describe postprocess_time_ms as the whole engine-side post-processing (the
model's post-processor, the CPU move under model-level offload, and
formatting), note the synchronous receive on a KV prefetch miss, say that
_ms is replaced by _s, that hidden all-zero rows still apply, and that only
the output that finishes the stage is counted. Drop the issue reference
from the design text.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
Build the formatted outputs as OmniRequestOutput and resolve async
outputs through a small executor fake instead of SimpleNamespace, and
drop the od_config stub that step_streaming does not read.

Signed-off-by: MinhaoLi0318 <lminhao039@gmail.com>
@MinhaoLi0318
MinhaoLi0318 force-pushed the metrics/rfc8671-pr2-diffusion-rows branch from dddc2af to cab730d Compare October 19, 2026 03:17
@MinhaoLi0318

Copy link
Copy Markdown
Contributor Author

@hsliuustc0106 Rebased onto current main (21ef5b4bb); new head cab730d8e. It still merges cleanly into the latest main (a94a552ca).

The only conflict was in diffusion_engine.py, with #6580. #6580 moved the async-output wait into the stream and added DiffusionOutput.output_ready_wait_time with a default of 0.0. I kept #6580's structure and changed that default to None, so the field stays unset unless the stream actually waited for an async output. With 0.0, outputs that never waited would report output_ready_wait_time_ms=0.0, which is the case this PR leaves out. The stream still sets the measured value where it waits (diffusion_engine.py:1522), and exec_total_time subtracts (output_ready_wait_time or 0.0). The change is in the first commit, so each commit passes on its own.

The streaming test fakes now go through the real get_output_stream / _iterate_output_stream path from #6580. I added test_output_without_async_wait_leaves_wait_unset; with the default set back to 0.0, 4 tests in that file fail.

Tests (local CPU run, not the CI image: macOS, Python 3.12.14, torch 2.13.0, vLLM 0.31.0, VLLM_TARGET_DEVICE=cpu):

pytest tests/diffusion/test_diffusion_step_streaming_metrics.py tests/diffusion/test_diffusion_engine_metrics.py tests/metrics/test_modality.py -q
75 passed

I also ran #6580's engine tests and the diffusion tests touched by #8952. The failures there (1 and 7, CUDA-only or environment related) are the same on plain main.

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

@hsliuustc0106 hsliuustc0106 added benchmark/profiler/metrics/logger Codes related to benchmarks, profiler, metrics and logger system core related to core module: cache, scheduler, engine, worker, modelrunner labels Oct 19, 2026
@vllm-omni-review-bot

Copy link
Copy Markdown

Omni ReviewBot: no human activity for 7 days

@MinhaoLi0318 this pull request has had no human commit, comment or review since 2026-10-19. Please confirm the current plan and next step. 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.

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

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants