Files
aituner/docs/opprof/patch-design.md
Gahow Wang d5b276180d Add OpProf campaign: protocols, results, patches, run evidence (P0-P6)
Workload-conditioned operator profiling on patched vLLM 0.24.0 +
Qwen3-30B-A3B/H20. H1b PASS (irregular patterns carry +23-45pp R64
raggedness, 8-45% token-efficiency loss vs rectangular controls);
mechanism decomposition kills the padding narrative and finds the
arrival-uniformization artifact (-12.9%); cross-version churn surface
shows TP2/MNS64 -29.4% across vLLM 0.20->0.24 while the argmax held.
Raw Layer-1 JSONL streams (507 MB) stay on disk, git-ignored; footer
sidecars and metrics are tracked.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-07-13 11:06:10 +08:00

25 KiB

OpProf dual-layer instrumentation patch design

Status: design for review; no vLLM patch has been implemented.

Target source: vLLM v0.24.0, commit ee0da84ab9e04ac7610e28580af62c365e898389. Target campaign: Qwen3-30B-A3B serving on NVIDIA H20 (SM90), using the V1 engine. All source paths and line numbers below are relative to the pinned clone.

Approved dispositions (2026-07-11)

  • Use JSONL with msgspec, the proposed context/chunk histogram edges, and an 8192-record bounded queue.
  • Keep exact expert loads Layer-2-only.
  • Use the community BF16 Qwen3-30B-A3B checkpoint. TP1 is primary, with TP2 and TP4 counterpoints; record the selected MoE backend logs in every run.
  • Use two profiler warm-up iterations followed by eight active iterations.
  • Apply the 3% Layer-1 overhead gate to the upper bound of the 95% confidence interval for every primary serving metric.
  • Reject --disable-log-stats when OpProf is enabled; retain the five-file fail-fast design.

Goal and success criteria

The patch should make every serving iteration conditionable on its request and execution pattern while keeping the always-on path below a 3% serving overhead budget. Heavy kernel tracing and exact MoE routes are sampled separately.

The proposed split is:

  1. Layer 1: one compact composition record per scheduler step, emitted by the scheduler process rather than every tensor-parallel worker.
  2. Layer 2: short, sampled windows using vLLM's existing torch-profiler configuration and /start_profile and /stop_profile endpoints.

The design deliberately does not add hooks to GPU kernels, attention layers, the Qwen model, or the OpenAI serving API. Those surfaces are not needed to answer the Phase 0 profiling questions.

Assumptions and tradeoffs

  • The campaign uses the V1 engine and the default vLLM scheduler. Both the synchronous and AsyncScheduler paths inherit the base scheduler hooks.
  • The H20 backend statement assumes the usual unquantized BF16/FP16 Qwen3-30B-A3B checkpoint, moe_backend=auto, and no LoRA. Quantization, batched expert format, or an explicit backend can change kernel selection.
  • Layer 1 requires normal stats collection, which is enabled by default. If OpProf is enabled together with --disable-log-stats, initialization should fail with an actionable error. Supporting that unusual combination would require an extra stats path and a larger patch.
  • The context-length histogram records the sequence length at the end of the scheduled model input (num_computed_tokens before scheduling plus tokens scheduled in this step). This matches the worker-side sequence-length construction at vllm/v1/worker/gpu_model_runner.py:2010-2019 and avoids retaining raw request lengths.
  • “Decode tokens” means tokens scheduled for requests classified by vLLM as generation-phase requests, including scheduled speculative tokens. It is not the number of subsequently accepted output tokens. The existing classifier and its chunked-prefill semantics are at vllm/v1/utils.py:780-813.

Existing facilities to reuse

These are zero-patch wins:

