aituner/docs/opprof/phase2-smoke-dash0.md

OpProf Phase 2 single-H20 smoke on dash0

Final status: PASS. After preserving the earlier measurements and tracing the entire CUDA-graph-stat path, attempt 4 found that VLLM_OPPROF_DIR was accidentally included in vLLM's torch.compile cache key. Each unique ON output directory therefore forced a distinct graph/AOT cache and confounded the attempt-2 comparison; CUDA-graph-stat construction and msgspec serialization were not the material cost. The minimal production fix is one ignored-factor entry in vllm/envs.py.

The unchanged A-P2-1 rerun produced mean ON throughput 29.666501 req/s, mean OFF throughput 29.654057 req/s, and overhead -0.04196% with paired-bootstrap 95% CI [-0.17443%, 0.04550%]. Its upper bound is below the unchanged 3% gate. The accepted Layer-2 run then produced a loadable 16,416,452-byte Kineto trace with exactly two discarded warm-up iterations and eight active profiler steps.

Attempt 2 remains preserved below as a valid measurement of the pre-fix patch: 4.1816% overhead with 95% CI [3.1364%, 4.7117%]. Attempt 3 then exonerated the recorder stages and localized the boundary outside opprof.py, as required, before attempt 4 identified the exact cache-key operation and made the evidence-driven fix.

Attempt 1 remains preserved below as an invalidated measurement. Its raw calculation was 13.1133% overhead with 95% CI [6.2434%, 19.5259%], but the orchestrator rejected that approximately 10-second, cold-start-confounded protocol rather than adjudicating the patch from it.

Attempt 1 also had a reproducibility anomaly: its input/output length arrays and token totals were identical in all ten trials, but the generated-text digest differed in all ten. Between 185 and 190 of 200 responses in each later trial matched trial 1 exactly. The bundled client also generated ten distinct request-ID prefixes even though --seed 20260711 and --temperature 0 were fixed. A-P2-1 removed the work-volume consequence with fixed completion length.

Dated amendment A-P2-1 (2026-07-11)

This amendment was written before launching any rerun. Attempt 1 remains below as an invalidated measurement and will not be erased or pooled with the amended data. The 3% CI-upper-bound gate is unchanged.

1. Each server will receive 128 fixed-seed warm-up requests after readiness and before timing. These requests are excluded from the measurement. One additional unmeasured server start and representative warm-up will run before measured trial 1 so that no measured arm is the globally coldest start.
2. Every measured trial will use the same 4,000-request stream. A trial is acceptable only if its measured window is at least 120 seconds; 4,000 also exceeds the 2,000-request minimum. If any trial is shorter than 120 seconds, the amended series is invalid and stops without a gate conclusion.
3. The random input distribution remains centered at 512 tokens with input range ratio 0.5. Output range ratio is fixed at 0, --ignore-eos is explicit, --random-output-len 64 fixes max_tokens=64, temperature is 0, seed is 20260711, and request-ID prefix is fixed as opprof-p2a-. Thus every successful request must produce exactly 64 completion tokens in every run.
4. Ten fresh-server trials use the counterbalanced sequence ON,OFF,OFF,ON,ON,OFF,OFF,ON,ON,OFF. Adjacent trials form five pairs; within each pair, the ON/OFF orientation alternates. The only intended arm difference remains whether VLLM_OPPROF_DIR is set.
5. Before and after each trial, the record will include /proc/loadavg, a nvidia-smi -q -d CLOCK snapshot for physical GPU 0, GPU memory/utilization, and a host-process snapshot. A periodic process/GPU sampler will record any newly appearing process owned by another user. Server lifetime is measured from launch to completed teardown.
6. Before serving, an offline dash0 microbenchmark will time the complete capture_start + begin + finalize + non-blocking writer submit path for a synthetic 64-request scheduler state over 10,000 measured iterations. It will report total and per-step time; setup, writer drain, and close are outside the timed region.
7. An artifact addendum will launch one extra short server forced to vLLM 0.24.0 cudagraph_mode=PIECEWISE. Its accepted footer-valid JSONL must contain at least one PIECEWISE record with bucket_tokens >= unpadded_tokens and padding_tokens = bucket_tokens - unpadded_tokens.
8. The primary statistic remains 1 - mean(ON) / mean(OFF). Its 95% CI will use a paired percentile bootstrap over the five adjacent counterbalanced pairs, 100,000 resamples, seed 20260711, NumPy's default linear percentile, and no outlier removal. If the upper bound exceeds 3%, execution stops again. Layer-2 runs only after this unchanged gate passes.

A-P2-1 execution clarification (2026-07-11)

This clarification was recorded before restarting the accepted ten-run series. The first 4,000-request invocation used unbounded client concurrency and is an excluded admission pilot, not an overhead trial: the client hit its 1,024-file descriptor ceiling, so only 984 requests succeeded and 3,016 failed with OSError: [Errno 24] Too many open files. Its 42.799-second partial duration and 22.991182 req/s successful-request rate are not gate inputs.

The accepted series retains 4,000 measured requests and every setting above, but fixes --max-concurrency 200 identically in both arms. This bounds client file descriptors while keeping the server saturated: the earlier valid 200-request burst sustained approximately 21 req/s, implying an approximately 190-second 4,000-request window. All ten accepted trials restart from pair 1; the excluded pilot is not pooled, substituted, or counted. The >=120-second, 4,000-success, zero-failure, and fixed-64-output acceptance checks remain hard.

Goal and hard-gate outcome

The goal was to deploy the accepted Layer-1 patch at base ee0da84a and tip-equivalent 668cfb7e, validate one scheduler-owned JSONL stream on one H20, measure its serving overhead with the pre-registered ten-run protocol, and then sample one two-warm-up/eight-active torch-profiler window only if the earlier gates passed.

Hard gate	Result	Evidence
Artifacts	PASS	The original footer-valid artifact passed schema, footer, step, drop, histogram, KV, graph-field, and composition checks. The A-P2-1 addendum forced PIECEWISE and added a footer-valid stream with 129 PIECEWISE records preserving bucket/padding identities.
Overhead CI	PASS	Attempt-4 fixed point overhead -0.04196%; paired-bootstrap 95% CI [-0.17443%, 0.04550%]; required upper bound <=3%. Attempt 2's valid pre-fix FAIL is retained separately.
Layer-2	PASS	Exactly 2 warm-up + 8 active profiler iterations; gzip/JSON-loadable Kineto trace, 790,843 events and 7,367 kernel events. The active steps ran uncaptured (NONE) because their approximately 8,192-token batches exceeded the captured bucket limit; mode coverage is reported, not hidden.

Environment and deployment

Field	Value
Host	dash0 (ds-07429c65-1-6c5fd97778-9vhkr)
OS / kernel	Ubuntu 24.04 / Linux 5.10.134-013.8.2.kangaroo.al8.x86_64
CPU / RAM	2 sockets, 80 cores/socket, 160 logical CPUs, 1,554,500,000 KiB RAM; CPU string Intel(R) Xeon(R) Processor
GPU used	Physical GPU 0, NVIDIA H20, UUID GPU-ad3e049a-5bf0-44b7-e7f1-9af297b172af
Driver / reported CUDA	NVIDIA 580.95.05 / CUDA 13.0
Wheel path	Exact-base precompiled cu130 wheel; metadata for commit ee0da84ab9e04ac7610e28580af62c365e898389 returned HTTP 200 and contained vLLM 0.24.0 x86-64
Python / torch	Python 3.12.3; torch 2.11.0+cu130; torch.version.cuda=13.0
vLLM	Editable installation still reports build metadata 0.24.1.dev3+g668cfb7e2; runtime source contains the three accepted commits plus two fix/test commits. Compiled extensions remain from the exact v0.24.0 base wheel.
Compiled extension check	vllm._C_stable_libtorch and vllm._moe_C_stable_libtorch imported successfully
msgspec	0.21.1
Source	/home/admin/cpfs/wjh/opprof-phase2-dash0-20260711/vllm-v0.24.0
Source state	dash0 HEAD 9ad32ff2eeb147c074beeb54418551923a57857b and local HEAD bbfa7176a6a3686a88ee66696f1ad8d754559d96; commit hashes differ because git am dates differ, but all five patch IDs match. HEAD~5=ee0da84ab9e04ac7610e28580af62c365e898389; both trees clean.
Active venv	/tmp/wjh-opprof-phase2-dash0-20260711/.venv, 8.6 GiB
Persistent audit workdir	/home/admin/cpfs/wjh/opprof-phase2-dash0-20260711
Weights	/home/admin/cpfs/wjh/models/Qwen/Qwen3-30B-A3B
Weight validation	Qwen3MoeForCausalLM, torch_dtype=bfloat16, no quantization_config, 128 experts, top-8; 16/16 shards present, 61,066,575,648 shard bytes
MoE backend	TRITON Unquantized MoE backend, observed in every campaign server-start log, including all 19 attempt-4 launches (48/48 total)

