# 2026-05-07 · M3.6 Phase 1 nsys trace — ARLE s48 high-conc

## Goal

- M3.6 Phase 1 capture per
  [`docs/plans/M3.6-decode-throughput-no-retraction-tax.md`](../../plans/M3.6-decode-throughput-no-retraction-tax.md)
  Phase 1 / [`docs/plans/M3.6-nsight-trace-analysis-runbook.md`](../../plans/M3.6-nsight-trace-analysis-runbook.md):
  identify which layer of the ARLE stack hosts the 39% throughput
  gap to vLLM's `--max-num-seqs 14` equal-width control (codex's
  Phase-1 step 3 evidence at `c3b0449`).
- Goal type: **diagnostic** (not optimization). Output is evidence
  that licenses the next code change, not a perf delta.

## Hypothesis

Going in, three layers were plausible (per M3.6 P0 finding table):
scheduler CPU overhead, scheduler page-accounting policy, decode
kernel efficiency. F1 (prefill admission cap) was already falsified
by codex at `c3b0449`. The trace was expected to discriminate F2
(decode-protected kv_util) vs kernel-level work.

## Command

ARLE server under `nsys profile` with delay+duration so trace
bounds the steady-state bench window only:

```bash
NVCC_CCBIN=/usr/bin/g++-14 INFER_TILELANG_PYTHON=...venv/bin/python TORCH_CUDA_ARCH_LIST=8.9 \
nsys profile \
  --output bench-output/2026-05-07-m3.6-arle-s48-nsys/arle-s48 \
  --trace cuda,nvtx,osrt --cuda-graph-trace node \
  --delay 25 --duration 60 --kill none \
  target/release/infer --port 8000 --max-seq-len 5120 --num-slots 48
```