Need Existing v0.24.0 facility Design consequence
Scheduled request and token map SchedulerOutput.num_scheduled_tokens, total tokens, preempted IDs, and new/cached request data at vllm/v1/core/sched/output.py:180-219 Derive composition in the scheduler; do not add fields to SchedulerOutput.
Prefill/decode classification compute_iteration_details() at vllm/v1/utils.py:780-813 Reuse the exact definition already used by the iteration log.
Queue/KV/prefix stats SchedulerStats at vllm/v1/metrics/stats.py:170-198 and construction at vllm/v1/core/sched/scheduler.py:2228-2264 Reuse field semantics, but snapshot at schedule time to avoid async misattribution.
Per-step CUDA-graph descriptor CUDAGraphStat at vllm/compilation/cuda_graph.py:32-37, populated at vllm/v1/worker/gpu_model_runner.py:3919-3934 Reuse the object; only broaden the condition under which it is returned.
Sampled CPU/CUDA tracing profiler config and schedule at vllm/config/profiler.py:33-105, endpoints at vllm/entrypoints/serve/profile/api_router.py:21-45 Layer 2 needs configuration and orchestration, not a new profiler implementation or endpoint.
Exact routed expert IDs routed-expert capture callback and buffers at vllm/model_executor/layers/fused_moe/routed_experts_capturer.py:58-84 and vllm/v1/worker/gpu_model_runner.py:7382-7437 Use only in a separate sampled Layer-2 run; it is too expensive for Layer 1.

Layer 1: always-on composition records

Data flow and hook placement

Scheduler.schedule()
  -> snapshot request composition, queues, KV and prefix deltas
  -> SchedulerOutput -> TP workers -> ModelRunnerOutput.cudagraph_stats
  -> Scheduler.update_from_output()
  -> finalize the same step record -> bounded queue -> background JSONL writer

The scheduler is the ownership boundary for Layer 1. It sees the full logical batch once, so recording in each TP worker would duplicate data and require an aggregation protocol.

Exact proposed hooks against the pinned clone:

  1. Initialize one recorder in the base scheduler constructor. The scheduler already owns stats state and passes the normal log_stats setting into the KV-cache manager (vllm/v1/core/sched/scheduler.py:78-87 and vllm/v1/core/sched/scheduler.py:250-260). If VLLM_OPPROF_DIR is set, construct the recorder and reject log_stats=False.
  2. Begin a record inside Scheduler.schedule(). Read prefix counters at method entry, then finish the snapshot immediately after SchedulerOutput and connector metadata are constructed and before _update_after_schedule() mutates request state (vllm/v1/core/sched/scheduler.py:1012-1100). Prefix lookup counters are updated synchronously during this schedule call (vllm/v1/core/kv_cache_manager.py:202-242 and vllm/v1/core/sched/scheduler.py:675-712,897-915), so before/after deltas remain attributable even when several batches are in flight.
  3. Finalize in Scheduler.update_from_output(). Pair the returned ModelRunnerOutput with the exact SchedulerOutput at vllm/v1/core/sched/scheduler.py:1464-1477, and enqueue after normal output processing near vllm/v1/core/sched/scheduler.py:1791-1803. Store pending drafts by id(scheduler_output) and remove them on finalize; the identifier never leaves the process. This is robust to the batch queue, which retains and later returns the matching output object (vllm/v1/engine/core.py:519-632).
  4. Return the existing CUDA-graph stat when OpProf is enabled. Change the condition at vllm/v1/worker/gpu_model_runner.py:3919-3926 from only observability_config.cudagraph_metrics to that flag or VLLM_OPPROF_DIR. The file already imports vllm.envs at line 23. No CUDA synchronization or tensor transfer is introduced.
  5. Close through the existing scheduler shutdown. Drain and join the writer before the scheduler reports shutdown complete at vllm/v1/core/sched/scheduler.py:2285-2295; retain an atexit fallback for abnormal embedding/test lifecycles.

The scheduler assigns a monotonically increasing local step_index at begin. Every real scheduler call is represented, including zero-token steps. A DP-only dummy execution has no SchedulerOutput and is outside this composition stream; if DP is later in campaign scope, add a distinct dummy_step marker rather than pretending it has a request composition.

Record schema

Use schema-versioned JSON Lines. An illustrative record is:

{"schema":1,"engine_id":"dp0-pid1234","step_index":42,"submit_wall_ns":1783761000000000000,"submit_mono_ns":8920000000,"complete_mono_ns":8922371000,"model_executed":true,"scheduled_requests":37,"decode_batch_size":32,"prefill_requests":5,"prefill_tokens":896,"decode_tokens":32,"chunked_prefill":{"first":2,"middle":1,"final":1,"unsplit":1,"tokens":896,"chunk_size_hist":[0,0,1,1,1,1,1,0,0]},"context_length_hist":[0,0,3,6,12,10,5,1,0,0,0,0],"preemptions":0,"queues":{"running":37,"waiting":9,"deferred":0},"kv":{"total_blocks":120000,"free_blocks":42000,"used_blocks":78000,"usage":0.65},"prefix":{"local":{"requests":2,"queries":4096,"hits":3072,"preempted_requests":0,"preempted_queries":0,"preempted_hits":0},"external":null},"cudagraph":{"hit":true,"runtime_mode":"PIECEWISE","unpadded_tokens":928,"bucket_tokens":1024,"padding_tokens":96},"moe_expert_load":null,"dropped_records_before":0}

Required field semantics:

  • submit_wall_ns permits joining to external workload logs; submit_mono_ns and complete_mono_ns provide stable within-process ordering and elapsed time without wall-clock jumps.
  • scheduled_requests is the number of entries in num_scheduled_tokens. decode_batch_size, prefill_requests, prefill_tokens, and decode_tokens reuse vLLM's classifier.
  • chunked_prefill contains aggregate split information, never request IDs. A context request is first when the scheduled range ends before its prompt ends, middle when it was already a prefill chunk and remains incomplete, final when a prior chunk completes, and unsplit when its prefill completes in one step. chunk_size_hist uses token-count buckets (16, 32, 64, 128, 256, 512, 1024, 2048, +inf).
  • context_length_hist includes every scheduled request, with fixed upper edges (128, 256, 512, 1024, 2048, 4096, 8192, 16384, 32768, 65536, 131072, +inf). The final array therefore has 12 bins. The example above is illustrative and will be checked against the final chosen edges in tests.
  • preemptions is the size of the step's preempted_req_ids, created at vllm/v1/core/sched/scheduler.py:1059-1076. It is not an interval-derived Prometheus value.
  • Queue lengths and KV blocks are captured immediately after scheduling. KV usage follows the existing null-block-adjusted calculation at vllm/v1/core/block_pool.py:692-711. deferred means skipped/deferred waiting requests, matching num_skipped_waiting_reqs in vllm/v1/metrics/stats.py:174-183.
  • Local and external prefix fields are per-schedule deltas copied from the existing mutable counters. The existing stats drain resets those objects at vllm/v1/core/kv_cache_manager.py:190-200 and vllm/v1/core/sched/scheduler.py:2235-2242; OpProf must read, not drain or replace, them. These retain vLLM's lookup semantics: a local lookup can be counted before allocation later rejects that waiting request, so prefix requests is not required to be less than or equal to scheduled prefill requests.
  • cudagraph.hit is the operational serving definition runtime_mode != NONE. FULL selects the full graph path and PIECEWISE selects graph-wrapped compiled regions; the latter must not be interpreted as full-step graph coverage. Startup normally captures all dispatcher descriptors at vllm/v1/worker/gpu_model_runner.py:6595-6643, but the stat itself has no capture-versus-replay bit, so a rare lazy first capture cannot be distinguished from replay. bucket_tokens is num_padded_tokens in the existing stat.
  • moe_expert_load is explicitly null in Layer 1. This avoids accidentally presenting unavailable data as zero.

Encoding, buffering, and flush

JSONL is recommended over a compact binary ring buffer for Phase 1 because the schema will evolve during campaign bring-up, records need to be directly inspectable beside Kineto traces, and msgspec is already a vLLM dependency (requirements/common.txt:35). Encoding one small dictionary with a reused msgspec.json.Encoder avoids the standard json module's larger CPU cost. Once the schema stabilizes, the same record can be moved to a binary format only if Phase 2 measurements show JSONL is the bottleneck.