The driver reports CUDA 13.0, and vLLM 0.24.0 maps CUDA major 13 to cu130. The cu129 path was therefore not selected. The exact cu130 metadata probe was completed before installation.

The installation command was:

VLLM_USE_PRECOMPILED=1 \
VLLM_PRECOMPILED_WHEEL_COMMIT=ee0da84ab9e04ac7610e28580af62c365e898389 \
VLLM_PRECOMPILED_WHEEL_VARIANT=cu130 \
/tmp/wjh-opprof-phase2-dash0-20260711/.venv/bin/python -m pip install -e \
  /home/admin/cpfs/wjh/opprof-phase2-dash0-20260711/vllm-v0.24.0

The successful local-rootfs install took 377 seconds. pip check reported no broken requirements.

The final exported patch files are checksum-identical to the dash0-applied series:

File	SHA-256
0001-Add-lightweight-per-step-OpProf-telemetry.patch	3b6843906dde103ac47fe6862a092cc507de2f6e721cf39c147d89b6b70ce27d
0002-Add-standalone-OpProf-telemetry-tests.patch	897c770d5f137bd49a852530d5e8dc54666a867f754ef8fd7825c7fd64bbbb99
0003-Log-the-OpProf-output-path-at-startup.patch	c60b44f23d02e753b46e06d9a8d845203095802ce32538c11411b1b7069e69e7
0004-Exclude-OpProf-output-path-from-compile-cache-key.patch	c76bb2cf20dcdfd3b9d0ef40d4e235f8fa9e6e703cd9af9cd084790f65caf0f0
0005-Keep-compile-factor-regression-import-light.patch	16ab2f1101067d9df2831fba312d3e82dfa9d24404954ac817e3fd9681be5537
apply.sh	2e2a4392b3b5714ccf38d0cf2174d829c557af23597f91fa6162390b684dc92c

apply.sh returned OpProf patch series is already applied. only after checking that the clone contained the exact five patch IDs rooted at the required base. A second clean-base worktree applied all five patches and its idempotent reapplication returned the same message.

Remote unit-test command and result:

/tmp/wjh-opprof-phase2-dash0-20260711/.venv/bin/python -m pytest \
  --confcutdir=tests/v1/core tests/v1/core/test_opprof.py -q

...............                                                          [100%]
15 passed in 0.18s

The final import-light local run passed 15/15 in 0.02 seconds, Ruff passed, and the remote clean-base application passed 15/15 in 0.07 seconds. The original deployed 14/14 result is retained in the archived pre-fix evidence.

Serving protocol

Attempt 1 protocol (invalidated)

All servers used one physical H20. GPU 0 had 0 MiB, 0% utilization, and no compute process immediately before every launch. The server command was:

CUDA_VISIBLE_DEVICES=0 \
VLLM_OPPROF_DIR=<run>/opprof \
/tmp/wjh-opprof-phase2-dash0-20260711/.venv/bin/vllm serve \
  /home/admin/cpfs/wjh/models/Qwen/Qwen3-30B-A3B \
  --tensor-parallel-size 1

OFF trials used the same command with VLLM_OPPROF_DIR explicitly unset. No serving knobs beyond the model path and explicit TP1 were changed. Startup logs selected the default FULL+PIECEWISE CUDA-graph configuration and reported the Triton unquantized MoE backend.

The artifact smoke used this fixed-seed, mixed-length load with no client warm-up:

vllm bench serve --backend openai --host 127.0.0.1 --port 8000 \
  --endpoint /v1/completions \
  --model /home/admin/cpfs/wjh/models/Qwen/Qwen3-30B-A3B \
  --dataset-name random --num-prompts 200 \
  --random-input-len 512 --random-output-len 64 \
  --random-range-ratio '{"input":0.5,"output":0.5}' \
  --request-rate inf --seed 20260711 --temperature 0 \
  --save-result --save-detailed --disable-tqdm \
  --percentile-metrics ttft,tpot,e2el --metric-percentiles 50,95,99

The overhead trials added --num-warmups 16; the bundled benchmark executes those warm-up requests before starting its measured timer. Every trial used a fresh server. The exact order was ON,OFF repeated five times. The only intended ON/OFF difference was the OpProf environment variable.

After a measured load had become idle, the EngineCore process was signalled first and allowed to execute scheduler.shutdown() and drain the writer. The API parent was then stopped. This ordering was used identically for ON and OFF overhead trials because the default parent-first shutdown force-killed the EngineCore before the first smoke footer could be written.

A-P2-1 accepted protocol

The amended order was ON,OFF,OFF,ON,ON,OFF,OFF,ON,ON,OFF. One default-configuration burn-in server ran before measured pair 1. Every measured server received 128 excluded warm-up requests followed by this fixed-work command:

vllm bench serve --backend openai --host 127.0.0.1 --port 8000 \
  --endpoint /v1/completions \
  --model /home/admin/cpfs/wjh/models/Qwen/Qwen3-30B-A3B \
  --dataset-name random --num-prompts 4000 --num-warmups 128 \
  --max-concurrency 200 \
  --random-input-len 512 --random-output-len 64 \
  --random-range-ratio '{"input":0.5,"output":0.0}' \
  --ignore-eos --request-rate inf --seed 20260711 --temperature 0 \
  --request-id-prefix opprof-p2a- \
  --save-result --save-detailed --disable-tqdm \
  --percentile-metrics ttft,tpot,e2el --metric-percentiles 50,95,99

All ten accepted runs completed 4,000 requests with zero failures. Every completion was exactly 64 tokens; input/output length digests each had one distinct value across runs. Each internal measured duration exceeded 120 seconds. The client generated seven distinct text-content digests, but this no longer changed generation work because ignore_eos and max_tokens=64 fixed every completion length.

Before and after every run, the controller captured /proc/loadavg, full nvidia-smi -q -d CLOCK output, selected-GPU state, and a host process snapshot. A five-second sampler recorded clocks and newly appearing processes. The server was restarted and torn down identically for every arm. A transient 4 MiB, 0%-utilization driver-accounting sample after trial 1 stopped the first controller before trial 2 launched; after five consecutive 0 MiB/0% samples, the unchanged sequence resumed at trial 2.

Artifact gate

Invalid first attempt

The first smoke completed 200/200 requests in 9.634701 seconds at 20.758299 req/s. It produced 110 step records, including one runtime PIECEWISE record:

runtime_mode=PIECEWISE, unpadded_tokens=478, bucket_tokens=480,
padding_tokens=2

The parent-first default shutdown then force-killed the EngineCore and the file had no footer. This file was retained as failure evidence but excluded from the accepted artifact checks.

Footer-valid rerun

The unchanged load rerun completed 200/200 requests in 9.391693 seconds at 21.295415 req/s. Its JSONL contained 109 records followed by one footer. Every line decoded against a strict, unknown-field-forbidding msgspec.Struct schema.

Check	Result
JSONL / schema	110/110 lines schema-valid; 109 records plus one terminal footer
Footer	encoded=109, written=109, dropped=0; encoded=written+dropped
Steps / pending leak	Step indices exactly 0 through 108; Prometheus counted 107 executed iterations and the stream contained 2 zero-token steps, totaling 109
Queue drops	Footer drops 0 and sum of dropped_records_before 0
Per-record invariants	All counters non-negative; context/chunk histograms sum correctly; KV block accounting exact; KV usage in [0,1]; completion timestamp not before submission
CUDA-graph fields	Hit/mode identity valid; bucket >= unpadded; padding = bucket - unpadded for every record
Layer-1 MoE field	moe_expert_load null in every record
Last state	Zero-token record, queues all zero, KV used blocks zero

Observed graph modes in the footer-valid file were FULL=93 and NONE=16. The bucket family had n=109, min=0, max=8192, distinct=32; padding had n=109, min=0, max=7, distinct=8. No valid-file record exercised PIECEWISE. A planned single-request PIECEWISE probe was not run after the overhead stop rule fired, so the strict artifact gate remained unresolved at the end of attempt 1 despite the other artifact checks passing.

Composition cross-check

Random inputs covered 261 to 761 tokens; requested/actual outputs covered 32 to 96 tokens because the random OpenAI-compatible benchmark ignores EOS for this dataset.

Quantity	OpProf	Client ground truth	Delta / tolerance
Prefill tokens	102,848	102,848 input tokens	0; exact
Decode tokens	11,987	12,187 completion tokens	-200, or 1.6411%; allowed structural tolerance was one first token per completed request
Decode plus first-token correction	12,187	12,187 completion tokens	0; exact

The one-token/request correction is expected because the first completion token is sampled from the prefill logits; only later completion tokens require decode inputs.

A-P2-1 PIECEWISE addendum