Bench (codex's exact 1024 in / 256 out shape replayed):

```bash
guidellm benchmark run --target http://localhost:8000 \
  --profile concurrent --rate 64 \
  --data 'prompt_tokens=1024,...,output_tokens=256,...' \
  --max-seconds 45 --warmup 5 --random-seed 20260416
```

Note: wrapper `scripts/profile_nsys_guidellm.sh` was not used —
hardcoded `--attach-pid` no longer recognised by nsys 2025.6.3 (CLI
removed it in favor of the `nsys start --session-new=...` pattern).
Tracked as a follow-up; this run drove nsys directly.

## Environment

- GPU: NVIDIA RTX 4080 SUPER, CUDA 13.2.1, SM 8.9
- Driver / nsys: 2025.6.3.541, ncu: 2026.1.1.0
- Build: `998bfee` (NVTX scaffolding) + `cargo build --release --features cuda`
- Server: `--num-slots 48 --max-seq-len 5120` (5120 to fit guidellm's
  prompt_tokens=1024 + headroom; codex's prior work used 2048 with
  rejection of 4097-token noise prompts)
- Bench: 1024 in / 256 out, c=64, 45s + 5s warmup
- Workload: `Qwen3-4B`, processor `infer/models/Qwen3-4B`
- Capture window: 60s, starting at server-boot + 25s

## Results

### Bench numbers (overlap with codex Phase 1 step 3 baselines)

| Metric | This run (s48 + 5120) | codex s48 baseline | codex vLLM s14 control |
|---|---:|---:|---:|
| out tok/s | **462.1** | 442 | 615 |
| TTFT mdn | 3729 ms | 3878 ms | 17609 ms |
| ITL mdn | 66.0 ms | 65.4 ms | 20.2 ms |
| TPOT mdn | 79.9 ms | — | — |
| Concurrency mdn | 64 | 47 | 51 |

ARLE 462 vs vLLM 615 = **75.1% of vLLM throughput at equal admission**.
Gap = 33% (consistent with codex's prior 39% characterization within
scout noise).

### Step 1 — top GPU kernels (`cuda_gpu_kern_sum`)

| Rank | Kernel | GPU Time % | Avg | Calls |
|---|---|---:|---:|---:|
| 1 | `decode_attention_varlen_quantized_partial_kernel<128,1,0>` | **41.6%** | 4.55 ms | 4,104 |
| 2 | `ampere_bf16_s1688gemm_bf16_128x128_ldg8_f2f_stages_32x1_tn` | 25.1% | 0.39 ms | 28,836 |
| 3 | `decode_attention_fp8_partial_kernel<128>` | **13.9%** | 0.40 ms | 15,732 |
| 4 | `ampere_bf16_s16816gemm_bf16_128x64 32x6` | 7.4% | 0.105 ms | 31,464 |
| 5 | `ampere_bf16_s16816gemm_bf16_128x64 64x3` | 3.1% | 0.087 ms | 15,732 |
| 6 | misc bf16 GEMM variants | ~6% | varies | varies |

**Decode attention kernels combined: 55.5% of all GPU time**. Per
runbook §Step 1 mapping, this matches the "Top kernel is decode_attn
≥ 70%" pattern (close — 55.5% combined).

### Step 2 — NVTX phase share (`nvtx_sum`)

| NVTX range | Wall % | Avg per instance | Instances |
|---|---:|---:|---:|
| `step_total` | 96.6% | 82.1 ms | 554 |
| `step_mixed_kernel_launch` | 1.3% | 5.20 ms | 114 |
| `step_prefill_kernel_launch` | 1.1% | 531 ms | 1 (single warmup launch) |
| `step_decode_kernel_launch` | 0.9% | 1.00 ms | 437 |
| `step_admission` | 0.02% | 18.8 µs | 554 |
| `step_plan` | 0.02% | 14.7 µs | 553 |
| `step_dispatch_emits` | 0.02% | 12.7 µs | 553 |
| **`step_mixed_launch_retract`** | **0.001%** | 3.06 µs | 114 |

Scheduler-policy ranges sum to ~0.06% of wall time. Kernel-launch
ranges sum to ~3.3%. **Step_total is 96.6% — the remaining ~93% is
unaccounted for, i.e. CPU outside instrumented ranges**. See Step 3.

### Step 3 — CPU API surface (`cuda_api_gpu_sum`)

| API call | % of CPU API time | Total | Avg | Calls |
|---|---:|---:|---:|---:|
| **`cuStreamSynchronize`** | **48.6%** | **43,786 ms** | **65.7 ms** | 666 |
| `cudaMemsetAsync` | 0.1% | 78 ms | 2.7 µs | 28,999 |
| `cuMemAllocAsync` | <0.1% | 30 ms | 26 µs | 1,138 |
| `cuMemcpyDtoHAsync_v2` | <0.1% | 22 ms | 18 µs | 1,217 |
| (everything else) | <0.1% each | | | |

`cuStreamSynchronize` average **65.7 ms per call** with max
**274 ms**. 666 sync calls over ~45 s of bench = ~15 syncs per
second across all streams. The trace shows the 96.6%
unaccounted-for `step_total` time is dominated by CPU blocked on
`cuStreamSynchronize`.

### Step 4 — CUDA graph replay

Not run separately — graph events visible in cuda_api_gpu_sum and
no anomaly flagged. Replay variance check deferred (would only
matter if the bottleneck were graph-shape regression, which it is
not given Step 3).

## Headline finding

**Two simultaneous bottlenecks**, ranked by clarity of fix-direction:

### Finding 1 — CPU is blocked on `cuStreamSynchronize` 48.6% of the time

The scheduler issues kernels and then `cuStreamSynchronize` blocks
the CPU thread until they finish, instead of pipelining the next
step's preparation against the current step's GPU execution. At
65 ms avg sync × ~15 calls/s, the scheduler thread is blocked
~1 second per second of wall time. This is the kind of CPU-blocked
pattern that CUDA graphs and stream-pipelining usually eliminate;
ARLE has graphs but the sync is still happening, suggesting:

- (a) graph replay itself uses synchronous launch then waits, or
- (b) some non-graph code path (sampling readback? KV bookkeeping?)
  still calls sync per-step.

### Finding 2 — Decode attention is the largest single GPU cost

`decode_attention_varlen_quantized_partial_kernel` alone is 41.6% of
GPU time at avg 4.55 ms per call. Compared to vLLM's Triton
attention at the same effective batch — **the Phase 2 vLLM control
trace is required to confirm whether ARLE's kernel is genuinely
slower or just busier**. Phase 2 IS the next action.

### Falsified hypotheses

- **F2 — decode-protected kv_util threshold**: the retract NVTX
  range is **3 µs avg, 0.001% of wall time**. There is no
  retraction tax to pay. F2 is falsified by trace evidence.
- **Scheduler CPU overhead** (admission / plan / dispatch_emits /
  retract): all combined ~0.06% of wall. Not the bottleneck.
- **F3 — split prefill page budget**: F3 is a sub-case of F2;
  same evidence falsifies it.

## Problems

1. **Wrapper broken under nsys 2025.6.3**:
   `scripts/profile_nsys_guidellm.sh` uses `nsys profile --attach-pid`
   which was removed. Drove nsys directly for this run; wrapper
   needs migration to the modern `nsys start --session-new=` pattern
   or to spawn-mode (this run used spawn-mode + delay).
2. **First-attempt rejected prompts**: ran the wrapper with
   `--profile concurrent --concurrencies 64` but no explicit
   `--data prompt_tokens=...`; bench wrapper sent 4097-token prompts
   that server (`--max-seq-len 2048`) rejected. Re-ran with explicit
   `--data` matching codex's `m6-highconc-phase1-vllm-s14` shape.
3. **Phase 2 vLLM control trace not yet captured**. Required to
   compare decode kernel duration ARLE-vs-vLLM at the same effective
   batch (the only way to firmly distinguish "kernel slow" from
   "kernel busy").

## Learnings

- `step_total` 96.6% wall vs ~3.3% inside any kernel-launch NVTX
  range → instrumented ranges only catch the CPU-launch side; the
  CPU `cuStreamSynchronize` wait is OUTSIDE the kernel-launch
  scopes. Future NVTX additions should include a `step_gpu_wait`
  range around the post-launch sync to localize this in future
  traces.
- F2/F3 trace-evidence falsification is a strong reason to NEVER
  ship those fixes. The plan's "candidate parking" structure paid
  off — landing F2 speculatively would have been wasted code.
- Industry pattern (WukLab MLSys "scheduling overhead can dominate"
  paper) was about scheduling overhead at the Python-vLLM-CPU layer.
  ARLE has the OPPOSITE problem: scheduler is fast, GPU completion
  wait is slow.

## Bench Status

- Headline bench: 462 out tok/s, matches codex baseline 442 within
  scout noise. 75.1% of vLLM s14 control throughput.
- Trace artifact: `bench-output/2026-05-07-m3.6-arle-s48-nsys/arle-s48.nsys-rep`
  (~19 MB, gitignored). sha256:
  `d0711d7a0333cdbc61c1f32c608aa3b9113fd443c389794a78b6faf73b5dfb4e`.
  Per `docs/bench-and-trace-spec.md` §§8-9 — raw nsys-rep stays in
  bench-output, sha256 cited here for durable reference.

## Next actions (decided by trace evidence)

1. **Phase 2 — vLLM s14 control trace** (codex or me, next tick).
   Drive `scripts/vllm_serve_control.sh` (committed in `998bfee`)
   under `nsys profile`. Compare decode-attention `Avg Time` ARLE vs
   vLLM at the same effective batch. Decision matrix per runbook
   §Decision matrix.
2. **Investigate `cuStreamSynchronize` callers in ARLE** — grep
   `infer/src/scheduler/cuda/` and `crates/cuda-kernels/csrc/` for
   the sync calls. If they are in the decode batch finalize path,
   that is the F4 candidate (parallel to vLLM's CUDA-graph-only
   replay).
3. **Phase 4 — `ncu --set full` on `decode_attention_varlen_quantized_partial`**
   ONLY after Phase 2 confirms the kernel is genuinely slower than
   vLLM's equivalent. ncu serializes execution and is not run on the
   full bench — single-launch micro-bench instead.

## Rule

- The runbook §Step 3 default-frame ("CPU bubble = scheduling
  overhead") was wrong-direction here. ARLE's CPU bubble is from
  WAITING on GPU completion, not from scheduling work. The runbook
  needs an update: when `cuStreamSynchronize` dominates AND
  scheduler NVTX ranges are tiny, the answer is graph-replay /
  pipelining work, not algorithm work in the scheduler.
- Always check `cuda_api_gpu_sum` for the sync calls separately.
  `cuStreamSynchronize` ≥ 30% is its own diagnostic class.
