aituner/docs/opprof/patch-design.md

# 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

```text
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:

```json
{"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:

```text
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:

```text
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.