The addendum forced the exact vLLM 0.24.0 configuration --compilation-config '{"cudagraph_mode":"PIECEWISE"}' and ran 16 excluded warm-ups plus 64 requests with fixed 64-token completions. EngineCore-first shutdown produced one footer-valid file. Every line decoded with the same strict, unknown-field-forbidding msgspec schema.

Check	Result
File / footer	139 records plus one footer; encoded=139, written=139, dropped=0
Step accounting	Indices 0 through 138, contiguous and unique; no pending leak
Runtime modes	PIECEWISE=129, NONE=10
PIECEWISE unpadded tokens	n=129, min=1, max=241, distinct=9
PIECEWISE buckets	n=129, min=1, max=248, distinct=6
PIECEWISE padding	n=129, min=0, max=7, distinct=5
Identity	Every record had bucket >= unpadded and padding = bucket - unpadded

This closes the attempt-1 coverage red flag. The final artifact gate is PASS: the original artifact supplies the composition and scheduler-step cross-checks, while the addendum supplies footer-valid runtime PIECEWISE coverage without weakening any earlier invariant.

Attempt 1 overhead (invalidated measurement)

Metric: bundled-client request_throughput, in req/s. The registered statistic was 1 - mean(ON) / mean(OFF). The 95% interval used paired percentile bootstrap resampling of the five adjacent ON/OFF pairs, 100,000 resamples, analysis seed 20260711, NumPy's default linear percentile, and no outlier removal.

Trial	Mode	Throughput (req/s)	Measured duration (s)	Server GPU lifetime (s)
1	ON	20.487487	9.762056	155
2	OFF	22.864574	8.747156	139
3	ON	22.685507	8.816201	144
4	OFF	26.350950	7.589859	107
5	ON	19.877357	10.061700	144
6	OFF	23.302197	8.582882	92
7	ON	20.419460	9.794578	150
8	OFF	20.378458	9.814285	93
9	ON	20.068985	9.965626	145
10	OFF	26.269114	7.613504	91

Adjacent-pair overheads were 10.3964%, 13.9101%, 14.6975%, -0.2012%, and 23.6024%.

Statistic	Value
Mean ON	20.707759 req/s
Mean OFF	23.833059 req/s
Point overhead	13.1133%
95% CI	[6.2434%, 19.5259%]
Raw calculation	19.5259% > 3%; later invalidated as a measurement

All five ON artifacts closed with valid footer accounting and zero drops. Their record counts were 183, 186, 183, 184, and 184.

The shape-level load checks passed: all trials completed 200 requests with no reported failures; every result had 102,848 input and 12,187 output tokens; and the input-length and output-length digests each had one distinct value. The token-content check did not pass. Generated-text digests had ten distinct values, and exact response matches against trial 1 were [200, 189, 186, 187, 190, 190, 186, 188, 188, 185]. In addition, the bundled client's automatically selected request_id_prefix had ten distinct values. The performance numbers are therefore reported for the gate as registered but should not be used to claim that instrumentation caused the entire measured difference.

The orchestrator subsequently invalidated this attempt because the OFF-arm spread was 29%, the approximately 10-second windows included cold compile and autotune effects, and strict ON,OFF alternation assigned the globally coldest run to ON. These ten rows are not pooled with A-P2-1 and do not adjudicate the patch.

A-P2-1 amended overhead gate

The first unbounded 4,000-request invocation was an excluded admission pilot: the client exceeded its 1,024-file-descriptor ceiling, completing 984 requests and failing 3,016 with Too many open files. The accepted series restarted from pair 1 with maximum concurrency 200, as pre-recorded in the execution clarification above.

Trial	Mode	Throughput (req/s)	Measured duration (s)	Server allocation (s)
1	ON	28.202897	141.829399	297
2	OFF	28.800396	138.886980	267
3	OFF	29.585085	135.203261	260
4	ON	28.183682	141.926096	307
5	ON	28.256715	141.559272	311
6	OFF	29.640096	134.952330	272
7	OFF	29.632434	134.987225	266
8	ON	28.249738	141.594235	312
9	ON	28.187008	141.909351	308
10	OFF	29.578830	135.231855	258

Adjacent-pair overheads were 2.0746%, 4.7369%, 4.6673%, 4.6662%, and 4.7055%. The frozen paired-bootstrap analysis used 100,000 resamples, seed 20260711, NumPy's default linear percentile, and no filtering.

Statistic	Value
Mean ON	28.216008 req/s
Mean OFF	29.447368 req/s
Point overhead	4.1816%
95% CI	[3.1364%, 4.7117%]
Gate	FAIL: 4.7117% > 3%

This measurement passed its protocol-validity checks: ten distinct positive throughputs, ten durations from 134.952330 to 141.926096 seconds, 4,000 successes and zero failures per run, exactly 2,031,054 input tokens and 256,000 output tokens per run, one input-length digest, one output-length digest, and exactly 64 completion tokens per request. Generated text content still had seven distinct digests, but it could not change token work.

All five ON JSONLs strict-decoded and closed cleanly. Their record counts were 1,405, 1,406, 1,405, 1,403, and 1,403; each footer had encoded=written=records, dropped=0, contiguous step indices, and valid bucket/padding identities.

Host and clock observations

Trial	Mode	1-minute load before / after	Startup (s)	New other-user processes	Other-user GPU samples
1	ON	0.15 / 1.63	111	3	0
2	OFF	0.23 / 1.22	73	11	0
3	OFF	1.03 / 1.24	65	2	0
4	ON	1.05 / 1.07	113	2	0
5	ON	0.99 / 1.22	115	4	0
6	OFF	1.11 / 0.93	64	3	0
7	OFF	0.79 / 1.20	70	2	0
8	ON	1.01 / 1.57	116	2	0
9	ON	1.27 / 0.97	113	3	0
10	OFF	0.82 / 1.51	64	7	0

The sampler observed 39 newly appearing root-owned host processes: 13 python3, 6 bash, 3 each of sed, runtime-bridge, nvidia-smi, grep, and config-sync, 2 sshd, and one each of metrics-monitor, envd, and easworker-proxy. Some were orchestrator state checks. None appeared as an other-user GPU compute process, and selected GPU 0 had no contamination.

All 545 periodic GPU samples were P0 with one 1,980 MHz maximum SM clock. Among 318 active samples, observed SM clocks spanned 1,740 to 1,980 MHz; means were 1,970.0 MHz ON and 1,973.9 MHz OFF. One-minute host load stayed between 0.15 and 1.63 on 160 logical CPUs. These observations do not support GPU clock throttling or host CPU saturation as the 4.1816% explanation. Full per-run before/after clock snapshots and process lists are retained in the archive.

Recorder microbenchmark and localization

The offline benchmark pinned one CPU, used a synthetic state with 64 requests (8 prefill, 56 decode, 312 scheduled tokens), ran 1,000 excluded warm-ups, and timed 10,000 complete capture_start + begin + finalize + submit calls. The writer drain and close were outside the timing, as pre-registered.

Producer-path metric	Value
Whole-loop cost	29.1467 us/step
Per-iteration mean / median	28.9279 / 27.7620 us
p95 / p99	36.6643 / 40.6231 us
Min / max	26.293 / 70.111 us
Distinct nanosecond timings	4,144 / 10,000
Writer accounting	11,000 encoded, 11,000 written, 0 dropped, including warm-ups

Production ON files averaged 1,404.4 records over active spans of 144.727 to 144.969 seconds: 9.696 steps/s, 914.7 bytes/record, and 8.87 KB/s. Applying 29.1467 us to 1,404.4 steps predicts only about 0.041 seconds per run, whereas mean ON duration exceeded mean OFF duration by 5.911 seconds, or approximately 4.209 ms per production record. Raw msgspec encode volume and non-blocking enqueue cost in isolation therefore cannot explain the measured gap.

The remaining localization hypothesis is an interaction absent from the offline benchmark: the real begin loop can inspect up to 200 requests rather than 64, and the production writer thread runs concurrently, introducing possible GIL handoff, queue-lock, flush/I/O, or engine-loop cadence effects. The systematic startup split (ON 111-116 seconds; OFF 64-73 seconds), although excluded from throughput, is additional evidence that the enabled path has a broader runtime interaction. This turn did not profile, tune, or fix any of these hypotheses after the hard-gate failure.

Attempt 3 stage bisection and stop

Temporary diagnostic only

The installed editable dash0 source received a temporary 30-addition, 3-deletion diff, never committed or exported. It introduced VLLM_OPPROF_STAGE with these exact boundaries:

• off: OpProfRecorder.create() returned None;
• capture: capture_start and begin ran; finalize paired/popped the pending step, then skipped record construction, encode, and submit;
• encode: the full producer and queue path ran while the writer thread wrote to a Python null sink; and
• full: unchanged JSONL behavior.