The foreground path encodes once and performs non-blocking put_nowait() into a bounded queue of 8192 records. A single daemon writer thread drains into one file per EngineCore/DP rank and process. It flushes userspace buffers every 1 MiB or one second, whichever comes first, and on clean process exit; it never calls fsync() per record. When the queue is full, the serving thread drops the new record, increments a counter, and the next successful record reports the gap in dropped_records_before. Shutdown emits a footer with encoded, written, and dropped counts. The file name includes schema, DP rank, PID, and start time, but not TP rank because there is one scheduler record stream.

The sole on/off switch is:

VLLM_OPPROF_DIR=/absolute/output/directory

Unset or empty means a true no-op: no recorder, queue, thread, record construction, or graph-stat broadening. Directory validation and a clear startup log happen before serving. Runtime toggling is intentionally omitted; it adds synchronization and ambiguous partial files without helping the campaign.

Expected cost and Phase 2 overhead gate

These are estimates, not measurements:

  • composition and two fixed histograms: about 20-80 microseconds per step, linear in scheduled requests;
  • msgspec encoding plus a non-blocking queue insertion: about 5-20 microseconds per step;
  • CUDA-graph stat construction: below 2 microseconds and no GPU sync;
  • disk I/O: off the serving critical path, subject to bounded-queue drops.

The expected foreground total is roughly 25-100 microseconds per step. At a 2 ms decode step, the high end would exceed 3%, so the budget is a measurement gate, not a claim.

Phase 2 should use the same Qwen3 checkpoint, request trace, random seed, hardware, vLLM commit, TP/EP topology, CUDA-graph configuration, and cache state for off/on comparisons. Alternate off/on ordering, warm up before each measurement, and run at least five paired repeats. Report throughput and p50/p95 TTFT and TPOT, plus CPU utilization, log bytes per step, queue high watermark, and dropped-record count. The acceptance rule is less than 3% regression for every declared primary serving metric, with bootstrap confidence intervals reported. Whether the point estimate or upper 95% bound is the hard gate is an open decision.

Correctness checks for every run are: contiguous step indices except explicitly reported drops, scheduled token sums matching the prefill/decode split, histogram counts matching scheduled request/chunk counts, KV ratio in [0,1], non-negative counters, and identical generated outputs for the deterministic test trace.

Layer 2: sampled kernel windows

Trigger and window

Use the existing profiler API with a run-specific output directory and ignore_frontend=true. The worker start/stop RPC already fans out to all workers (vllm/v1/executor/abstract.py:256-257 and vllm/v1/executor/multiproc_executor.py:340-402), and each GPU worker creates a CPU+CUDA profiler with a rank-qualified trace name (vllm/v1/worker/gpu_worker.py:929-980). No Layer-2 vLLM code patch is needed.

Recommended initial configuration:

profiler=torch
torch_profiler_dir=<run>/kineto
ignore_frontend=true
delay_iterations=0
max_iterations=8
wait_iterations=0
warmup_iterations=2
active_iterations=8
torch_profiler_record_shapes=false
torch_profiler_with_memory=false
torch_profiler_with_stack=false
torch_profiler_with_flops=false
torch_profiler_use_gzip=true
torch_profiler_dump_cuda_time_total=true

The primary trigger should be step-count based: an external campaign controller POSTs /start_profile immediately before a desired composition regime. The built-in schedule records two warm-up plus eight active model iterations and max_iterations=8 then stops the underlying profiler on the following worker step. The “exceeds max” control semantics are explicit at vllm/profiler/wrapper.py:83-114 and in tests/v1/worker/test_gpu_profiler.py:77-98; the controller should still POST /stop_profile afterward to clear the active control state. Worker iteration boundaries already call profiler.step() and annotate context and generation token counts at vllm/v1/worker/gpu_worker.py:803-827. On-demand manual POST remains useful for debugging. A time-based trigger is a fallback for live traffic but is less reproducible because it yields a variable number of steps. Phase 1 should confirm that the trace contains exactly eight active iteration annotations; profiler scheduling and trace callbacks live at vllm/profiler/wrapper.py:159-226,290-307.

