perf: Stage 2 — per-role GPU timing instrument, and the decode profile it produced

[ulises-c]

Summary

Stage 2 of the Qwen 3.6 perf work. Two things land here: an opt-in per-role GPU
timing instrument, and the first real measurements taken with it on this host.

Stage 2 was originally planned as "cherry-pick NVMAI's individually-measured
perf commits." That premise did not survive contact — their headline
optimization (4beb74f, parallel expert pread fills) is already in our tree
at PreadExpertStreamer.executeExpertCachePlan, and the profiler-bug fix
927c94e repairs an instrument we never had. Their percentages are measured
against a serial baseline we no longer have, so they are not transferable. The
rule adopted, and applied here: measure first, never carry over a reported
percentage as an expected result.

What's in it

commit	what
a73c25b	runner-side accumulation of completed GPU spans by role
f2a8e6c	deterministic CLI report on stderr
da7d816	the profile + A/B writeup in docs/STAGE2_PLAN.md

TURBO_FIELDFARE_KERNEL_STATS=1 — and only that exact value — enables
collection. Roles: embed, attention_router, shared_expert, the optional
moe_phase1_hit split, every routed_moe layer, and whichever of
fused_head/logits_head ran.

Design points worth a reviewer's attention:

• Bounded state. Aggregation is by role as samples arrive, not one sample
  per command buffer, so storage is bounded by role count rather than token
  count or runner lifetime. Cleared on reset() and on prompt-cache
  continuation, so one generation never inherits another's spans.
• Timestamps read only after completion. Routed, shared, and phase-one
  buffers are recorded in the common drain path after completion and error
  validation, so every layer is counted and no timestamp is read early.
• Off means off. With the flag unset the only added work is a branch at each
  completion point. No scheduling, pipeline, or default changes anywhere.
• stdout is untouched. The report goes to stderr only.

The profile

M5 Max, 36 GB, macOS 26.6.2, Swift 6.3.3, release build, Gemma 4
scratch/gemma4.gturbo. All three frozen real-generation-v1 prompts,
--max-new 128 --max-context 4096 --temperature 0.2 --top-k 64 --top-p 0.95 --seed 20260721.

prompt	tok/s	expert io await	unaccounted	attention_router
short-explanation	42.44	1222.8 ms	1692.5 ms	527 ms
medium-review	40.30	1198.1 ms	1872.5 ms	684 ms
long-synthesis	38.17	1192.2 ms	2059.6 ms	903 ms

Two separable blocks, and the per-role split is what separates them:

1. Expert I/O await is ~40 % of decode and flat across prompt lengths
   (1222/1198/1192 ms) — a per-token fixed cost of pulling routed experts, not a
   context effect.
2. unaccounted (GPU waits) is the other ~55 % and it is the part that grows
   with context (1692 → 2059 ms). attention_router alone accounts for it,
   going 527 → 903 ms while every other role stays flat.

Summed GPU spans (1382 ms) sit well below decode wall time (3016 ms) even though
the roles cover the whole forward pass — command buffers overlap, so the gap is
stall, not unmeasured compute. embed is 0.36 ms over 128 tokens; nothing to
win there.

First A/B: expert-cache slots

Interleaved A/B/A/B, four pairs, two warmup runs discarded, short-explanation:

arm	tok/s (4 runs)	mean	expert io await
16 slots (default)	45.93 / 44.90 / 45.55 / 45.43	45.45	1078.7 ms
32 slots	48.20 / 46.80 / 46.38 / 48.17	47.39	866.0 ms

+1.93 tok/s (+4.3 %), winning all four adjacent pairs with disjoint
distributions (min B 46.38 > max A 45.93). The mechanism matches the profile
rather than merely correlating with it: the gain is bought entirely in expert
I/O await (−19.7 %), the exact block the profile named, with roughly half
refunded to unaccounted as decode stalls on the GPU instead — which is why the
headline is +4.3 % and not the ~7 % the I/O delta alone would suggest.

A confound I hit, and how it's controlled

The first attempt ran the arms back to back and produced a clean monotonic win
for more slots. It was an artifact. Every run beat the previous one
regardless of arm — page-cache warming aliased perfectly onto run order. The
numbers above are the redo with arms interleaved so order cannot alias the
lever. The discarded pass is written up in the plan doc too, since the failure
mode is the more reusable finding.

--rdadvise adaptive/bounded cut I/O await similarly but returned all of it to
unaccounted, netting no throughput change. It was only measured in the
confounded pass, so it is logged as "no effect observed", not a settled
negative.

Test plan

• Scripts/test.sh — 1328 tests in 203 suites passed (161s)
• Generated stdout byte-identical with instrumentation off, verified against
  the Stage 1 baseline hash on the installed model
• stdout also byte-identical with instrumentation on — same hash across
  all 10 A/B runs and both flag states
• Three repeats of short-explanation within 0.1 % on tok/s
• Independent read-only review of the full diff: no blocking defects

Blocking questions

1. Should the 32-slot result graduate to a default flip? Not proposed here —
   per AGENTS.md this is a measurement, not a default change. Making the case
   needs the other two prompts, a memory-headroom check at 32 slots, and the
   same interleaved treatment. Worth doing now, or defer until Qwen is
   installed?
2. Is attention_router in scope for Stage 2C? It is the entire
   context-dependent cost and currently the larger block, but it is also the
   part where NVMAI's picks are least likely to transfer.
3. Should rdadvise get a clean interleaved A/B, or is "no effect observed"
   enough to drop it?

Caveat on coverage

The installed model is Gemma 4; Qwen 3.6 is not downloaded. Expert-I/O,
slot-cache, and rdadvise work is family-agnostic and measurable on Gemma today,
but any Qwen-specific decode claim needs the ~19.6 GB install first.