The exact diff is archived as runs/stage-bisection-attempt3/temporary-stage-toggle.diff, SHA-256 6c9186089fd61bc88b92ba38692f299b772cf3bf3b437fd9f9508eddf9ec3f2c. Before GPU work, py_compile, semantic stage checks, and all 14 remote unit tests passed. After the bisection, the diff was reversed and opprof.py returned to SHA-256 679c9ae3026cd9eb3cdb48a681a91a9f7693c1dc52cc5ca7ade46cb5b268adbe.

Bisection table reported before any fix

Each fresh server received 128 excluded warm-ups and the same 4,200-request stream at concurrency 200. All stages completed 4,200/4,200 requests, zero failures, 2,132,262 input tokens, and 268,800 output tokens. Every completion was exactly 64 tokens, and input/output length digests were identical.

Stage	Throughput (req/s)	Duration (s)	Overhead vs off	Startup / allocation (s)	JSONL files / bytes
off	28.389494	147.942050	0.000%	113 / 302	0 / 0
capture	28.257144	148.634981	0.466%	114 / 304	1 / 96
encode/null sink	28.221609	148.822131	0.591%	126 / 316	0 / 0
full/CPFS	28.269199	148.571596	0.424%	111 / 301	1 / 1,346,466

The full output directory was on CPFS (fuse.aliyun-alinas-efc / fuseblk); /tmp was rootfs overlay. Full CPFS output was faster than the null-sink stage and only 0.424% below off, so filesystem I/O was not implicated and the conditional full-on-/tmp trial was not run.

Culprit boundary and mandated stop

No opprof.py stage reproduced the valid 4.1816% gate gap. Source inspection then found the bisection-boundary violation:

• vllm/v1/worker/gpu_model_runner.py sets self.opprof_enabled = bool(envs.VLLM_OPPROF_DIR) during initialization; and
• its cudagraph dispatch path constructs and propagates CUDAGraphStat when either cudagraph metrics or self.opprof_enabled is true.

All four diagnostic servers had non-empty VLLM_OPPROF_DIR, so this worker/model-runner path stayed enabled even when stage off returned no recorder. The stage named off was therefore equivalent only at the scheduler recorder boundary, not to the accepted gate's environment-unset OFF arm. The evidence localizes the missing overhead outside opprof.py, specifically to the CUDAGraphStat construction/propagation path or its downstream interaction; it does not isolate which operation inside that path is expensive.

This matches the user's explicit outside-OpProf stop example. Consequently no minimal fix was made: real branch line delta 0, no commit, and no patch re-export. The local and remote branches remain at 668cfb7e; all three patch files and apply.sh retain their accepted checksums. The unchanged local standalone suite passed 14/14 in 0.02 seconds. No quick pair, full gate rerun, or Layer-2 run was authorized after this stop condition.

Attempt 4 static CUDA-graph-stat path analysis (2026-07-11; before GPU)

This analysis was completed and recorded before launching any attempt-4 GPU trial. The authoritative tree is the accepted vLLM v0.24.0 patch tip 668cfb7e27e488454dbf09a4927b8a60d6d49b40 in /home/gahow/phd/vllm-v0.24.0.

Worker to scheduler: no serializer in this TP1 configuration

• With TP1/PP1/DP1, world_size == 1 selects backend uni (vllm/config/parallel.py:915-916); Executor.get_class() maps that backend to UniProcExecutor (vllm/v1/executor/abstract.py:73-76).
• UniProcExecutor.collective_rpc() invokes run_method() on its in-process driver_worker and returns the object directly (vllm/v1/executor/uniproc_executor.py:79-106); execute_model() is only a thin call through that method (:108-121). The EngineCore receives the resulting ModelRunnerOutput from the completed future and passes it to the scheduler in the same process (vllm/v1/engine/core.py:479-508).
• Therefore the comment that ModelRunnerOutput can be serialized (vllm/v1/outputs.py:231-234) does not describe this TP1 execution path. For comparison only, the multiprocessing executor uses its worker response MessageQueue (vllm/v1/executor/multiproc_executor.py:376-396), whose implementation explicitly pickles the complete response (vllm/distributed/device_communicators/shm_broadcast.py:727-745) and unpickles it at :772-805. It does not use a msgspec unknown-type hook.

Conclusion: adding a CUDAGraphStat field cannot poison a worker-to-scheduler serializer fast path in the measured TP1 server because that serializer does not run.

Exact producer work when the stat is enabled

The accepted OpProf patch adds only two CUDA-graph-stat enablement lines to the upstream path: it caches bool(VLLM_OPPROF_DIR) at runner construction (vllm/v1/worker/gpu_model_runner.py:429-440) and ORs that flag with upstream observability_config.cudagraph_metrics (:3920-3925). When the condition is true, each executed step performs:

1. three existing CPU integer reads/arithmetic operations,
2. str(cudagraph_mode), and
3. construction of one frozen four-field CUDAGraphStat dataclass (vllm/compilation/cuda_graph.py:32-37 and vllm/v1/worker/gpu_model_runner.py:3925-3930).

The dispatch decision and BatchDescriptor already exist before this branch (gpu_model_runner.py:3867-3918); the metrics flag is not passed to the dispatcher. The stat is carried through ExecuteModelState (:405-418, :4402-4413, :4452-4464) and assigned to ModelRunnerOutput (:4625-4639). There are no CUDA events, event reads, tensor .item() calls, stream synchronizations, dispatcher re-queries, or feature-specific logs in this branch. The only nearby .item() is the pre-existing DP>1 coordination at :3907-3918, which is not entered in this DP1 smoke and is independent of the metrics condition.

Scheduler and EngineCore-to-frontend handling

The scheduler reads the field once (vllm/v1/core/sched/scheduler.py:1485-1497), supplies it to the existing make_stats() path (:1812-1822), and stores it as the SchedulerStats.cudagraph_stats field (:2255-2291; field definition at vllm/v1/metrics/stats.py:170-198). OpProf consumes the same object locally after that assignment (scheduler.py:1824-1828).

EngineCoreOutputs is a typed, array-like msgspec.Struct with an optional SchedulerStats (vllm/v1/engine/__init__.py:220-234). The EngineCore output thread calls MsgpackEncoder.encode_into() and sends the resulting ZMQ frames (vllm/v1/engine/core.py:1589-1654); the async frontend constructs MsgpackDecoder(EngineCoreOutputs) (vllm/v1/engine/core_client.py:585-595) and decodes those frames at :1005-1011.

MsgpackEncoder is a msgspec MessagePack encoder (vllm/v1/serial_utils.py:136-171). Its custom hook handles tensors, ndarrays, slices, multimodal objects, and utility results; an unknown object raises unless insecure serialization is explicitly enabled, in which case only that object is placed in a pickle/cloudpickle extension (:191-235). Insecure fallback is off by default (vllm/envs.py:197, :1508-1509). CUDAGraphStat is a standard dataclass, which msgspec handles natively: a local typed encode/decode witness saw zero hook calls with either None or a populated stat. Thus the stat neither uses an extension hook nor forces pickle for the whole EngineCoreOutputs.

As a scale check only (not a GPU gate result), a 500,000-iteration synthetic typed encode+decode loop measured 1.5340 us/message without the nested stat and 1.7215 us/message with it, a 0.1875 us/message delta; encoded size grew from 358 to 451 bytes. At the observed roughly 9.7 steps/s this is far below the valid attempt-2 throughput gap. This witness checks serializer mechanism, not end-to-end performance.

On the frontend, AsyncLLM hands scheduler_stats to the output processor and logger manager (vllm/v1/engine/async_llm.py:656-702). Beyond OpProf, the CUDA-graph-specific consumer exists only when the upstream CLI/config flag is true: LoggingStatLogger creates CUDAGraphLogging (vllm/v1/metrics/loggers.py:99-123), appends one dataclass per step (:163-190), and at each normal logging interval builds a Counter, sorts rows, formats a table, logs it, and resets the list (vllm/compilation/cuda_graph.py:65-124 and vllm/v1/metrics/loggers.py:219-283). With only VLLM_OPPROF_DIR set and cudagraph_metrics=False, this logger is absent; the stat is still encoded to the frontend but has no feature-specific frontend consumer.

Static mechanism conclusion: serializer fast-path poisoning is ruled out for the measured TP1 worker path and was not observed on the remaining typed msgspec leg. The common hot-path delta to test is the upstream four-field stat production and propagation; the upstream-only versus env-set/recorder-off trials distinguish upstream feature cost from OpProf-specific enablement.

Static-witness sanity: encode/decode configurations n=2, min/max 1.5340/1.7215 us, distinct=2; message sizes n=2, min/max 358/451 bytes, distinct=2. All timings and sizes were positive, the typed round trip preserved values, and hook-call count was exactly zero in both configurations.

Three-arm confirmation reported before fixing