The profile directory should be unique per campaign server run. The HTTP start endpoint does not accept a profile_prefix, and a worker that is restarted for another window retains the trace name chosen on first initialization (vllm/v1/worker/gpu_worker.py:939-975). Multiple windows in one server run therefore share a directory and need a controller manifest containing start/ stop wall times and produced filenames. Use a new directory only when the server is restarted; adding a new endpoint parameter is not justified for Phase 1. Every TP worker emits its own trace, and the rank suffix contains DP, PP, TP, DCP, EP, and global rank information (vllm/distributed/utils.py:664-695). Keep these traces separate and aggregate only offline.

CUDA graphs and Kineto interpretation

Keep CUDA graphs enabled in the primary sampled windows so kernel time reflects the serving configuration. The pinned code profiles CUDA activity (vllm/v1/worker/gpu_worker.py:953-960) while a captured path invokes CUDAGraph.replay() instead of rerunning the Python callable (vllm/compilation/cuda_graph.py:233-360). Therefore Kineto/CUPTI can observe CUDA activity launched during replay, but the Python/PyTorch operator scopes that created the graph are not re-executed and cannot be assumed to retain per-layer attribution. vLLM explicitly documents the related limitation that layerwise NVTX tracing does not work with CUDA graphs (vllm/config/observability.py:60-63).

The clone does not contain a stronger guarantee about whether a particular PyTorch/CUPTI build will present every graph node as an individually named kernel versus a coarser graph-launch view. Treat that as an empirical Phase 2 check. Run one matched eager (cudagraph_mode=NONE) taxonomy window to identify kernel families, but do not use its timings as the production baseline.

Calibration and MoE routing

Join each profiler iteration annotation to Layer-1 records by rank-independent step order, the profiler window marker, timestamps, and the prefill/decode token counts. Aggregate kernels into attention, router/top-k, expert GEMMs, dense GEMMs, normalization/activation, collectives, and sampling. For TP, report both sum-of-rank GPU work and the maximum per-rank critical-path time. Fit or tabulate kernel-time attribution conditioned on composition, context histogram, graph runtime mode, and capture bucket, then validate on held-out windows rather than the same samples used for calibration.

For the Phase 2 “operator time approximately equals iteration time” gate, do not naively add overlapping kernels. Compute the union of CUDA kernel intervals per rank, use the maximum rank as the distributed GPU critical path, and retain an explicit CPU/queue/unattributed residual against Layer 1's submit-to-complete span. Operator-category interval unions plus the residual must reconstruct the span; summed GPU work is reported separately and may legitimately exceed wall time.

Exact per-layer expert loads are Layer-2-only. A separate server start with --enable-return-routed-experts exposes per-token, per-layer top-k IDs through the existing router callback (vllm/model_executor/layers/fused_moe/router/base_router.py:233-278). Aggregate those arrays offline into per-layer expert counts, entropy, max/mean load, coefficient of variation, and top-k imbalance. Do not enable it in the normal Layer-1 or baseline Kineto run: its worker transit buffer costs a few MB, and the scheduler-side slot buffer can reach multiple GB with a CPU fancy-index copy per step (vllm/model_executor/layers/fused_moe/routed_experts_capturer.py:223-305).

Patch surface estimate

Proposed implementation and tests:

File Approximate changed/new lines Purpose
vllm/envs.py 4 Declare and parse VLLM_OPPROF_DIR.
vllm/v1/opprof.py (new) 220 Schema, schedule snapshot/deltas, histograms, pending-step pairing, encoder, bounded writer, drop/footer handling.
vllm/v1/core/sched/scheduler.py 32 Initialize recorder; begin before state mutation; finalize with the matching model output.
vllm/v1/worker/gpu_model_runner.py 4 Return existing CUDAGraphStat when either built-in metrics or OpProf needs it.
tests/v1/core/test_opprof.py (new) 190 Schema/invariants, chunk classification, async pairing, disabled no-op, bounded-queue drops, shutdown flush.
Total 5 files / about 450 lines About 260 production lines and 190 test lines.

