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

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

1234 lines
71 KiB
Markdown
Raw Blame History

# 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:
```bash
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:
```bash
/tmp/wjh-opprof-phase2-dash0-20260711/.venv/bin/python -m pytest \
--confcutdir=tests/v1/core tests/v1/core/test_opprof.py -q
```
```text
............... [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:
```bash
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:
```bash
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:
```bash
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:
```text
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.
Reference in New Issue View Git Blame Copy Permalink