These three fresh-server trials reused the frozen A-P2-1 stream: 128 excluded warm-up requests, then 4,000 measured requests at concurrency 200, random input lengths 256-768 from seed 20260711, greedy temperature 0, ignore_eos, and exactly 64 output tokens. All arms completed 4,000/4,000 requests with zero failures, 2,031,054 input tokens, and 256,000 output tokens.

Trial	Configuration	Throughput (req/s)	Duration (s)	Startup (s)	Server lifetime (s)	Difference vs baseline
1	True baseline: env unset, CUDA-graph metrics off	29.716821	134.603900	74	258	0
2	Upstream only: env unset, --cudagraph-metrics	29.641918	134.944034	64	248	0.2521%
3	VLLM_OPPROF_DIR set, temporary recorder off	28.452675	140.584322	122	307	4.2540%

The env-set arm was also 4.0120% below upstream-only. Input-length and output-length digests were identical across all three arms. Generated-text digests differed, as already seen in the longer A-P2-1 series; exact token volume remained fixed. GPU0 was stably 0 MiB/0% before and after each arm, and all three selected the TRITON unquantized MoE backend.

The table rules out the proposed upstream-stat/serializer mechanism: upstream metrics were only 0.2521% below baseline, while the OpProf environment alone reproduced the material gap with no recorder.

Exact operation: compile-cache key poisoning by the output path

envs.compile_factors() starts from every registered vLLM environment variable and removes only names in its explicit ignored_factors set (vllm/envs.py:2011-2017, :2089-2104). The accepted patch registered VLLM_OPPROF_DIR but did not add it to that exclusion set. VllmBackend hashes those environment factors and combines the environment, vLLM config, traced-code, and compiler hashes into the torch.compile cache-directory key (vllm/compilation/backends.py:1024-1065).

The persisted cache_key_factors.json files make the mechanism exact:

• baseline/upstream used cache directory 2f59bf1436; env-set/recorder-off used c0e8930879;
• config hash 05ca9c77d6, code hash 7d1415ae9c2a984358bee50a7ae3079b0e9f0afd27ecdff56e25f9ef57e89c15, and compiler hash 1efad2be6d were identical;
• the sorted environment maps differed in exactly one entry: VLLM_OPPROF_DIR="" versus the per-run output directory.

Consequently every ON trial's unique artifact directory generated a unique compile cache key. The baseline/upstream server loaded the existing graph and AOT artifact (torch.compile 6.07 seconds); env-set/recorder-off compiled and saved a new graph/AOT artifact (torch.compile 36.41 seconds). Its total engine initialization was 70.22 seconds versus 21.85 seconds for baseline, matching the startup signature seen throughout attempts 2 and 3. This cache churn also placed each ON arm on a newly compiled/autotuned artifact instead of the common warmed artifact, which is the systematic measurement confound.

Fix hypothesis, frozen before implementation: VLLM_OPPROF_DIR controls only the host-side telemetry destination and cannot affect the model computation graph, so excluding it from compile_factors() will make ON and OFF share the same compilation/AOT cache. Verification requires the same cache directory in a quick ON/OFF pair and quick-pair overhead below 2% before the full gate.

Minimal fix, export, and verification

The production change adds exactly one string, "VLLM_OPPROF_DIR", to compile_factors()'s ignored_factors set in vllm/envs.py:2011-2093 (new entry at :2047). It does not touch CUDA-graph dispatch, scheduler plumbing, serialization, the recorder, or the import surface. The regression test loads envs.py directly with light module stubs, sets the output path, and asserts that the name is not returned as a compile factor.

The two fix commits are local 335da4a/bbfa717 and patch-ID-equivalent dash0 commits fbbc886/9ad32ff. Relative to accepted tip 668cfb7e, the fix delta is +1/-0 production line and +21/-1 test lines, or +22/-1 overall. The fifth commit exists only to keep the new regression import-light; it does not alter production code.

Verification summary:

• local standalone suite: 15/15 passed in 0.02 seconds;
• local Ruff check: passed;
• dash0 real-tip suite: 15/15 passed in 0.18 seconds;
• a fresh worktree at exact base ee0da84a: all five exported patches applied, 15/15 passed in 0.07 seconds, and a second apply.sh invocation was a no-op;
• the final real branch and clean-base worktree both retained the import-light contract (no installed vLLM or torch required by the local test run).

An earlier four-patch clean-base validation exposed that the first version of the regression test imported torch before the existing import-light assertion. That test-isolation bug did not affect production code or GPU measurements; it was corrected by the fifth commit before the final clean-base result above.

Quick signal pair after the fix

One unmeasured 128-request burn-in preceded a fixed-work ON/OFF pair. Both measured servers used compile cache f66a11246c.

Arm	Throughput (req/s)	Duration (s)	Startup / lifetime (s)
ON	29.700657	134.677153	72 / 256
OFF	29.677979	134.780065	63 / 247

Quick-pair overhead was -0.07641%, below the pre-declared 2% continuation threshold, so the full unchanged protocol was run.

Attempt 4 full unchanged A-P2-1 gate

The burn-in server lived for 94 seconds. The ten measured fresh servers then used the frozen ON,OFF,OFF,ON,ON,OFF,OFF,ON,ON,OFF order, 128 excluded warm-up requests, and the same 4,000-request fixed stream. Every run completed 4,000 requests with zero failures, 2,031,054 input tokens, and 256,000 output tokens. Every completion was exactly 64 tokens. All eleven servers, including burn-in, used compile cache f66a11246c.

Trial	Pair	Arm	Throughput (req/s)	Duration (s)	Startup / lifetime (s)	Host load 1m before / after
1	1	ON	29.712835	134.621958	60 / 244	0.49 / 1.48
2	1	OFF	29.624180	135.024835	64 / 248	1.26 / 1.78
3	2	OFF	29.658364	134.869208	64 / 249	1.51 / 1.55
4	2	ON	29.647687	134.917776	63 / 247	1.43 / 1.91
5	3	ON	29.637994	134.961900	76 / 262	1.62 / 2.36
6	3	OFF	29.634841	134.976258	62 / 247	1.90 / 1.75
7	4	OFF	29.677443	134.782500	63 / 247	1.56 / 1.42
8	4	ON	29.657455	134.873342	62 / 246	1.20 / 1.63
9	5	ON	29.676533	134.786632	61 / 246	1.38 / 1.20
10	5	OFF	29.675455	134.791530	64 / 249	1.09 / 1.49

Pair	ON (req/s)	OFF (req/s)	1 - ON/OFF
1	29.712835	29.624180	-0.29927%
2	29.647687	29.658364	0.03600%
3	29.637994	29.634841	-0.01064%
4	29.657455	29.677443	0.06735%
5	29.676533	29.675455	-0.00363%

Mean ON was 29.666501 req/s, mean OFF was 29.654057 req/s, and the pre-registered aggregate overhead 1 - mean(ON)/mean(OFF) was -0.04196%. The paired percentile bootstrap (100,000 resamples, seed 20260711) gave a 95% CI of [-0.17443%, 0.04550%]. Its 0.04550% upper bound is below 3%: overhead hard gate PASS.

All pre-launch clock snapshots reported current SM 345 MHz; all immediate post-run snapshots and active samples reported 1,980 MHz. Maximum SM remained 1,980 MHz and memory 2,619 MHz throughout. Before/after compute-process snapshots were empty, periodic GPU samples contained only the campaign EngineCore, and no other user's GPU process appeared. One-minute host load stayed between 0.23 and 2.36 on 160 logical CPUs. Input- and output-length digests each had one value across all ten runs; generated-text digests had six values, but exact work volume was invariant.

Layer-2 window

The accepted retry used vLLM's profile endpoint during the same fixed 4,000 request load. VLLM_TORCH_PROFILER_DIR pointed to dash0-local /tmp during capture, with VLLM_TORCH_PROFILER_WITH_STACK=1, VLLM_TORCH_PROFILER_RECORD_SHAPES=1, and the v0.24.0 schedule configured for wait 0, warm-up 2, active 8, repeat 1. The resulting files were copied into the persistent run directory before teardown.

The trace dp0_pp0_tp0_dcp0_ep0_rank0.1783785319893394827.pt.trace.json.gz is 16,416,452 bytes with SHA-256 4d6bb869ff03ddfd421d3111414ec9532330a9cbefdfa9e9fed1982070f6d72e. It decompressed and parsed as JSON schema version 1, containing 790,843 trace events, 7,367 kernel events, and 35 distinct kernel names. The trace contains exactly eight active ProfilerStep annotations numbered 2 through 9 and eight matching execute annotations; the two preceding iterations were warm-up and were correctly discarded. Visible kernels include the Triton fused-MoE kernel, FlashAttention, reshape-and-cache, top-k gating, and NVJet GEMMs.