No patch is proposed for ProfilerConfig, profile endpoints, profiler wrapper, SchedulerOutput, SchedulerStats, Prometheus/logging, CUDA kernels, fused MoE kernels, the Qwen model, or frontend APIs. If support for --disable-log-stats is required, add about 12 lines in vllm/v1/core/kv_cache_manager.py, making the estimate six files and about 462 lines; the smaller fail-fast design is recommended for this campaign.

Risks and mitigations

  • Foreground CPU overhead: request scanning and JSON encoding are the likely hot spots. Use fixed-size arrays, a reused encoder, no raw lists, no blocking I/O, and enforce the Phase 2 gate.
  • Async-scheduling races: queue/KV/prefix state observed during update_from_output() may include later in-flight schedules. Snapshot it inside the synchronous schedule() call; only the immutable returned CUDA-graph stat is added at completion. Pair by the exact SchedulerOutput object and assert one begin/one finalize.
  • TP and EP aggregation: Layer 1 is scheduler-owned and emitted once. Layer 2 remains per rank. Interpret TP critical path as the slowest rank and, for an expert-parallel routed-expert sample, aggregate expert ownership offline.
  • Log volume: at 500 steps/s, a 1.0 KiB record is about 44 GB/day per EngineCore. Rotate by campaign run, compress completed files, and use the bounded queue/drop counters. Production-long captures need a later sampling or rotation policy; Phase 1 files should be bounded by run duration.
  • Graph semantics: PIECEWISE is partial graph coverage, not a binary full hit. Preserve runtime_mode, unpadded tokens, bucket, and padding rather than reducing the record to one boolean.
  • Profiler perturbation: Kineto has medium-to-high overhead and trace flushes can stall. Use short windows, unique directories, disabled stacks/shapes and memory by default, and never use Layer-2 latency as an unprofiled performance result.
  • Backend drift: the unquantized SM90 oracle prioritizes Triton, but shape-specific fallbacks remain possible. Record startup backend logs and the full checkpoint/parallel/quantization configuration with every run.

Open decisions for review

  1. Approve JSONL with msgspec, the two proposed histogram edge sets, and a bounded 8192-record writer queue.
  2. Approve exact expert-load collection as Layer-2-only, rather than adding a new always-on GPU histogram kernel.
  3. Confirm the Qwen3 checkpoint precision/quantization and intended TP/EP/DP topology; the Triton backend conclusion depends on these inputs.
  4. Choose the first profiler window: recommended two warm-up plus eight active iterations, or a longer active window.
  5. Decide whether the 3% gate applies to metric point estimates or to the upper bound of their 95% confidence intervals.
  6. Confirm that campaign runs may reject --disable-log-stats; supporting it adds one file and about 12 lines.

Data sanity block

  • Patch estimate: n=5 files; per-file line-estimate min=4, max=220, distinct values=4; total about 450 lines, of which about 260 are production and 190 are tests.
  • Histogram definitions: n=2 arrays; bin-count min=9, max=12, distinct=2. In the illustrative record, context-bin sum=37 equals scheduled requests, chunk-bin sum=5 equals prefill requests, KV used=120000-42000, and graph padding=1024-928.
  • Estimated foreground components: n=3 timed components; min is below 2 microseconds for graph-stat construction, max is 80 microseconds for composition; distinct ranges=3. Their conservative combined foreground estimate is 25-100 microseconds per step.
  • Invariants checked: counters and histogram bins are non-negative; KV usage and prefix hit ratios are bounded in [0,1]; graph bucket is at least unpadded tokens; NONE is the only graph miss mode; no raw request IDs or context-length lists are serialized; one scheduler stream avoids TP duplicates.
  • Measurement status: n=0 benchmark runs; min/max and cross-configuration distinctness are not applicable. The cost figures are estimates and cannot support an overhead conclusion until Phase 2.