All eight active execute annotations totaled approximately 8,192 scheduled tokens (context 8,025-8,048 plus generation 144-167). They exceeded the largest captured CUDA-graph bucket, so OpProf classified all ten records in the scheduled collection interval as NONE. This explains why the trace shows 7,367 individual kernel launches and zero cudaGraphLaunch runtime events. The immediately preceding equal-length steady window contained 75 FULL and 20 NONE records; the broader pre-endpoint interval contained 215 FULL, 54 NONE, and two PIECEWISE records. The trace therefore proves kernel visibility for the uncaptured mode actually active in the profiler window; it does not claim individual-kernel visibility inside a FULL or PIECEWISE graph replay.

Perturbation is indicative only. During the 8.174811-second scheduled collection interval, 131 requests completed (16.0248 req/s) versus 269 in the equal preceding interval (32.9060 req/s), a 51.30% reduction. The complete 24.102657-second start/stop endpoint interval sustained 5.4351 req/s versus 19.4584 immediately before and 29.8722 immediately after, reductions of 72.07% and 81.81%; trace finalization inside stop_profile dominates that larger interval. Whole-load throughput was 25.869730 req/s, 12.80% below the fixed-gate ON mean. These values are profiler perturbation, not Layer-1 gate inputs.

The first Layer-2 controller attempt is excluded: its benchmark-progress marker remained block-buffered, so profiling started after the load had finished and produced no trace. No inference is drawn from that run. The accepted retry used an unbuffered progress source and triggered during load.

Layer-2 gate PASS: the configured 2+8 window executed, its Kineto file is loadable and kernel-bearing, observed CUDA-graph modes are documented, and perturbation was measured.

Deviations and failure notes

1. Two direct remote GitHub clones were interrupted by checkout/fetch transport behavior. rsync was unavailable on dash0. The accepted local clean clone was transferred as a gzip tar stream; apply.sh then verified the exact patch IDs and required base parent.
2. A CPFS-hosted venv spent 21 minutes in slow package metadata/page writes and was stopped before completion. It was preserved as failure evidence. The successful fresh venv was installed on dash0 local rootfs to avoid CPFS I/O variance in repeated startups and OpProf writes.
3. /usr/bin/time was absent, so install duration was recorded with epoch timestamps.
4. The initial binary-import check incorrectly tried vllm._C. vLLM 0.24.0's CUDA path uses _C_stable_libtorch and _moe_C_stable_libtorch; both actual modules imported successfully before testing or serving.
5. Parent-first shutdown produced no footer. EngineCore-first teardown produced a footer but causes the API parent to log an expected teardown-only EngineDeadError after all requests and metrics are complete.
6. After overhead trial 6, the first cleanup sample showed 4 MiB and 0% utilization with no compute process. The controller stopped before trial 7. GPU memory was 0 MiB on two later checks; trials 7-10 resumed unchanged, and cleanup polling was extended to wait for driver accounting to return to zero.
7. The footer-valid smoke did not contain PIECEWISE. The invalid first file did, but it was not promoted into accepted gate evidence.
8. The fixed-seed commands did not yield bit-identical generated outputs, and the bundled client generated a random request-ID prefix for each invocation. A-P2-1 fixed the request-ID prefix and exact output length; content digests still varied, but work volume did not.
9. A-P2-1's first unbounded 4,000-request admission pilot exceeded the client's file-descriptor limit. It was excluded before any CI calculation. Maximum concurrency 200 was documented before the accepted ten-run series began.
10. After accepted trial 1, a 4 MiB/0% transient appeared after an earlier 0 MiB cleanup sample. Trial 2 had not launched. Five subsequent 0 MiB/0% samples were required before resuming the frozen sequence at trial 2.
11. The process sampler recorded 39 transient root-owned processes, including orchestrator checks and cluster control processes. None used a GPU, host load remained low, and no process was touched.
12. A-P2-1 fixed completion work but still produced seven generated-text digests. Because all 40,000 accepted completions were exactly 64 tokens, this did not recreate attempt 1's work-volume confound.
13. Two malformed temporary stage-diff attempts failed before serving. The first failed git apply --check; the second was immediately reversed after py_compile exposed incorrect zero-context placement. The final logged diff passed py_compile, stage semantic checks, and 14 tests before GPU use.
14. Attempt 3 showed that stage off could not disable the model-runner's environment-controlled CUDAGraphStat path. The outside-OpProf stop rule correctly prevented a speculative change in that turn; attempt 4 resumed only after explicit authorization to trace that path.
15. The first attempt-4 confirmation controller incorrectly applied an ON-file acceptance check to the true-baseline arm and stopped after that valid trial. A first resume wrapper then failed a shell declaration before any GPU launch. The remaining two arms resumed in order with unchanged commands; neither control-plane error changed a measured result.
16. The first clean-base four-patch test exposed a test-only import-light regression: the new test loaded real torch before the existing assertion. Production code was unaffected. The fifth patch stubbed torch, and the final five-patch clean-base validation passed 15/15.
17. Footer anomaly: the attempt-4 quick/full-gate and accepted Layer-2 controllers terminated the API and EngineCore process group simultaneously after metrics were complete. Their record lines are contiguous and decodable, but the five full-gate ON files and accepted Layer-2 file have no footer. They are therefore not promoted as artifact-gate evidence. The artifact hard gate remains based on the earlier footer-valid streams, and the one-line cache-factor fix cannot alter recorder shutdown behavior.
18. The first Layer-2 controller used a block-buffered benchmark marker, so the endpoint fired after load completion and produced no trace. That run is explicitly excluded; the unbuffered retry produced the accepted trace.

Artifacts and reproducibility record

• Persistent campaign workdir: /home/admin/cpfs/wjh/opprof-phase2-dash0-20260711
• Runtime artifact archive: /home/admin/cpfs/wjh/opprof-phase2-dash0-20260711/phase2-runtime-artifacts.tar.gz
• Archive SHA-256: 040eb234818564f880489fca4a1a8b21278210dcd04b9f613e6000a28fbb3beb
• Archive inventory: 203 files, 7 JSONL files, 12 serving result JSON files; compressed size 1.6 MiB, uncompressed run tree 6.4 MiB.
• Remote analysis summaries are included at runs/artifact-smoke-rerun/artifact-gate.txt and runs/overhead/overhead-analysis.json inside the archive.

The amended evidence is separately preserved so attempt 1 remains immutable:

• A-P2-1 archive: /home/admin/cpfs/wjh/opprof-phase2-dash0-20260711/amendment-a-p2-1-runtime-artifacts.tar.gz
• A-P2-1 archive SHA-256: acbf5eb2f495e322ecb087f8238540806bfa1c412cad3be0d8265f17c2e938cb
• Inventory: 344 files; 24 MiB compressed and 120 MiB uncompressed.
• Primary analysis: runs/amendment-a-p2-1/overhead-attempt2-accepted/overhead-analysis.json
• Microbenchmark: runs/amendment-a-p2-1/microbenchmark/result.json
• PIECEWISE validation: runs/amendment-a-p2-1/piecewise-addendum/artifact-validation.json

Attempt 3 is separately archived:

• Stage-bisection archive: /home/admin/cpfs/wjh/opprof-phase2-dash0-20260711/attempt3-stage-bisection-artifacts.tar.gz
• Archive SHA-256: e2ee764b905a19162f41fbe153283de3b133024c5548813749837c89779dbe58
• Inventory: 82 files; 12 MiB compressed and 50 MiB uncompressed.
• Bisection analysis: runs/stage-bisection-attempt3/bisection-analysis.json

Attempt 4, including the accepted Kineto trace, is separately archived:

• Fix/confirmation/gate/Layer-2 archive: /home/admin/cpfs/wjh/opprof-phase2-dash0-20260711/attempt4-fix-and-gate-artifacts.tar.gz
• Archive SHA-256: 55d227d644d3d42c2a68edc19fcb2d47231f6971aa74dca9d2a9ef44de2cefa2
• Inventory: 536 entries; 56,705,396 compressed bytes.
• Three-arm raw table: runs/attempt4-stat-path-confirmation/results.tsv
• Full gate analysis: runs/attempt4-fix-full-gate/overhead-analysis.json
• Layer-2 analysis and trace: runs/attempt4-layer2-window-accepted/layer2-analysis.json and runs/attempt4-layer2-window-accepted/traces/.

Final required summary

• Artifacts hard gate: PASS. Original composition/accounting checks passed; the addendum supplied 129 footer-valid PIECEWISE records with exact mode/bucket/padding semantics.
• Overhead CI hard gate: PASS. Fixed ON 29.666501 req/s, OFF 29.654057 req/s, overhead -0.04196%, paired-bootstrap 95% CI [-0.17443%, 0.04550%]. The unchanged limit was 3%.
• Attempt history: attempt 1's 13.1133% / [6.2434%, 19.5259%] is retained as invalidated; attempt 2's 4.1816% / [3.1364%, 4.7117%] is retained as the valid pre-fix FAIL; attempt 3 was diagnostic; attempt 4 is the final PASS.
• Attempt-3 bisection: off 28.389494, capture 28.257144, encode/null-sink 28.221609, and full/CPFS 28.269199 req/s; incremental overheads 0%, 0.466%, 0.591%, and 0.424%.
• Exact mechanism: no TP1 worker serializer exists; the remaining msgspec leg natively encodes CUDAGraphStat with zero hook/pickle calls. Instead, envs.compile_factors() (vllm/envs.py:2011-2017,2089-2104 in the pinned pre-fix tree) included VLLM_OPPROF_DIR, and VllmBackend folded that map into the graph/AOT cache key (vllm/compilation/backends.py:1024-1065). A unique output directory therefore meant a unique, cold cache.
• Fix / line delta: ignore VLLM_OPPROF_DIR in compile factors; +1/-0 production line, +21/-1 test lines. Final local tip bbfa717, dash0 patch-ID-equivalent tip 9ad32ff; five exported patches.
• Unit tests: 15/15 local (0.02 s), 15/15 dash0 real tip (0.18 s), and 15/15 dash0 clean-base exported-series application (0.07 s); Ruff passed and the import-light contract is preserved.
• Layer-2 hard gate: PASS. Loadable 16,416,452-byte Kineto trace; exactly 2 warm-up + 8 active steps, 790,843 events, 7,367 kernels, and 35 distinct kernel names. Active mode was NONE because each profiled batch was about 8,192 tokens; the coverage caveat is explicit.
• Recorder microbenchmark: 29.1467 us/step by whole-loop timing; 27.7620 us median and 36.6643 us p95 over 10,000 iterations.
• PIECEWISE verification: PASS; 129/139 records PIECEWISE, buckets 1-248, padding 0-7, footer encoded=written=139 and dropped=0.
• MoE backend observed: TRITON unquantized in 48/48 campaign server logs.
• Weights path: /home/admin/cpfs/wjh/models/Qwen/Qwen3-30B-A3B.
• Total GPU time consumed: attempt 4 added 4,629 launch-to-clean seconds (77.15 H20-minutes): confirmation 813, quick signal 648, full gate 2,579, excluded Layer-2 attempt 329, accepted Layer-2 260. Whole campaign total is conservatively 11,018.58 seconds = 183.64 H20-minutes = 3.061 H20-hours.
• Cleanup: all eight H20s ended at 0 MiB/0%, with no campaign process.

Data sanity block

Attempt 4 is the final gate conclusion. Attempts 1-3 remain listed for auditability and are not pooled into its estimate.

Attempt 1 (invalidated measurement)

Numeric family	n	Min	Max	Distinct	Sanity note
Initial dash0 GPU memory used (MiB)	8	0	0	1	All eight H20s initially idle
Initial dash0 GPU utilization (%)	8	0	0	1	All eight H20s initially idle
Selected-GPU overhead precheck memory (MiB)	10	0	0	1	Required before every trial
Selected-GPU overhead precheck utilization (%)	10	0	0	1	Required before every trial
Selected-GPU immediate post-cleanup memory (MiB)	10	0	4	2	Trial 6 anomaly stopped the controller; next two checks were 0
Model shard bytes	16	1,087,928,584	3,999,975,472	11	Sum 61,066,575,648; no shard missing
Unit-test cases	14	N/A	N/A	14 names	14 passed, 0 failed
Footer-valid artifact step index	109	0	108	109	File order contiguous and monotonic
Artifact scheduled tokens/step	109	0	8,192	73	Non-negative
Artifact prefill tokens/step	109	0	8,188	15	Non-negative
Artifact decode tokens/step	109	0	200	80	Non-negative
Artifact scheduled requests/step	109	0	200	77	Non-negative
Artifact KV usage ratio	109	0	0.370965	106	Every ratio in [0,1]
Artifact CUDA-graph bucket	109	0	8,192	32	Bucket >= unpadded for every record
Artifact CUDA-graph padding	109	0	7	8	Exact bucket-minus-unpadded identity
Smoke input lengths	200	261	761	172	Sum 102,848
Smoke output lengths	200	32	96	59	Sum 12,187
ON throughput (req/s)	5	19.877357	22.685507	5	Not all identical
OFF throughput (req/s)	5	20.378458	26.350950	5	Not all identical
All throughput (req/s)	10	19.877357	26.350950	10	Positive; high run-level spread
Measured benchmark duration (s)	10	7.589859	10.061700	10	Positive
Adjacent-pair overhead fraction	5	-0.002012	0.236024	5	One negative pair, four positive pairs
Bootstrap overhead fraction	100,000	-0.002012	0.236024	232	Fixed paired resampling; no filtering
ON JSONL record count	5	183	186	3	Footer-written count matched records; drops all zero
ON JSONL bytes	5	165,982	168,696	5	Non-negative, non-identical
Overhead server GPU lifetime (s)	10	91	155	9	Sum 1,260 seconds
All server GPU lifetime (s)	12	91	414	11	Sum 1,863 seconds
Overhead startup time (s)	10	66	126	7	Excluded from throughput timing
Client wall time including warm-up (s)	10	21	25	5	Main metric used internal measured duration
Completed requests	10	200	200	1	Expected identical fixed workload
Failed requests	10	0	0	1	Expected invariant
Input tokens	10	102,848	102,848	1	Expected identical fixed workload
Output tokens	10	12,187	12,187	1	Expected identical fixed shapes
Exact generated responses vs trial 1	10	185	200	7	Anomaly: generated-text digests distinct in all ten trials

Attempt 2 A-P2-1 valid pre-fix measurement

Numeric family	n	Min	Max	Distinct	Sanity note
Accepted pre-launch GPU memory (MiB)	10	0	0	1	Every accepted server launched only after stable zero
Accepted pre-launch GPU utilization (%)	10	0	0	1	No selected-GPU process present
PIECEWISE addendum step index	139	0	138	139	Contiguous and monotonic
PIECEWISE runtime records	129	1 unpadded token	241 unpadded tokens	9 token counts	Every runtime mode was PIECEWISE
PIECEWISE bucket tokens	129	1	248	6	Bucket >= unpadded
PIECEWISE padding tokens	129	0	7	5	Exact bucket-minus-unpadded identity
Microbenchmark per-iteration cost (us)	10,000	26.293	70.111	4,144 ns values	Mean 28.9279, median 27.7620, p95 36.6643
Microbenchmark empty-timer cost (us)	10,000	0.082	12.012	84 ns values	Harness cost small relative to producer path
Accepted ON throughput (req/s)	5	28.183682	28.256715	5	Range 0.259% of minimum; not identical
Accepted OFF throughput (req/s)	5	28.800396	29.640096	5	First OFF lower than later OFF runs
All accepted throughput (req/s)	10	28.183682	29.640096	10	Positive and non-identical
Accepted measured duration (s)	10	134.952330	141.926096	10	Every run >=120 seconds
Accepted pair overhead fraction	5	0.020746	0.047369	5	All five pairs positive
Accepted bootstrap overhead fraction	100,000	0.020746	0.047369	263	CI [0.031364, 0.047117]
Completed requests/run	10	4,000	4,000	1	Expected fixed workload
Failed requests/run	10	0	0	1	Required invariant
Input tokens/run	10	2,031,054	2,031,054	1	Input-length digest distinct=1
Output tokens/run	10	256,000	256,000	1	Output-length digest distinct=1
Input lengths in one fixed stream	4,000	256	768	512	Same array in all ten runs
Output lengths in one fixed stream	4,000	64	64	1	ignore_eos fixed all work
Generated-text digests	10	N/A	N/A	7	Content varied; token volume did not
Accepted ON JSONL records	5	1,403	1,406	3	Footers matched; all drops zero
Accepted ON JSONL bytes	5	1,283,109	1,286,129	5	Mean 914.7 bytes/record
Accepted ON active stream span (s)	5	144.726692	144.968812	5	Continuous submit-to-complete spans
Accepted ON step rate (steps/s)	5	9.681545	9.707954	5	Mean 9.696167
Scheduled requests/telemetry record	7,022	0	200	127	Non-negative; configured cap 200
Periodic GPU samples	545	P0	P0	1 pstate	No pstate transition
Active GPU SM clock (MHz)	318	1,740	1,980	12	Max-clock family distinct=1 at 1,980 MHz
Active GPU power (W)	318	118.46	501.12	311	Non-negative
One-minute load average	20	0.15	1.63	19	Low relative to 160 logical CPUs
Newly observed other-user processes	39	N/A	N/A	11 command names	All root-owned; explicitly reported
Other-user GPU samples/run	10	0	0	1	No GPU contamination
Accepted startup time (s)	10	64	116	8	ON 111-116; OFF 64-73; excluded from metric
Accepted server allocation (s)	10	258	312	10	Sum 2,858 seconds
Amended server allocation (s)	13	102.54	312	13	Burn-in, PIECEWISE, excluded pilot, accepted series; sum 3,303.58 seconds
Campaign allocation through attempt 2 (s)	25	91	414	24	Sum 5,166.58 seconds = 86.11 H20-minutes

Attempt 3 diagnostic bisection

Numeric family	n	Min	Max	Distinct	Sanity note
Stage pre-launch GPU memory (MiB)	4	0	0	1	Stable zero before each server
Stage pre-launch GPU utilization (%)	4	0	0	1	No selected-GPU process
Stage throughput (req/s)	4	28.221609	28.389494	4	Total spread 0.595% of minimum
Stage measured duration (s)	4	147.942050	148.822131	4	Every stage approximately 140 seconds or longer
Stage overhead vs off fraction	4	0	0.005914	4	No stage approached 0.041816
Completed requests/stage	4	4,200	4,200	1	Fixed work
Failed requests/stage	4	0	0	1	Required invariant
Input tokens/stage	4	2,132,262	2,132,262	1	Input digest distinct=1
Output tokens/stage	4	268,800	268,800	1	Output digest distinct=1; every output 64 tokens
Stage startup time (s)	4	111	126	4	Excluded from measurement
Stage server allocation (s)	4	301	316	4	Sum 1,223 seconds
Stage JSONL file count	4	0	1	2	Off/encode 0; capture/full 1
Stage JSONL bytes	4	0	1,346,466	3	Capture footer 96 bytes; full CPFS 1,346,466
Temporary-diff unit tests	14	pass	pass	14 names	14/14 remote before trials
Restored-branch unit tests	14	pass	pass	14 names	14/14 local after reversal
Whole-campaign server allocation (s)	29	91	414	28	Sum 6,389.58 seconds = 106.49 H20-minutes

Attempt 4 confirmation, fix, and final gate

Numeric family	n	Min	Max	Distinct	Sanity note
Static typed msgspec round-trip time (us)	2	1.5340	1.7215	2	Populated-stat delta 0.1875 us; hook calls 0/0
Static typed MessagePack bytes	2	358	451	2	Positive; populated stat is larger as expected
Confirmation throughput (req/s)	3	28.452675	29.716821	3	Baseline/upstream close; env-set arm isolated
Confirmation measured duration (s)	3	134.603900	140.584322	3	Every arm >=120 seconds
Confirmation difference vs baseline	3	0	0.042540	3	Upstream 0.002521; env-set 0.042540
Confirmation compile-cache key	3	N/A	N/A	2	Baseline/upstream same; env-set alone differed
Compared torch.compile time (s)	2	6.07	36.41	2	Cache load versus compile/save
Compared engine initialization (s)	2	21.85	70.22	2	Same cache-key split as compile time
Confirmation server allocation (s)	3	248	307	3	Sum 813 seconds
Quick-pair throughput (req/s)	2	29.677979	29.700657	2	Positive, not identical
Quick-pair overhead fraction	1	-0.000764	-0.000764	1	Negative means ON was 0.0764% faster; <2% continuation threshold
Fixed-gate pre-launch GPU memory (MiB)	11	0	0	1	Burn-in plus ten trials all launched from zero
Fixed-gate pre-launch GPU utilization (%)	11	0	0	1	No selected-GPU process present
Fixed-gate ON throughput (req/s)	5	29.637994	29.712835	5	Positive and not all identical
Fixed-gate OFF throughput (req/s)	5	29.624180	29.677443	5	Positive and not all identical
All fixed-gate throughput (req/s)	10	29.624180	29.712835	10	Total spread 0.299% of minimum
Fixed-gate measured duration (s)	10	134.621958	135.024835	10	Every run >=120 seconds
Fixed-gate pair overhead fraction	5	-0.002993	0.000674	5	Three ON-faster and two OFF-faster pairs
Fixed-gate bootstrap overhead fraction	100,000	-0.002993	0.000674	224	CI [-0.001744, 0.000455], no filtering
Completed requests/run	10	4,000	4,000	1	Fixed work invariant
Failed requests/run	10	0	0	1	Required invariant
Input tokens/run	10	2,031,054	2,031,054	1	Input-length digest distinct=1
Output tokens/run	10	256,000	256,000	1	Output-length digest distinct=1; every completion 64
Generated-text digests	10	N/A	N/A	6	Content varied; exact work did not
Fixed-gate startup time (s)	10	60	76	6	Excluded from throughput metric
Fixed-gate measured server lifetime (s)	10	244	262	6	Sum 2,485 seconds
Full-protocol server allocation (s)	11	94	262	7	Includes burn-in; sum 2,579 seconds
One-minute host-load snapshots	22	0.23	2.36	20	Low relative to 160 logical CPUs
Current-SM clock snapshots (MHz)	22	345	1,980	2	Eleven pre-launch 345; eleven immediate post-run 1,980; max 1,980 throughout
Idle memory-clock snapshots (MHz)	22	2,619	2,619	1	Stable before/after
Other-user GPU process count/run	11	0	0	1	Periodic samples contained only campaign processes
Fixed-gate ON JSONL records	5	1,406	1,412	4	Contiguous step indices and msgspec-decodable
Fixed-gate ON JSONL bytes	5	1,285,722	1,291,357	5	Positive and not identical
Fixed-gate ON footer count	5	0	0	1	Anomaly: simultaneous teardown; excluded from artifact accounting
Final unit-test cases	15	pass	pass	15 names	Local, real-tip remote, and clean-base remote all passed

Layer-2 accepted window

Numeric family	n	Min	Max	Distinct	Sanity note
Kineto trace files	1	16,416,452 bytes	16,416,452 bytes	1	gzip and JSON loadable; SHA-256 recorded
Trace category counts	13	1	713,524	13	Sum 790,843 total events
Kernel event count	1	7,367	7,367	1	35 distinct kernel names
Active profiler-step number	8	2	9	8	Contiguous; configured active count exactly met
Active execute context tokens	8	8,025	8,048	5	Non-negative
Active execute generation tokens	8	144	167	5	Context + generation exactly 8,192 each
Scheduled collection window duration (s)	1	8.174811	8.174811	1	Covers the active trace collection
Equal-window completed requests	2	131	269	2	Profile versus immediately preceding steady window
Equal-window request rate (req/s)	2	16.024836	32.905961	2	Indicative 51.30% profiler perturbation
Endpoint-window request rate (req/s)	3	5.435085	29.872225	3	Profile, equal pre, equal post; stop/finalization included
Layer-2 whole-load throughput (req/s)	1	25.869730	25.869730	1	4,000 completed, zero failed
OpProf collection-window per-mode record counts	1	10	10	1	Only observed mode was NONE
OpProf endpoint-pre per-mode record counts	3	2	215	3	FULL 215, NONE 54, PIECEWISE 2; sum 271
Layer-2 OpProf record count	1	1,407	1,407	1	Contiguous; used only for mode/timing evidence
Layer-2 OpProf footer count	1	0	0	1	Anomaly: same simultaneous-teardown issue; not artifact-gate evidence
Attempt-4 server allocation (s)	19	94	329	13	Sum 4,629 seconds = 77.15 H20-minutes
Whole-campaign aggregate GPU time (s)	1	11,018.58	11,018.58	1	183.64 H20-minutes; one GPU only

Checked invariants across accepted evidence: non-negative counters; KV ratios in [0,1]; exact KV block accounting and histogram sums; contiguous unique step indices; footer encoded=written+dropped and zero drops in the footer-valid artifact evidence; graph hit/mode/bucket/padding consistency; footer-valid PIECEWISE runtime coverage; fixed ABBA order; five adjacent pairs; positive throughput; 4,000 successes and zero failures per fixed-gate run; durations

=120 seconds; output lengths exactly 64; input/output arrays identical across runs; shared post-fix compile-cache key; and per-arm results not all identical. Negative overhead values are permitted because they denote an ON-faster sample, not a non-negative counter or probability. Monotonicity/curve continuity is not applicable to this interleaved repeated-measures experiment.

Attempt 3 additionally checked identical fixed work, zero failures, durations

=140 seconds, stable-zero GPU prechecks, clean teardown, and four distinct positive throughputs. Its key invariant failure was conceptual rather than numeric: stage off returned no recorder but could not disable the external model-runner flag derived directly from VLLM_OPPROF_DIR.

Red flags and anomalies were reported before conclusions: attempt 1's invalid noise/cold-start protocol; the excluded file-descriptor pilot; transient 4 MiB driver accounting; 39 root-process arrivals; varying content digests; the attempt-2 mode-correlated startup split and valid CI exceeding 3%; attempt 3's non-equivalent off boundary; the initial clean-base test-isolation failure; the excluded buffered-marker Layer-2 run; and missing footers caused by the attempt-4 simultaneous process-group teardown. The PIECEWISE coverage red flag is closed, not suppressed. Attempt-4 files without footers are explicitly excluded from artifact accounting rather than treated as footer-valid.