Skip to content

bench: add a decode-shaped CPU benchmark harness (gap, warm-up, park/wake) - #1395

Merged
justinchuby merged 13 commits into
mainfrom
squad/sebastian-gap-harness
Aug 25, 2026
Merged

justinchuby merged 13 commits into
mainfrom
squad/sebastian-gap-harness

Conversation

@justinchuby

@justinchuby justinchuby commented Aug 19, 2026 •

Copy link
Copy Markdown
Owner

Revived after a long stall. The branch was 469 commits behind main; this brings it current, and the merge was resolved so that the branch is now purely additive — 2260 insertions, 0 deletions against main.

What this is, and what it is not

A model-level decode-gap harness: it runs a real ONNX model through the native session with a configurable inter-token gap distribution, and reports the steady-state wall/CPU/RSS/context-switch/pool-counter picture around it.

It is not a replacement for crates/onnx-runtime-ep-cpu/benches/decode_gap_park_ab.rs, which is already on main. That one is a synthetic harness over the decode SPMD pool. This one drives task_runtime::pool through a real graph. Those are two different pools with different park/spin policies, and — as decode_gap_park_ab.rs's own docs say — a conclusion from one must not be quoted for the other. Saying so here because the two names are confusingly similar and I expect to be the person who confuses them.

The merge decision worth flagging

My original branch extracted ~520 lines out of bench_generic.rs into a shared module. Over 469 commits, bench_generic.rs had moved on considerably. I took main's version wholesale rather than re-applying my refactor.

The consequence is a real cost and I would rather state it than hide it: model_io.rs duplicates some helpers that also exist in bench_generic.rs. I chose duplication over refactoring a file that several other lanes are actively editing. If the duplication becomes a maintenance problem the de-duplication is a separate, reviewable change; folding it into a revival PR would have made this one impossible to review and would have conflicted with everyone.

Exactly one compile error survived 469 commits of drift: PoolCounters gained straggler_waits and straggler_yields. That is a good sign for the interface, not for my branch hygiene.

The finding that came out of the smoke run, and the change it forced

The first end-to-end run reported:

cpu:           19.070 s over steady window  (7.85 cpu-s per wall-s)
native pool:   0.00 dispatches/iter  0.00 parks/iter  0.00 spin-hits/iter

Eight cores of work, and a row of zeroes from the instrument that is supposed to explain it. That is precisely what a dead counter looks like, so I chased it as one before pushing.

It was not dead. An fp32 MatMul fans out on rayon, not on task_runtime, so the zero was true — the harness was faithfully reporting a pool the model never touched.

The defect is that I could not tell those apart from the output. The pool counters answer "how hard did task_runtime work"; they cannot answer "did this model use task_runtime at all"; and the two questions produce byte-identical output. Only one of them means the harness is broken.

So the run now attributes its own routes through dispatch_ledger, and annotates a zero-dispatch row with which case produced it:

native pool:   0.00 dispatches/iter  0.02 parks/iter  0.00 spin-hits/iter  0 slot-exhausted
ATTRIBUTION:   this model never dispatched to task_runtime -- the pool row above is a
               true zero, not a dead counter. Routes below say what ran instead.
route:         MatMulF32 -> Native (f32, 8 calls, up to 8 threads)

Recording is enabled for a single attribution inference and never during the timed window, because record_with builds an Observation per dispatch.

Both branches are proved, not asserted:

condition output
ledger on, 8-layer fixture MatMulF32 -> Native (f32, 8 calls, up to 8 threads)
ledger on, 4-layer fixture MatMulF32 -> Native (f32, 4 calls, up to 2 threads)
enable() commented out zero dispatches AND zero routes recorded ... this is a dead instrument, not a measurement -- do not quote the pool row

The third row is the whole point. Without it, the dead case and the true-zero case print the same thing, and I would have pushed a harness that cannot distinguish them.

A side benefit that matters for this campaign specifically: the route line makes every run state on the record whether it was pure native, MLAS, or an ORT fallback. That was previously an assumption carried in the operator's head rather than a column in the output.

Other properties it already had, and which the smoke run exercised

  • A null A/A arm. --arm null runs the same configuration twice and prints null_b_over_a with the explicit note that any A/B ratio inside this band is noise. Measured 0.968x on a small fixture and 0.992x on a large one.
  • It refuses to report a steady state it did not observe. At 32 iterations: steady window: NOT REACHED (series never settled) plus WARNING: no steady state ... Every number above describes the warm-up transient. Raise --iters. At 512 iterations it detects the window and reports from it.
  • Parity against ORT before the timed loop, with the ORT session built, used and dropped before timing starts — a co-resident ORT session spin-waits long after its last op and depresses a native arm measured beside it.

Validation

  • cargo test -p onnx-genai-bench --features bench-native --lib — 32 passed, 0 failed
  • cargo clippy -p onnx-genai-bench --features bench-native --bin bench_decode_gap -- -D warnings — clean
  • cargo fmt --all -- --check — clean
  • End-to-end runs under scripts/hostlock.sh, both fixtures, both ledger states

No timing claim is made from any of these runs. They are correctness and instrument-liveness checks; the numbers quoted above are shown only to demonstrate that the instrument distinguishes cases, and the fixtures were synthetic MatMul chains, not a model anyone should benchmark.

Known, not mine

cargo clippy -p onnx-genai-bench --features bench-native --bin compare -- -D warnings fails on collapsible_if at compare.rs:845. Verified identical on an unmodified tree — that feature combination is evidently not gated in CI. Not introduced here.

…wake)

The CPU scheduler campaign had two harness shapes and neither was honest
about decode. `bench_generic`'s tight loop measures the one regime decode
never occupies: with no gap between iterations the task pool's workers never
park, so every dispatch lands on a spinning core. Its short default run also
sits inside the pool warm-up transient, which on a 16-wide budget runs to
several hundred iterations.

Add `bench_decode_gap`, which runs any ONNX model with a configurable
inter-token gap (mean, jitter, and busy/sleep/mixed kind), detects its own
steady-state window instead of taking a guessed `--warmups`, and reports the
counters that identify the scheduling regime: wall/CPU/RSS, per-thread
context switches, and the task pool's own park/spin/dispatch counters. The
ORT session is dropped after the parity check so the timed window is solo by
construction rather than by remembering a flag (§38).

Measurement logic lives in `decode_gap.rs` behind 31 unit tests. Two of those
tests exist because the first working harness was confidently wrong:
`/proc/self/status` has no CPU accounting at all, and its context-switch
counters describe only the leader thread — which made a pool of sixteen
parking workers indistinguishable from a spinning one at every gap.

Extract the model I/O and parity paths shared with `bench_generic` into
`model_io.rs` so the two harnesses cannot silently diverge on input
synthesis. Verified behaviour-preserving: both binaries report bit-identical
parity fingerprints for the same model.

Findings recorded in §41 of the campaign ledger, including: the pool stops
spinning between 200us and 500us (`MAX_SPIN`, confirmed independently by the
`task_runtime_latency` micro-benchmark); the ~2x-budget unnamed threads are
our own eagerly-built global Rayon pool, and the ORT session contributes
zero threads; median latency under 4 concurrent sessions degrades 1.9x while
p90 degrades 4.6x, which the dispatch-level micro-benchmark cannot see.

No kernel or scheduler behaviour changes here. The adaptive spin window is
deliberately left alone: it costs +0.4 CPU-ms per iteration at a
decode-shaped 100us gap, and only saturates near 6.5 CPU-ms at gaps decode
does not have.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The 4-to-8 scaling stall reported in §41.6 does not reproduce. Chasing it
turned up something more useful than the claim it retracts.

Re-measuring budget 4 with the same binary and flags gives 1.858/1.847/1.861
in one session and 2.766/2.761/2.756 in another. Four samples inside 1%
within a session — tighter than the null control — and 1.48x apart across
sessions. Each reading is genuinely steady; they are steady at different
values, so steady-state detection does not catch this.

The cause is the budget's own affinity confinement. `select_budget_cpus` is
deterministic: budget 4 always takes CPUs [0, 2, 4, 6]. Those cores were
22-34% busy with co-tenant work during the slow session. A budgeted process
cannot migrate away from a busy core, because migration is the thing the
budget gave up.

Three consequences now written down: a narrower budget is *more* volatile on
a shared host, not less; budgeted processes collide deterministically on the
same low-numbered cores rather than spreading; and low-budget cells in any
matrix measured across sessions carry co-tenant load as signal. Measured
within one session, 4->8 is 1.57x — sublinear and unremarkable.

The original table is kept as measured rather than silently corrected, since
how the number dissolved is the part worth having.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@justinchuby

Copy link
Copy Markdown
Owner Author

Pushed a correction to my own numbers, before this merges rather than after.

The 4→8 budget scaling stall reported in §41.6 does not reproduce, and I have retracted it.

Re-measuring budget 4 with the identical binary and flags:

session p50 samples (ms)
A 1.858, 1.847, 1.861, 1.871
B 2.766, 2.761, 2.756, 3.992

Four samples inside 1% within a session — tighter than the null control band — and 1.48x apart across sessions. Notably the steady-state detector does not save you here: each reading is genuinely steady, they are just steady at different values.

The cause is the budget's own affinity confinement. select_budget_cpus is deterministic — budget 4 always confines to CPUs [0, 2, 4, 6] — and sampling /proc/stat during the slow session showed those exact cores 22-34% busy with co-tenant work at load average 8-21. A budgeted process cannot migrate away from a busy core, because migration is precisely what the budget gave up.

So the original comparison put a quiet-session budget-4 reading against a busy-session budget-8 reading and read the difference as parallel-decomposition behaviour. Measured within one session, 4→8 is 1.57x — sublinear, unremarkable, not a stall.

Three things now written down in a new §41.7 that were not before:

  1. A narrower budget is more volatile on a shared host, not less — the opposite of the natural intuition. Budget 4 gives up 28 of 32 logical CPUs and keeps 4 it must share, having removed the scheduler's usual remedy. Budget 16 spans more cores and moved only 0.910 → 0.889 between the same two sessions.
  2. Budgeted processes collide deterministically. Every one picks the same low-numbered physical cores rather than spreading. Correct and intended single-tenant; close to worst-case multi-tenant — and this campaign's own benchmark host is multi-tenant.
  3. Budget sweeps are only interpretable if every cell is measured in one session, interleaved. Across sessions you are comparing co-tenant weather.

I also tried to isolate it by pinning to apparently-idle CPUs (taskset -c 11,17,20,31) and got worse results — 1.866 then 3.296 — because 11, 17 and 31 are SMT siblings of busy physical cores 10, 16 and 30. Picking logical CPUs without regard to SMT pairing hands you cores you do not own, which is the lesson #1232 already encoded in select_budget_cpus and which I re-learned by hand.

I have kept the original table exactly as measured rather than quietly editing the numbers, because how the figure dissolved is more useful than the figure would have been.

This does not affect the harness itself, the park-threshold result, the thread census, or the concurrency finding — the concurrency matrix was measured at a single budget within one session, which is the shape §41.7 now says is required.

… misreading

The claimed '111 of 915 dispatches declined' was never a number
`nested_dispatch_slot_pressure` could produce — it issues ~25-30 dispatches
in total. Re-measured over four runs it declines 0, 1, 2 and 6 of ~25-30,
always in the 16-dispatcher row and never below it, which brackets #1377's
zero rather than contradicting it.

The count tracks host load for the same reason §41.7 gives: when co-tenants
hold cores, workers free their slots later and more nested dispatches take
the inline fallback. That fallback is the designed behaviour.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@justinchuby

Copy link
Copy Markdown
Owner Author

Second correction, same session, same reason — I kept measuring and the number did not survive.

Retracted: the claimed nested-dispatch regression ("111 of 915 dispatches declined at 16 dispatchers, where #1377 measured zero").

That was a misreading on my part. nested_dispatch_slot_pressure issues roughly 25-30 dispatches in total, so 915 was never a figure it could produce. The full output makes the shape obvious:

 dispatchers        wall    dispatches    declined     inline
           1    1866.5us             1           0          0
           2     210.3us             2           0         13
           4     442.5us             4           0         16
           8     797.3us             8           0         74
          16    1577.9us            14           2        104
totals: 2 of 29 dispatches declined for want of a slot

Re-measured over four runs it declines 0, 1, 2 and 6 of ~25-30, with every decline in the 16-dispatcher row and none below it. #1377's zero sits inside that range rather than being contradicted by it.

The variation has the same cause as the budget-4 swing in §41.7: when co-tenants hold cores, workers free their slots later, so more nested dispatches take the inline fallback. That fallback is the designed behaviour — this is the mechanism working, not a regression.

Worth naming the common thread in both retractions, because it is the real lesson of this phase. The harness I built here fixed within-run honesty — steady-state detection, real park/wake counters, thread attribution — and it did that well enough that individual readings are now tight to within 1%. It does nothing about across-run honesty on a shared host, and the tightness is actively misleading there: four samples inside 1% look authoritative right up until the next session produces four different samples inside 1%.

Both of the claims I retracted today were of that shape. Neither would have been caught by a better detector. They were caught by re-measuring something I had already written down.

Ledger and PR description updated. The findings that stand — the 200-500us park threshold (independently confirmed by the micro-benchmark), the thread census resolving the ~2x-budget question, zero ORT threads, and the concurrency p90 collapse — were all measured within a single session at a single budget, which is the shape §41.7 now says is required.

… it doesn't matter

worker_loop has two doubling sites and one halving site. After any park the
sequence is halve (500->250us), futex wake returns because work arrived,
drain, `ran > 0`, double (250->500us). Net zero. The halving can never win,
so the window sits at MAX_SPIN in any workload that does work — which is what
saturates idle CPU at ~16 x MAX_SPIN in §41.4.

Removing the `ran > 0` doubling should let a large-gap workload converge to
MIN_SPIN. Measured interleaved in one session it does not: 5% slower at a
100us gap, 7% faster at 2ms, both inside the null band, and CPU moves 3%
where the model predicted 44%. parks/iter is ~17 in both arms, so the workers
park either way; the spin loop exits early on the epoch check far more often
than it runs to the window's end.

Not shipped. Recorded so nobody tunes MIN_SPIN/MAX_SPIN expecting the
adaptation to respond, with the measurement bounding what fixing it is worth.

Also records where idle CPU actually is: the task runtime burns 12x the
decode SPMD pool, and the prefill Rayon pool is 1.5% of the total.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@justinchuby

Copy link
Copy Markdown
Owner Author

Item 2 outcome: a real defect found, a fix built and measured, and not shipped. Recorded in a new §41.11.

The adaptive spin window is structurally pinned at MAX_SPIN. worker_loop has two doubling sites and one halving site:

  • ran > 0 after a drain doubles it (~line 367)
  • a spin hit doubles it (~397)
  • a park halves it (~408)

The sequence after any park is: halve (500 → 250us), then the futex wake returns because work arrived, the worker drains it, ran > 0, double (250 → 500us). Net zero, every time. In any workload that does work at all the window never leaves MAX_SPIN. The comment at the halving site — "shrink it so a mostly-idle process converges on parking rather than on burning a core" — describes an intent that the very next statement undoes. It also explains why §41.4's idle CPU saturates at ~6.5 CPU-ms ≈ 16 workers × MAX_SPIN.

Running work is not evidence a spin window was well-sized; only a spin hit is. So the ran > 0 doubling is the wrong one, and removing it should let a large-gap workload converge to MIN_SPIN in five iterations.

It does not. Two binaries interleaved in one session (the rule I just wrote in §41.7), sleep gaps, budget 16:

gap arm p50 (ms) cpu/wall parks/iter
100us base 0.844 / 0.846 12.61 / 12.84 4.16 / 2.04
100us fix 0.877 / 0.899 12.91 / 12.68 3.41 / 7.19
2000us base 0.974 / 1.050 5.78 / 5.45 16.92 / 19.04
2000us fix 0.942 / 0.911 5.60 / 5.06 17.16 / 19.11

5% slower at 100us, 7% faster at 2ms, both inside the 0.81-1.24 null band, and CPU moved ~3% where I predicted ~44%.

The prediction failed for a checkable reason, which is the part worth keeping: parks/iter is ~17 in both arms at a 2ms gap. The workers park either way. The window only governs how long they spin first, and that is empirically worth ~0.4 CPU-ms per iteration rather than the ~8ms that 16 × MAX_SPIN implies — the spin loop exits early on the epoch check far more often than it runs to the window's end.

So: defect real, inference from it wrong, change reverted. I would rather log a bounded negative result than ship a scheduling change whose entire effect is inside the noise band.

The attempt did establish where idle CPU actually lives, from the per-thread census at a 2ms gap:

pool threads total CPU over the run
task runtime (nxrt-task-*) 15 ~3.45 s
decode SPMD (onnx-genai-deco) 16 0.28 s
prefill Rayon (nxgn-prefill-*) + main 17 0.05 s

The task runtime is 12x the decode pool. Future idle-CPU work belongs there — and the prefill pool, the one that looked alarming in §41.5 for being 16 wide and anonymous, is 1.5% of the total. Worth naming (#1398), not worth making lazy.

@justinchuby

Copy link
Copy Markdown
Owner Author

Phase 22 (measurement only): where the single-session CPU actually goes

Single-session utilisation at budget 16 is ~9.2–9.9 CPU-s per wall-s out of 16.
This run attributes that number by phase and thread. Host: AMD EPYC 9V74,
1 socket, 1 NUMA node, 16 physical cores (32 SMT), two L3 domains (CPUs 0–15
and 16–31, 32 MiB each). Model gemm_nbits_llama3_8b_mlp_t1.onnx, 35 MB of int4
weights, gap 100 µs, 400 iters, --native-threads 16, pure native, no fallback.

0. Retraction first

In the previous update I reported that forcing the flat fan-out onto Rayon was
~1.46x faster than the task runtime at budget 16 (3 of 4 reps). That result
was wrong and I am withdrawing it.
It was host weather, not routing.

The A/A null control (identical binaries, separate processes, interleaved) sizes
the band at 0.85–1.07x on p50 and 9.48–10.11 on cpu-per-wall. Re-running
the A/B with alternating arm order and discarding reps where the host collapsed
(cpu/wall fell to 2–4, load average 7.6–10.3):

rep order task runtime p50 forced Rayon p50 ratio
1 RT first 1.820 ms 1.900 ms RT 1.04x
2 RAY first 1.756 ms 1.905 ms RT 1.08x
3 RT first 1.756 ms 1.949 ms RT 1.11x
8 RAY first 2.125 ms 1.984 ms RAY 1.07x

Every clean rep is inside the null band. Routing is latency-neutral for this
shape. The original 1.46x came from a run where the second arm happened to land
in a quiet window. The only reason this was caught is the null control — the same
control discipline that the "avoid tuning to a paired-ORT artifact" instruction
exists to enforce. Treat the earlier number as retracted.

1. Routing is neutral on latency but not on cost

Same workload, two binaries differing only in MIN_ROUTED_FAN_OUT_WIDTH (16 vs 17):

arm decode-Rayon CPU nxrt-task CPU total CPU p50 vol / invol ctxsw per iter
task runtime 800 ms 6830 ms 7.84 s 2.055 ms 19.1 / 0.5
forced Rayon 8080 ms 0.0 ms 8.27 s 1.979 ms 47.7 / 43.3

Two things worth keeping:

  • An idle task-runtime pool costs exactly 0.0 ms of CPU. All 15 workers park
    and stay parked. There is no idle-spin leak in the task runtime, which rules
    out the "unused pool burns CPU" hypothesis I had been carrying.
  • The task runtime does the same work for 5% less CPU and 87x fewer
    involuntary context switches
    . #1363's routing is defensible on cost even
    though it does not move p50.

2. Thread inventory: 47 workers for a 16-core budget

--census-phases attributes every thread to the phase that created it:

phase created identity
native-session-load +16 unnamed global Rayon pool (build_global)
timed-session-warm +16 onnx-genai-decode-* pinned decode pool (build_decode_pool, matmul_nbits.rs:3999)
timed-session-warm +15 nxrt-task-* task runtime (+ dispatcher = 16 lanes)

That is three pools, each sized to the budget — 47 worker threads on 16 cores,
which is the ~2x-budget unnamed-thread question from an earlier phase, now closed.
The 16 unnamed threads are the global Rayon pool; Rayon does not name
build_global workers, so they inherit the process name. #1398 names them
nxgn-prefill-*, which makes this visible in any future census.

ONNX_GENAI_PROFILE_OPS=1 shows one MatMulNBits per iteration at 99.95% of
the forward pass
, and the counters show 1.01 dispatches/iter. So the task
runtime performs 100% of the model work, and the decode pool's 800 ms is
not model work: 15 of its 16 workers block as a pass-through layer while one
becomes the dispatcher.

3. Utilisation decomposition at budget 16

Of the 16 CPUs available (9.15 cpu-s per wall-s observed):

component cpu/wall share of the 16
nxrt-task workers (useful) 7.99 50%
decode-pool pass-through (idle) 0.94 6%
global Rayon + main (idle) 0.21 1%
unused 6.86 43%

Per-iteration: each task worker is busy ~1.14 ms of a 2.055 ms iteration — a
56% duty cycle. The rest is fork-join, not model work: 15.1 parks/iter
(every worker parks every iteration), and 99.7% of dispatches wait on a
straggler
with 5.75 yields/iter. Per-worker CPU spreads 430–500 ms, so the
slowest worker does ~16% more than the fastest.

So the headline "9.4 of 16" is really 8.0 useful + 1.15 overhead + 6.9 idle,
and the dominant single loss is the fork-join straggler tail, not park cost.

4. Hypotheses tested and rejected

  • L3/CCD locality. The 8→16 wall (b=8 p50 2.10 ms vs b=16 2.05 ms — doubling
    cores buys ~2%) looked like it might be the CCD boundary, since budget 8 lands
    entirely inside L3 domain 0 while budget 16 spans both, and the weights (35 MB)
    exceed one 32 MiB L3. Tested directly at equal core count: 8 cores inside one
    L3 (0,2,4,6,8,10,12,14) vs 8 cores split across both
    (0,2,4,6,16,18,20,22), ONNX_GENAI_CPU_DECODE_AFFINITY=off + taskset.
    Clean reps were identical (3.657 vs 3.619; 2.219 vs 2.191). Rejected.
  • Idle pool spin in the task runtime. Rejected — 0.0 ms, see above.
  • Raw DRAM bandwidth. 35 MB per 2.05 ms is only ~17 GB/s, ~1.07 GB/s per
    core, well under what a single core can pull. Not obviously saturated, but see
    the caveat below.

5. What is still open

The single MatMulNBits GEMV does not scale past ~8 workers, and I have not yet
proven why. The straggler tail (99.7% of dispatches) and the 56% duty cycle are
the leading candidates, ahead of memory bandwidth. The next step is finer or
dynamic partitioning of the output rows to cut the tail, measured with the
straggler counters from #1411.

Caveat on every number here: the host is shared and was under load average
7.6–10.3 for this session, with several reps collapsing to 2–4 cpu/wall. All
comparisons are interleaved, alternate arm order, and are reported against a
measured null band; single-rep differences inside 0.85–1.07x mean nothing. The
b=8 vs b=16 comparison in particular deserves a re-run on a quiet host before
anything is built on it.

No code change in this phase — measurement only.

@justinchuby

justinchuby commented Aug 19, 2026 •

Copy link
Copy Markdown
Owner Author

Caution

RETRACTED — 2026-08-19. The central claim below, that SMT siblings give a 1.26x single-session p50 win, is wrong, and so is the "9.4 of 16" baseline it is built on. Both were measured on a loaded host.

Re-measured on a genuinely quiet host (load average 1.21), interleaved with alternating arm order:

arm p50 cpu/wall
physical-core (budget 16) 1.177 ms 12.3-12.6
SMT (32 lanes, affinity off) 1.219 ms 22.0-23.2

SMT is 1.03x slower, at 1.8x the CPU. The original 1.26x was an artifact of co-tenancy: when other jobs already occupy the sibling lanes, physical-core confinement buys you nothing (the sibling steals the core regardless), so taking all 32 CPUs simply captured more of a contended machine. That is a property of the host that day, not of the scheduler.

The "9.4 of 16" utilization figure is likewise the contended state. A quiet host reaches 12.3-12.8.

No SMT policy should be implemented on the basis of this comment. See the phase-24 comment below for the replacement analysis, which also explains the bistable fast/slow regime that made these numbers unstable in the first place.

Original text preserved unedited below for the record.


Phase 22b: the single-session "9.4 of 16" is memory latency, not the scheduler

Follow-up to the phase-22 attribution above. This resolves why one session cannot
fill the 16-core budget. Same host and model as before (EPYC 9V74, 16 physical
cores, gemm_nbits_llama3_8b_mlp_t1.onnx, 35 MB int4 weights, gap 100 µs, pure
native, no fallback/MLAS).

1. The fan-out itself scales almost perfectly to width 8

ONNX_GENAI_CPU_TASK_THREADS sets the task-runtime width independently of the
decode budget, so the budget (affinity, pool sizes, routing) can be held at 16
while only the fan-out width moves. Routing stays on the task runtime at every
width (calls=1, so the hot-fan-out branch is not taken). One clean session:

task width p50 speedup implied GB/s
1 16.175 ms 1.00x 2.2
2 8.132 ms 1.99x 4.3
4 4.133 ms 3.91x 8.5
8 2.132 ms 7.59x 16.4
16 1.945 ms 8.32x 18.0

Fitting wall = S + P/N on widths 1 and 2 gives S = 0.089 ms — a 0.55% serial
fraction
— and that fit then predicts the measured points: w=4 → 4.110
(measured 4.133), w=8 → 2.100 (measured 2.132). At w=16 it predicts 1.094 but
measures 1.945.

So scaling is 95% efficient through width 8 and collapses to 52% at 16.
Serial preprocessing/postprocessing, dependency barriers and task grain are all
excluded as the cause: a 0.55% serial fraction cannot produce this.

2. It is not a bandwidth ceiling

Per-lane throughput is a flat ~2.05 GB/s (8.5/4, 16.4/8), and the total pins near
18 GB/s, which looks like a bandwidth wall. It is not — running two concurrent
sessions breaks straight through it
:

config total lanes throughput cpu/wall GB/s
1 session x w8 8 469/s ~7.0 16.4
1 session x w16 16 518/s 9.64 18.1
2 sessions x w8 16 544/s 9.03 19.0
2 sessions x w16 32 750/s 14.55 26.3

26.3 GB/s comfortably exceeds the apparent 18 GB/s "ceiling", and utilisation
reaches 91% of the 16-core budget. A bandwidth-saturated workload cannot do
that. Note also that 2x w8 (16 lanes) is no better than 1x w16 (16 lanes) — what
buys throughput is more lanes than cores, not how they are grouped.

3. The mechanism is memory-latency stalls, and SMT recovers them

An M=1 GEMV streams 35 MB of int4 weights with almost no arithmetic per byte, so
each lane spends most of its time waiting on global loads — the same
latency-bound/Long-Scoreboard regime the profiling skill describes for decode
GEMVs. A lane leaves its core stalled roughly 44% of the time (measured directly
in the census above: workers are busy 1.14 ms of a 2.055 ms iteration, a 56% duty
cycle). Only a second runnable thread per core recovers those cycles.

Allowing the 16 SMT siblings confirms it. Four interleaved reps, alternating arm
order, single session:

rep budget16/width16 budget32/width32 ratio
1 2.726 ms (8.94 cpu/wall) 1.959 ms (15.10) 1.39x
2 1.940 ms (9.33) 1.627 ms (16.93) 1.19x
3 1.977 ms (9.57) 1.529 ms (18.25) 1.29x
4 1.882 ms (10.21) 1.540 ms (18.03) 1.22x

Median 1.26x, and every rep is outside the measured null band (0.85–1.07x) in
the same direction, holding even at load average 12. Intermediate widths move
monotonically (b16/w24 → 1.93 ms, b16/w32 → 1.73 ms), so this is oversubscription
recovering stall cycles, not a threshold artifact.

This is exactly what resolve_width() already says in its own comment —
"latency-bound work likes siblings, issue-bound work does not" — but the decode
budget's physical-core affinity confines the process to 16 CPUs, so the task
runtime can never reach a sibling no matter what width is asked for.

4. What this rules out

Everything I had been chasing:

  • Routing (task runtime vs Rayon) — inside the null band; retracted above.
  • Idle-pool spin — an idle task-runtime pool costs 0.0 ms.
  • Park/wake latency — p50 is flat (1.77–2.09 ms) across gaps of 0 to 4000 µs
    while parks go 11.5 → 17.8 and spin-hits go ~5 → 0.
  • Spin-window tuning — the adaptive window converges to ~2xMIN_SPIN (~40 µs)
    because it doubles on work and halves on a failed spin, so spin is only ~3.5%
    of task CPU. Cutting it saves little and cannot touch p50.
  • Serial pre/post and task grain — 0.55% serial fraction.
  • L3/CCD locality — 8 cores inside one L3 vs split across both were identical.

The 9.4-of-16 figure is therefore close to the honest ceiling for a single
latency-bound decode GEMV on a physical-core budget, not a scheduler defect.

The machine reaches 91% utilisation and 26 GB/s — but only with concurrent
sessions, which is a serving-shape property, not something the scheduler can
manufacture for one stream.

5. Consequence, and what I am not doing yet

There is a real trade here, and it is shape-dependent:

  • For latency, one session wants siblings: 1.26x on p50, at ~1.8x the CPU
    (9.6 → 18.0 cpu/wall). Efficiency-negative, latency-positive.
  • For throughput per CPU, the physical-core budget with concurrent sessions
    wins outright: 750/s at 14.55 cpu/wall (51.5 iter/s per CPU) versus 662/s at
    18.7 (35 iter/s per CPU).

That means the right answer is a shape-aware budget policy, not a blanket
change — and it directly touches the physical-core affinity semantics from #1232
and the budget/SMT warning in #1384. I am not opening that change on this
evidence alone: the host has been at load average 7–12 all session, several reps
collapsed outright, and a policy that regresses issue-bound prefill to help
latency-bound decode would be a bad trade. It needs a quiet host and a prefill
control arm before it becomes a PR.

Residual overheads worth fixing independently, from the attribution above: three
pools totalling 47 worker threads for a 16-core budget, and the decode pool
burning 800 ms as a pure pass-through while the task runtime does 100% of the
model work.

Measurement only — no code change in this phase.

@justinchuby

Copy link
Copy Markdown
Owner Author

Phase 23 — global Rayon ownership audit (mandate item 2), and a correction

The mandate asked me to stop the global Rayon pool being "eagerly constructed from probes/metadata" and to quantify which calls trigger it. I did the attribution. The premise turns out to be wrong, and I want that on the record before anyone acts on it.

Who actually builds it

I named the global pool's workers (nxgn-prefill-*, from #1398), combined that with the lazy-decode-pool change (#1434), and captured a one-shot backtrace at the first width probe.

The first construction is genuine first use, not a probe:

onnx_runtime_ep_cpu::provider::CpuExecutionProvider::copy_from_host
onnx_runtime_session::executor::state::Executor::build_with_cuda_requirement
onnx_runtime_session::executor::state::Executor::build
onnx_runtime_session::InferenceSession::from_parts

copy_host_bytes does the weight upload with par_chunks_mut once the copy is over host_copy_parallel_min_bytes(). That is real parallel work on the global pool at session load. The codebase is already careful here — copy_host_bytes deliberately checks size before calling host_copy_workers(), with a comment saying exactly why — so the small-copy path is already probe-free. There is no metadata/probe path constructing it that I can find.

I also tested the "probe builds it" hypothesis directly by making the fan-out width query non-constructing. Thread count did not move (54 both ways). The hypothesis is falsified.

Is it dead weight?

Per workload, at a 16-core budget, nxgn-prefill-* CPU:

workload global Rayon task runtime
GEMM decode t=1 16 thr, 0.0 ms 4960 ms
RoPE t=1 16 thr, 0.0 ms 0.0 ms
KV-cat p=2047 16 thr, 0.0 ms 0.0 ms
MoE t=512 (prefill) 16 thr, 177,160 ms 0.0 ms

So it is idle in decode and is the entire prefill workhorse. Deleting it or making its bounding lazy would be a serious prefill regression. It is also load-bearing in a subtler way: build_global() fails if the pool already exists, so the explicit-budget bounding must run before first use — which is why it sits in EpFactory::initialize(). That eager call is a no-op unless a budget is set, which I confirmed: with no budget, nxgn-prefill is 0 threads.

The real remaining thread-count item

At default (no explicit budget), a decode-only process carries 54 threads, and RAYON_NUM_THREADS bisects them:

RAYON_NUM_THREADS threads
unset 54
4 26
1 23

So 31 of the 54 are the global pool, spawned at one-worker-per-logical-CPU because that is Rayon's default — even though host_copy_workers() clamps the only thing that uses it at load to 8. We build 32 workers to run an 8-way memcpy, and in a decode-only process they then do nothing forever.

What I am not doing

The obvious fix is to give the default path the same bounded, named global pool the explicit-budget path gets (physical-core width), which would take default 54 → 38 and hand us nxgn-prefill-* attribution for free. I am not opening that PR on this evidence, because it changes process-wide prefill parallelism from 32 to 16 by default, and I have no prefill A/B on a quiet host to show that is free. That is a policy change and the standing rule is no policy claim until controlled. Logging it as a proposal.

Where the target stands

Target was "fewer than 47 workers for a 16-core budget without throughput regression". #1434 delivers 47 → 31 by removing the decode pool, with latency neutral inside the A/A null band and total CPU down ~2%. The remaining 16 are the prefill pool, and the evidence above says they should stay.

@justinchuby

Copy link
Copy Markdown
Owner Author

Phase 24 — the unexplained ~1.7x drift is exact-fit barrier fragility, and two of my earlier claims were wrong

The host went genuinely quiet for the first time this campaign (load average 1.21). That immediately falsified two things I had claimed, and then explained the drift we have been chasing since phase 18.

Correction 1: the "quiet band" was never quiet

I had been treating cpu_per_wall ≈ 9.5–10.1 as the quiet-host signature and rejecting anything outside it. On an actually-quiet host the same binary reports 12.3–12.8. So the "single-session utilization is 9.4 of 16" headline — which I have quoted for several phases and which motivated a lot of this lane — is the contended state, not a property of the scheduler. Real quiet-host utilization is ~12.5/16.

Correction 2: the SMT win does not exist

Phase 22b claimed SMT siblings cut single-session decode p50 by a median 1.26x. Re-run interleaved with alternating order on the quiet host:

arm p50 cpu/wall
physical-core (budget 16) 1.177 ms 12.3–12.6
SMT (32 lanes, affinity off) 1.219 ms 22.0–23.2

SMT is 1.03x slower at 1.8x the CPU. The earlier 1.26x was an artifact of measuring on a loaded host: when co-tenants occupy the siblings, physical-core confinement does not protect you (the sibling steals the core anyway), so grabbing all 32 CPUs simply captured more machine. I withdraw the SMT proposal for mandate item 3. The existing physical-core default is correct, and I am not opening the workload-class SMT experiment — the evidence says there is nothing to win.

The actual mechanism: the barrier is an exact fit with zero slack

Identical runs, same binary, same flags, are bimodal: p50 either ~1.17 ms (cpu/wall ~12.5) or ~1.85 ms (cpu/wall ~9.6). A 1.58x spread between runs of the same binary — this is the "unexplained ~1.7x drift".

It is not noise, and it is stable within a run. It correlates cleanly with one counter, straggler_yields/iter (#1411):

regime p50 straggler yields/iter
fast 1.17–1.18 0.28 – 1.51
slow 1.80–1.99 2.45 – 7.59

straggler_waits stays pinned at ~1.0 in both — every dispatch waits, as any fork-join does. It is the yields that explode, i.e. one lane is consistently late.

Why: at a 16-core budget the task runtime runs 15 worker threads plus the calling thread = exactly 16 runnable lanes on exactly 16 budget CPUs. There is no spare lane. mpstat during a slow window showed a co-tenant at 100% on CPU 11 (the SMT sibling of budget CPU 10) in one case and at 50% on budget CPU 14 in another. Either way a single contended lane halves, and an equal-chunk barrier makes the slowest lane set the pace for all 16.

The width sweep confirms it

Same conditions, interleaved:

task width rep1 rep2 rep3 median behaviour
16 (= budget) 1.819 1.171 1.862 1.819 bistable: produces both the best and the worst result
15 1.243 1.290 1.622 1.290 mostly stable
14 1.319 1.316 1.380 1.319 deterministic, never bad
12 1.508 1.519 1.505 1.505 stable but under-parallel

Width 14 gives up 13% against width 16's best case and beats its median by 1.38x, with a much tighter p90. Two spare lanes absorb the caller and any co-tenant, and the bistability disappears entirely.

What I am proposing, and what I am not doing

The finding argues the default task-runtime width should leave headroom below the CPU budget rather than matching it exactly. But that is a change to default budget/width policy, it touches the semantics in #1232/#1384, and the honest trade depends on whether the deployment is exclusive: on a dedicated machine width==budget is genuinely the fastest configuration.

Standing rule is no policy claim until controlled, and one intermittently-quiet shared host is not a controlled environment for a default-policy change. So I am logging this as a proposal with its evidence, not opening the PR. What it does justify immediately is cheap and safe: straggler_yields/iter (#1411) is a reliable online detector for this state, and any future measurement in this campaign should report it and reject reps where it exceeds ~2.

This also retroactively explains a lot of the campaign's rep-to-rep variance, and it means several earlier phase numbers were measured in the slow regime without knowing it.

…arness

# Conflicts:
#	docs/benchmarks/2026-08-15-cpu-ep-vs-ort-attention-moe.md
@justinchuby

Copy link
Copy Markdown
Owner Author

Phase 25 — the width-headroom proposal, put under deterministic control. Verdict: no PR.

Phase 24 ended with a width sweep suggesting that a barrier exactly as wide as the CPU budget is fragile, and that leaving one or two lanes of headroom removes a ~1.6x bistability. That was measured against ambient co-tenancy, which is not an experiment. This is the controlled version, and it does not support opening a PR.

Design

The confound in phase 24 was that contention was whatever the host happened to be doing. So:

  • Budget fixed at 16 CPUs for every cell (--native-threads 16), so the CPU set and the affinity mask are identical across arms. Only ONNX_GENAI_CPU_TASK_THREADS varies, which moves the barrier width independently of the budget. Verified: 32 threads at width 16, 30 at width 14, same 16-CPU confinement.
  • Contention is deliberate, not ambient: a busy loop pinned with taskset to CPU 14, a budget lane. Self-terminating, so the arm boundaries are exact.
  • Every rep runs all four widths in both conditions, alternating order between reps, and includes an A/A null control — the same cell twice — to size the band at that moment.
  • 10 reps, 1500 iterations each, decode shape (qwen3_0p6b_qkv_t1).

Script is at width_experiment.sh in my scratch tree; it is deterministic and re-runnable by anyone with the harness.

The null control rejected 3 of 10 reps

Null A/A ratios: 1.072, 1.009, 1.034, 1.177, 1.472, 1.062, 1.274, 1.131, 1.012, 1.071. Reps 4, 5 and 7 are discarded — at a null of 1.47 nothing smaller than 1.5x is observable. Host load ran 11 to 21 throughout, driven by other agents' sweeps.

Result on the seven surviving reps

width spinner OFF spinner ON
16 0.2399 0.2847
15 0.2474 0.2777
14 0.2581 0.2558
12 0.2184 0.2371

With the deliberate spinner, p50 is monotonic in width — every lane of headroom helps, 1.20x from 16 to 12. That is the predicted signature and it is the first time the effect has appeared under a controlled cause rather than ambient noise.

Without the spinner there is no ordering at all (width 12 fastest, width 14 slowest). The reason is not that the prediction failed but that "spinner off" is not "uncontended" on this host: at load 11-21 the ambient arm is contended too, just non-deterministically. The uncontended arm the comparison actually needs was never available.

I also falsified my own mechanism

A single run early in this phase looked like a clean structural explanation — at width 16 workers almost always parked (15.41 parks/iter, 1.07 spin-hits), while at width 14 they stayed spinning and caught the next dispatch (6.27 parks, 9.23 spin-hits). That would have been a satisfying story: the caller competes with a worker for the last CPU, so workers get descheduled and must take the expensive park/wake path.

Aggregated over all 10 reps it does not survive:

width parks/iter spin-hits/iter park share
16 14.39 1.56 90%
15 14.11 0.01 100%
14 13.31 0.06 100%
12 11.34 0.00 100%

Parks simply scale with worker count and spin-hits are ~0 at every width. The 9.23 spin-hits figure was itself a regime artifact — the same bistability this phase set out to explain, showing up inside my evidence for explaining it. The spin/park mechanism is withdrawn. I have a reproducible effect under controlled contention and no confirmed mechanism for it.

Verdict

Per the standing rule — no policy without control, and no PR unless a runtime-detectable policy beats both the contended and the quiet case without regressing budget semantics — this does not qualify, on three independent counts:

  1. The quiet dedicated-host arm is unobtainable here, so the tradeoff cannot be quantified. A narrower default would be a real cost on an exclusive machine, which is a legitimate deployment.
  2. The mechanism is unknown, so any policy would be curve-fitting to one host's contention pattern.
  3. The effect (1.11x at width 14, 1.20x at width 12) is only just outside the per-rep null band, on a host where the band reached 1.47.

It stays an experiment. What it does establish, and what I would defend: the effect is real and has a controllable cause — a deterministic spinner on one budget lane reproduces it monotonically, which ambient noise never did cleanly. If a dedicated host becomes available, the missing arm is one script invocation away.

…arness

# Conflicts:
#	docs/benchmarks/2026-08-15-cpu-ep-vs-ort-attention-moe.md
justinchuby added a commit that referenced this pull request Aug 19, 2026
…e it (#1407)

## The UB

`nested_dispatch_slot_pressure` (which I added in #1377) reconstructs a
`&mut [u64]` over the **entire** row in every task and only then
narrows:

```rust
let row = unsafe { std::slice::from_raw_parts_mut(base as *mut u64, NEST_INNER) };
for slot in &mut row[start..end] { *slot += 1; }
```

The *stores* are disjoint. The *retags* are not. Under Stacked Borrows
the violation is the retag: each task pushes a `Unique` covering all of
`NEST_INNER`, popping the previous task's tag. Narrowing before the
retag fixes it, and is the shape `parallel_output_rows_repeated` already
uses in production.

**Diagnosis and fix are Pris's, from #1385.** This PR carries them
because that one is still a draft with auto-merge off and the UB is on
`main` today. If #1385 goes ready first, close this and I will rebase
the Miri half onto it — the two halves are independent.

## Why it survived, which is the part worth keeping

CI's Miri lane runs `-p onnx-runtime-ep-cpu --lib task_runtime::`.
**Integration tests under `tests/` are never Miri-checked at all.**
Fixing this one instance would have left that gap open for the next one,
so this also puts the shape under the lane as a lib test.

That was not sufficient either, and the first attempt is the useful
part: **the new test passed under Miri with the bad retag still in it.**

Miri reports `available_parallelism() == 1`, so `resolve_width` builds a
one-lane pool, every fan-out returns `Backend::Serial`, and no two tasks
ever run against each other. Probe under Miri:

```
pool_width=1 backend=Serial tasks=1
```

The lane has been type-checking the unsafe blocks in this module without
exercising the concurrency they exist for. The workflow comment claims
it "runs real threads under Stacked Borrows" — it runs one.

So I would have shipped a canary that passes for a reason unrelated to
its claim, which is precisely the class Pris named in #1385. Two fixes:

1. **The test asserts it actually fanned out** (`Backend::Native`), so
it fails loudly if it ever degenerates to one task instead of passing
silently.
2. **A dedicated lane step with `-Zmiri-num-cpus=4`**, scoped to that
single test rather than all of `task_runtime::` — multi-CPU Miri
multiplies the runtime of what is already the slowest step in the lane.
The targeted step costs **18s**.

## Verified in both directions

| retag shape | `-Zmiri-num-cpus=4` | result |
| --- | --- | --- |
| whole row (**#1377 as merged**) | yes | `error: Undefined Behavior:
Data race detected between (1) retag write on thread task_runtime::t and
(2) retag write of type [u64] on thread nxrt-task-0` |
| whole row | **no** (lane default) | **passes** |
| own range (**this PR**) | yes | passes |

The middle row is the finding: without the flag the falsifier does not
falsify.

## Scope

Test-only plus one workflow step. No production change —
`for_each_chunk_mut` was always correct. 30/30 `task_runtime::` lib
tests pass natively and under Miri; the repaired benchmark still runs
(`1 of 30 dispatches declined`); fmt and clippy clean.

Includes the one-line rustfmt repair of
`onnx-runtime-ep-cuda/src/runtime.rs` that `main` is currently failing
on (same as #1393/#1395/#1398 — whichever lands first makes the rest a
no-op).

🤖 Generated with [GitHub Copilot
CLI](https://github.com/features/copilot/cli)

---------

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@github-actions

Copy link
Copy Markdown

✅ Benchmarks — No Regression

Comparison of criterion micro-benchmarks: PR head vs merge-base, measured on the same runner in the same job (base first → PR second).

ℹ️ Absolute times are informational only — they vary with runner load. The % change column is the reliable signal because both sides ran under identical conditions.

Status Scenario Base PR Change
✅ matmul/small_generic_f32_threads=8/1x256x256 33.34 µs 38.27 µs +14.8%
✅ block_quantized_moe_cached_dense/mxfp4_cached_dense_expert_repeated_call/rows=1,H=256,I=256,E=4,top_k=1 49.58 µs 56.21 µs +13.4%
✅ kv_cache/alloc_dealloc_pages 36.17 µs 40.17 µs +11.1%
✅ gather/medium_f32_threads=1-internal/32768 3.60 µs 3.86 µs +7.3%
✅ matmul/small_generic_f16_threads=8/1x256x256 27.07 µs 28.06 µs +3.7%
✅ gather/medium_bf16_threads=1-internal/32768 2.22 µs 2.27 µs +2.3%
✅ matmul/medium_generic_f16_threads=1/32x512x512 28.22 µs 28.85 µs +2.2%
✅ qwen3_sampling_processors/top_k_top_p_fast 610.01 µs 621.38 µs +1.9%
✅ block_quantized_matmul_cached_dense/mxfp4_preexpanded_dense_oncelock_like_proxy/1x1024x1024 42.78 µs 43.46 µs +1.6%
✅ matmul/large_generic_f16_threads=8/32x1024x1024 77.96 µs 79.15 µs +1.5%
✅ add/medium_f16_threads=1-internal/262144 96.69 µs 98.16 µs +1.5%
✅ qwen3_sampling_processors/top_k_top_p_full_sort_baseline 5.21 ms 5.29 ms +1.5%
✅ matmul/large_generic_bf16_threads=1/32x1024x1024 1.85 ms 1.87 ms +1.0%
✅ add/medium_bf16_threads=1-internal/262144 94.88 µs 95.61 µs +0.8%
✅ gather/small_f32_threads=1-internal/4096 615.2 ns 619.6 ns +0.7%
✅ matmul/small_generic_bf16_threads=8/1x256x256 28.82 µs 29.00 µs +0.6%
✅ reduce_mean/small_f32_threads=1-internal/4096 13.85 µs 13.93 µs +0.6%
✅ matmul/medium_generic_bf16_threads=1/32x512x512 495.96 µs 497.09 µs +0.2%
✅ grammar_masking/llguidance_compute_mask/32 68.85 µs 69.00 µs +0.2%
✅ matmul/medium_generic_f32_threads=1/32x512x512 2.13 ms 2.14 ms +0.2%
✅ logit_processing/seven_processor_chain_per_step 297.79 µs 297.69 µs -0.0%
✅ matmul/small_generic_f32_threads=1/1x256x256 34.03 µs 34.01 µs -0.1%
✅ matmul/small_generic_bf16_threads=1/1x256x256 28.45 µs 28.37 µs -0.3%
✅ add/medium_f32_threads=1-internal/262144 22.69 µs 22.61 µs -0.4%
✅ qwen3_sampling_processors/top_p_full_sort_after_top_k_baseline 3.27 ms 3.26 ms -0.5%
✅ gather/medium_f16_threads=1-internal/32768 2.23 µs 2.22 µs -0.6%
✅ block_quantized_moe_cached_dense/mxfp4_uncached_expert_dequant_each_call/rows=1,H=256,I=256,E=4,top_k=1 353.13 µs 350.22 µs -0.8%
✅ matmul/large_generic_f32_threads=1/32x1024x1024 8.72 ms 8.64 ms -0.9%
✅ reduce_mean/large_f32_threads=1-internal/262144 918.55 µs 908.85 µs -1.1%
✅ matmul/medium_generic_bf16_threads=8/32x512x512 361.69 µs 356.97 µs -1.3%
✅ add/small_bf16_threads=1-internal/1024 415.3 ns 409.8 ns -1.3%
✅ add/large_bf16_threads=1-internal/4194304 1.61 ms 1.59 ms -1.4%
✅ matmul/large_generic_f16_threads=1/32x1024x1024 76.38 µs 74.85 µs -2.0%
✅ block_quantized_matmul_cached_dense/mxfp4_uncached_dequant_each_call/1x1024x1024 554.85 µs 535.91 µs -3.4%
✅ reduce_mean/medium_f32_threads=1-internal/65536 236.37 µs 226.62 µs -4.1%
✅ matmul/large_generic_bf16_threads=8/32x1024x1024 1.34 ms 1.28 ms -4.5%
✅ matmul/large_generic_f32_threads=8/32x1024x1024 3.79 ms 3.62 ms -4.6%
✅ matmul/medium_generic_f32_threads=8/32x512x512 938.15 µs 892.12 µs -4.9%
✅ qwen3_sampling_processors/top_p_fast_after_top_k 519.75 µs 493.49 µs -5.1%
✅ gather/large_f16_threads=1-internal/131072 11.68 µs 10.98 µs -6.0%
✅ add/small_f32_threads=1-internal/1024 192.5 ns 178.8 ns -7.1%
✅ gather/small_bf16_threads=1-internal/4096 474.2 ns 438.2 ns -7.6%
✅ matmul/medium_generic_f16_threads=8/32x512x512 30.60 µs 28.13 µs -8.1%
✅ matmul/small_generic_f16_threads=1/1x256x256 30.20 µs 27.65 µs -8.4%
✅ tokenization/encode_tokens_per_second 390.07 µs 354.47 µs -9.1%
✅ qwen3_sampling_processors/top_k_partial_selection 144.03 µs 129.80 µs -9.9%
✅ gather/small_f16_threads=1-internal/4096 488.8 ns 438.9 ns -10.2%
✅ sampling_latency/min_p_per_token 231.67 µs 207.55 µs -10.4%
✅ add/large_f16_threads=1-internal/4194304 1.71 ms 1.51 ms -11.8%
✅ add/large_f32_threads=1-internal/4194304 655.35 µs 575.25 µs -12.2%
✅ tokenization/decode_tokens_per_second 6.63 ms 5.70 ms -14.1%
🟢 sampling_latency/top_k_per_token 57.46 µs 48.44 µs -15.7%
🟢 qwen3_sampling_processors/top_k_full_sort_baseline 2.34 ms 1.97 ms -15.8%
🟢 sampling_latency/top_p_per_token 422.39 µs 352.90 µs -16.5%
🟢 add/small_f16_threads=1-internal/1024 556.5 ns 460.5 ns -17.3%
🟢 block_quantized_matmul_cached_dense/mxfp4_cached_dense_repeated_call/1x1024x1024 50.89 µs 42.01 µs -17.5%
🟢 gather/large_f32_threads=1-internal/131072 28.60 µs 22.88 µs -20.0%
🟢 sampling_latency/greedy_per_token 3.78 µs 3.01 µs -20.5%
🟢 gather/large_bf16_threads=1-internal/131072 13.46 µs 10.19 µs -24.3%

Visual flags: ⚠️ ≥ 15% slower, 🔴 ≥ 30% slower — calibrated against measured runner noise (~27% worst-case on multi-threaded matmul)

Host info
CPU: Apple M1 (Virtual)
Cores: 3
OS: Darwin 25.5.0 arm64
Rust: rustc 1.97.1 (8bab26f4f 2026-07-14)
Load avg: { 3.30 3.27 4.58 }
What this cannot catch
  • Regressions in code paths not covered by these benchmarks (e.g., end-to-end decode with a real model)
  • Sub-threshold regressions that compound over multiple PRs
  • Performance changes that only manifest under GPU execution
  • Latency changes in the ORT integration path (these benchmarks exercise the native Rust kernels)

@codecov

codecov Bot commented Aug 20, 2026 •

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 81.20%. Comparing base (f66e842) to head (7cbaec1).
⚠️ Report is 43 commits behind head on main.

Additional details and impacted files

Impacted file tree graph

@@            Coverage Diff             @@
##             main    #1395      +/-   ##
==========================================
+ Coverage   80.32%   81.20%   +0.87%     
==========================================
  Files         426      429       +3     
  Lines      204769   214755    +9986     
  Branches   204769   214755    +9986     
==========================================
+ Hits       164484   174395    +9911     
+ Misses      34664    34593      -71     
- Partials     5621     5767     +146     
Flag Coverage Δ
cli-ort-linux 72.51% <ø> (?)
cli-ort-windows 72.01% <ø> (ø)
mlas 85.90% <ø> (?)
offline 81.35% <ø> (+0.80%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.
see 79 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

justinchuby added a commit that referenced this pull request Aug 22, 2026
## The problem

Rayon does not name the workers `build_global` creates, and an **unnamed
thread's `comm` defaults to the process name**. So the pool that
`bound_process_to_decode_budget` builds appears in `ps`, `top` and
`/proc/<pid>/task/*/comm` as N extra copies of the host binary.

This is not a cosmetic gap. It was the largest unattributed block of
threads in any budgeted process, and it is what kept "the process has
roughly twice the budget in threads and we don't know whose they are"
open as a question across several phases of the CPU scheduler campaign.

A flat thread census does not merely *fail* to explain these threads —
it **misattributes them to the caller**, which is worse, because the
census looks complete.

## What the naming immediately revealed

Census on `gemm_nbits_qwen3_0p6b_qkv_t8`,
`ONNX_GENAI_CPU_DECODE_THREADS=16`, decode-only:

```
== thread census (48 threads) ==
                        name   count        cpu_ms
             onnx-genai-deco      16          20.0
             bench_decode_ga       1          40.0
              nxgn-prefill-0       1           0.0
              nxgn-prefill-1       1           0.0
              ... (16 total)              all 0.0
```

Before this change the sixteen `nxgn-prefill-*` rows read as
`bench_decode_ga` — indistinguishable from the benchmark's own main
thread.

**All sixteen report 0.0 ms of CPU.** The pool is built eagerly at EP
init, is never used by a decode-only workload, and holds N threads for
the process lifetime.

That also quantifies the budget's real cost, which is larger than it
looks:

| configuration | threads | composition |
| --- | --- | --- |
| default (no budget) | 22 | 1 main + 6 decode + 15 task-runtime |
| budget 16 | 48 | 1 + **16 prefill Rayon** + 16 decode + 15
task-runtime |
| budget 32 | 80 | 1 + **32 prefill Rayon** + 32 decode + 15
task-runtime |

Setting an explicit budget of N does not size one pool to N — it sizes
the decode pool to N **and** builds a second, separate N-wide pool. Half
of that was previously anonymous.

A useful negative result falls out of the same census: **the ORT session
contributes exactly zero threads**. Whatever else is going on, our EP is
not double-provisioning against ORT.

## Why the names are short

Linux stores `comm` in 15 bytes. This crate's existing
`onnx-genai-`-prefixed convention (`decode_numa.rs`, `decode_spmd.rs`)
already exceeds that and collapses to `onnx-genai-deco` /
`onnx-genai-spmd`, losing the worker index — visible in the census
above, where all 16 decode workers fold into one row. `nxgn-prefill-15`
is exactly 15 bytes and survives intact, matching the short form the
task runtime already uses (`nxrt-task-N`).

The test asserts the *property* — fits in `comm`, keeps its prefix,
keeps its index, stays distinct — rather than the literal string, since
the string is not the thing that has to hold.

## Scope

Thread names only. No behaviour change, no sizing change, no scheduling
change. 1448/1448 `onnx-runtime-ep-cpu` lib tests pass; fmt and clippy
clean.

**Making the pool lazy is the real fix and is deliberately not attempted
here.** It would require every global-Rayon entry point in the default
build to route through a guard before first use, and missing one
silently un-bounds the user's explicit budget — a correctness regression
traded for a thread-count saving. Named as a measured cost with a known
shape (§41) so the decision is on the record rather than rediscovered.

Includes the one-line rustfmt repair of
`onnx-runtime-ep-cuda/src/runtime.rs` that main is currently failing on
(same as #1393/#1395 — whichever lands first makes the others a no-op).
Without it this branch cannot be green.

Follows #1395, which built the census that made this diagnosable.

🤖 Generated with [GitHub Copilot
CLI](https://github.com/features/copilot/cli)

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
justinchuby added a commit that referenced this pull request Aug 22, 2026
## Why

The 4-session p90 regression reproduces cleanly (~4.6x worse
per-iteration than 1 session) but `slot_exhausted = 0` throughout, so
slot capacity was not the constraint and no existing counter could say
what was. These two can.

- **`straggler_waits`** — the dispatcher finished draining its own slot
and found `remaining != 0`. This separates *"the fan-out was absorbed by
the dispatcher"* from *"the dispatcher is now blocked on someone else's
task"*.
- **`straggler_yields`** — the dispatcher burned a full
`DISPATCHER_YIELD_STRIDE` of spins on that straggler, which is only
reachable when the claimant is **descheduled**. A direct
sharing/oversubscription signal rather than an inferred one.

## What they found — and the control that reinterpreted it

Gap 100 µs, budget 16, 300 iters/session, all cells in **one session,
interleaved** (cross-session comparisons on this host measure co-tenant
weather, not the change).

My first reading was that the tail was a contention pathology. **The
control says otherwise, and I am recording that rather than shipping the
story.** If 4 sessions share a 16-CPU budget, each session's fair share
is 4 CPUs — so the honest comparison for a concurrent session is *not* 1
session at budget 16, it is **1 isolated session at budget 4**:

| shape | p50 (ms) | p90 (ms) | cpu-s per wall-s |
|---|---|---|---|
| 1 session, budget 16 | 1.803 / 1.811 | 1.984 / 1.994 | 9.4 / 9.5 |
| **1 session, budget 4** (fair share, isolated) | 4.159 / 6.721 |
**6.976 / 7.303** | 3.0 / 3.4 |
| **4 sessions, budget 16** (concurrent) | 4.510 / 4.617 | **6.418 /
6.448** | 15.5 / 15.7 |

**Concurrent is as good as or better than the isolated fair-share
control** — p90 6.42–6.45 ms vs 6.98–7.30 ms. Sharing 16 CPUs
dynamically across 4 sessions beats a static 4-CPU partition. There is
no lock, queue, wake-storm or work-stealing pathology to find here; the
per-iteration slowdown is the arithmetic of fair sharing.

The aggregate control agrees: 4 sessions concurrently finish the same
total work in **1.60–1.71 s** versus **2.78–2.88 s** for the same four
runs sequentially — concurrency is a **1.7x net win**. Per-session
latency degrades 2.6x while offered load goes up 4x, which is a
favourable trade, not a collapse.

So `straggler_yields` tracking the tail (0.04 → 3.0 per iter across the
sweep) is a *symptom of legitimate sharing*, not evidence of a defect.
The counters are still exactly what made this decidable, which is why
they are worth landing.

**The real signal in this table is the last column.** A single session
sustains only **9.4 of 16 CPU-seconds per wall-second (59%)**, while 4
sessions reach 15.5–15.7 (~97%). The loss is *single-session
under-utilisation*, not multi-session contention — and that is where I
am taking this next.

## What I tried and am not shipping

Yielding sooner — `DISPATCHER_YIELD_STRIDE` 4096 → 256, interleaved
arms, separate processes:

```
s=1 base  p50=0.8432 / 0.8486   p99=1.0030 / 1.9407
s=1 fix   p50=1.6767 / 1.4612   p99=1.9706 / 1.7566
s=4 base  p50=1.3966 / 1.4521   p99=6.4986 / 6.9379
s=4 fix   p50=1.3317 / 1.4917   p99=16.8717 / 12.7887
```

1-session p50 regresses ~1.8x and 4-session p99 gets 2–2.6x **worse**.
Under CFS a yield goes to the back of the runqueue, so yielding early
converts a short spin into a full requeue. Reverted; recorded so nobody
re-derives it.

Also note `parks_per_iter` falls from ~16.5 at 1 session to ~0.3 at 4
sessions, and voluntary context switches from ~21 to ~1. Under load,
workers essentially never park — which is why spin/park tuning has no
purchase on the concurrent shape.

## Risk

Counters only — **no scheduling change**. `straggler_waits` increments
in a branch that was already about to spin; `straggler_yields` sits
inside the existing rare stride branch. The fast path (dispatcher drains
its own slot, `remaining == 0`) is untouched.

## Validation

- `cargo fmt --all -- --check` clean; `cargo clippy -p
onnx-runtime-ep-cpu --all-targets -D warnings` clean
- `cargo test -p onnx-runtime-ep-cpu --lib` — **1448 passed, 0 failed,
17 ignored**
- New test `a_dispatcher_waiting_for_a_straggler_records_it` **verified
in both directions**: passes with the counter; with the increment
deleted it reports `0 passed; 1 failed`. It asserts an aggregate
property over repeated full-width fan-outs rather than a timing
assumption, because which thread holds the last task is genuinely the
scheduler's choice.

Harness-side plumbing (a `straggler:` report line in `bench_decode_gap`)
is left to a follow-up so #1395 stays scoped.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@justinchuby

Copy link
Copy Markdown
Owner Author

Status: moving this back to draft, and recording precisely what is and is not still true

This branch is 312 commits behind main and red on eight lanes. It has been open since 15 Aug. Rather than leave it sitting in the queue looking like a merge candidate, here is an accounting.

What has been superseded

  • The park/wake axis landed elsewhere. crates/onnx-runtime-ep-cpu/benches/decode_gap_park_ab.rs is on main and covers configurable inter-token gaps, warmup beyond pool construction, A/A null arms, and per-worker straggler attribution at EP level. That is the instrument the campaign has actually been using.
  • The bench_generic.rs → model_io.rs extraction is no longer applicable. This branch moves 520 lines out of bench_generic.rs; that file has been modified many times since, including by me (host_sib=, contention fields). Rebasing the extraction would produce a large, mostly-mechanical conflict resolution that nobody can review as a unit. If the extraction is still wanted it should be proposed fresh, on its own, against current main.

What is genuinely still unlanded

A model-level gap harness. decode_gap_park_ab is EP-level and synthetic: it drives the decode pool directly. Nothing on main runs a real session with a configurable inter-token busy/sleep gap distribution. That axis is still uncovered, and the reason it matters has not gone away — a zero-gap loop is the one workload on which parking cannot show its benefit, so tuning a blocktime default against it measures the wrong thing.

What must not be merged from here under any circumstances

docs/benchmarks/2026-08-15-cpu-ep-vs-ort-attention-moe.md — 378 lines of measured claims taken before either contention instrument existed.

That is not a formality. Since these numbers were taken:

Everything in that document was measured in the regime that produced the 13.8% self-difference. Three of its conclusions were already retracted in-branch (cb62fe0f8, 6d56b7353, f3c2a6a23), which is the pattern rather than the exception. None of it should re-enter the docs tree without being re-taken with foreign_% and sib_% screening and an in-run A/A null. I would rather these numbers stay in a draft PR than be findable in docs/.

Disposition

Back to draft. Not closing it: the harness design and its interface notes are the starting point for the model-level gap work, which I still own. When that lands it will be a fresh PR against current main, carrying the harness and no pre-instrument numbers.

@justinchuby
justinchuby marked this pull request as draft August 23, 2026 22:18
auto-merge was automatically disabled August 23, 2026 22:18

Pull request was converted to draft

justinchuby added a commit that referenced this pull request Aug 23, 2026
…te the idle (#1887)

## What this answers

[#1871](#1871) established
that the acc0 gap is ~1.78x at width 16 versus 1.12x at width 8, and
left the mechanism open: **when the `t=8 → t=16` doubling returns 1.32x
instead of 2x, are the extra workers idle, or busy and inefficient?**
Wall-clock timing cannot separate those. This adds CPU-seconds
attribution to both arms and answers it.

## The instrument

`process_cpu_time()` in `benches/common` reads `/proc/self/stat`
(thread-group user/sys ticks); `ort_matmulnbits_baseline.py` brackets
`getrusage(RUSAGE_SELF)` over the same window and emits
identically-named fields, so one parser reads both arms. Read directly
rather than through `/usr/bin/time`, whose `Percent of CPU` is
`(user+sys)/wall` — it looks like independent corroboration of a
wall-time result and is actually the same measurement divided by itself.

The decomposition is an **identity**, not a model:

```
tps(16) / tps(8)  ==  2 * R_busy / R_cpu
```

so residual is 0.00% by construction and it doubles as a free per-cell
self-test. Cells failing it are discarded as instrument faults rather
than reported.

**It earned its place before it was used in anger.** The harness's first
run returned `REPORT NOTHING (n_trusted = 1 < 6)`, which was honoured —
nothing was quoted, including the one trusted cell. Diagnosing it found
a defect in *my instrument*, not the host: each quantity was reduced by
its own independent median, and since `tps = tokens/wall` the two sort
in reversed orders, so at an even rep count they selected **different
repetitions**. Identity errors of **4.4%–29.7%** against a quantity that
is algebraically zero. Both producers now emit every CPU field from the
single median-throughput repetition. **No threshold in the
pre-registered rule was changed** — only the instrument feeding it, and
the change was forced by a self-test firing before anything was scored.

## Finding 1 — the CPU inflation is ours, not the host's

13 trusted of 14 launches, identity error 0.00% on every cell:

| arm | speedup 8→16 | `R_cpu` | `R_busy` | busy@8 | busy@16 |
sys_frac@8 | @16 |
|---|---:|---:|---:|---:|---:|---:|---:|
| native | 1.445 | **1.449** | 1.057 | 0.900 | 0.966 | 0.062 | **0.212**
|
| ORT | 1.860 | **1.074** | 0.999 | 1.000 | 0.999 | 0.000 | 0.000 |

ORT ran interleaved, same launches, same 16 cores, same minutes. If the
knee were a memory-bandwidth ceiling, ORT would hit it too. **This kills
the DRAM-plateau attribution.**

## Finding 2 — `busy` is blind to spin-wait, and the shipped wait path
spins

`decode_spmd`'s worker wait spins then `sched_yield`s for up to 500 µs
(`ONNX_GENAI_CPU_DECODE_BLOCKTIME_US`) before parking. A yielding thread
accrues CPU time exactly like a working one.

Dose-response first, because an env var that never reaches the child
produces a beautifully consistent null — w=16, 192 tokens: `sys_s` =
**0.13 / 3.28 / 3.12** at 0 / 500 / 20000 µs while `user_s` = **9.28 /
9.27 / 8.99**. Knob live, ramp saturated by 500 µs, and `user_s`
invariant — so the system time is pure overhead, not work.

Pre-registered A/B, 7 trusted of 10:

| w | ratio (bt0 ÷ bt500) | A/A null | busy@500 | busy@0 | cpu_s/tok
@500 | @0 |
|---:|---:|---:|---:|---:|---:|---:|
| 16 | **0.9960** | 0.9937 | 0.953 | **0.692** | 0.06037 | 0.04838 |
| 8 | 0.9906 | 1.0186 | 0.957 | 0.916 | 0.04078 | 0.03794 |

**Throughput: REJECT** (43% sign consistency against a 5.24% A/A
half-width). Removing the ramp does not make this workload faster, and
the favourable mechanism data does not change that. No regression at
w=8.

## What finding 2 does to finding 1

BURN-DOMINATED keys on `R_busy ≥ 0.90` — "the workers are not idle".
That quantity was masked. Same harness, same unchanged rule,
`--blocktime 0`, 9 trusted of 12, identity 0.00%:

| arm | `R_cpu` | `R_busy` | busy@8 | busy@16 |
|---|---:|---:|---:|---:|
| native | **1.304** | **0.652** | 0.938 | **0.595** |
| ORT | 1.109 | 0.999 | 1.000 | 0.999 |

**VERDICT: MIXED**, 100% sign consistency on *both* ratios.

| configuration | busy@16 | reads as |
|---|---:|---|
| default (500 µs ramp) | 0.966 | pool nearly fully occupied → BURN |
| ramp off | **0.595** | **40% of the pool is not working** |

**The correct attribution is mixed: ~30% more real CPU per token at
width 16 *and* ~40% of the sixteen cores idle.** Both halves are real,
both are ours.

A useful side-effect: over the same 9 cells the wall-derived speedup
swings **0.78x–1.37x** while `R_cpu` holds 1.10–1.34 and `R_busy`
0.52–0.81, both 100% sign-consistent. A competing process steals our
wall clock but does not add to our CPU seconds — which is the whole
reason for the instrument.

## Scope limit, stated up front

This is a **zero-gap** decode loop — exactly the workload where parking
early looks free. **Nothing here licenses changing the shipped blocktime
default**, which exists to protect latency when there *are* gaps; that
needs the gap-aware harness (#1395). What it does establish is that
**any occupancy reading of the decode pool taken at the default
blocktime over-reads by tens of points**, which is now recorded in the
ledger.

This independently corroborates, on a second workload, the
~20%-of-process-CPU figure @sebastian reported for the `worker_wait`
yield ramp — the cost side is confirmed; the latency side remains his.

## Next

1. Localise the **idle** half — `ONNX_GENAI_CPU_DECODE_WORKER_PROFILE` /
#1859's per-worker straggler attribution, to separate load imbalance
from dispatch/wake latency.
2. Localise the **burn** half — per-op attribution at w=8 vs w=16
against the 136.3 MB/token figure.

## Validation

- `cargo build --release -p onnx-runtime-ep-cpu --bench
int4_decode_loop_ab` ✅
- `cargo fmt --check` ✅, `cargo clippy` clean on the touched bench ✅
- `ruff check` clean on all touched `.py` (the one repo-wide F401 is
pre-existing in `ort_baseline.py`, untouched here)
- Harness branch-validators run before use: 13 checks / 0 failures
(cpu-split), 0 failures (blocktime A/B)
- All measurement runs taken under `scripts/hostlock.sh` with
announce-before/after

Both harnesses accept `--replay <json>` to re-score archived data, and
both carry their acceptance rule in the module docstring where it was
written before the first run.


---

# Update: the idle half is now attributed

Follow-up 1 from the "Next" section above is **done in this PR** (commit
`53d3ff076`). `int4_decode_loop_ab` now brackets `SpmdWorkerProfile`
deltas over exactly the window that produces `wall`, and
`acc0_w16_worker_split.py` scores them against a rule written before its
first run. **10 launches, 10 trusted, both fired conditions at 100% sign
consistency.**

**Wake latency is not the problem.** `wake_frac` is 0.006 at w=8 and
**0.051** at w=16; the pre-registered WAKE-BOUND condition did **not**
fire. A perfect wait/wake path recovers at most 5 points.

The mean worker's window at width 16:

| | w=8 | w=16 |
|---|---:|---:|
| useful work | 0.886 | **0.492** |
| straggler wait | 0.031 | **0.222** |
| wake latency | 0.006 | 0.051 |
| dispatcher / serial | 0.077 | 0.235 |

**Not all of that is a defect.** Holding w=8's serial time constant and
halving its parallel time — Amdahl with no defect anywhere — predicts a
0.204 serial share at w=16; observed is 0.235. So:

| component | points | recoverable? |
|---|---:|---|
| straggler wait | 22.2 | **yes** |
| serial in excess of Amdahl | 3.1 | maybe |
| wake latency | 5.1 | partly |
| Amdahl-predicted serial | 20.4 | **no** |

Quoting the 46% residual as recoverable would be wrong by more than 2x.
The same calibration also **rules out pure Amdahl** as the explanation
for the knee: it predicts 0.796 useful work and the pool delivers 0.492.

**The straggler** holds **72%** of last-arrivals against a 6.7% chance
share, does **1.5x** the median work, and almost never parks. Two
candidate mechanisms were tested and are **negative**: not a static
mis-partition (segments divide evenly for every shape here, and the
straggler's identity moves between launches), and not the unpinned
dispatcher colliding with a worker (dispatcher CPU → straggler CPU over
four profiled launches: `30→22`, `6→24`, `6→20`, `{30,20,18}→18`). **No
mechanism is claimed.**

**Nothing can help it today.** `DEFAULT_STEAL_TILES_PER_WORKER = 1`
makes `target == total_workers`, so `work_stealing_segments_aligned`
always falls back to static equal segments — there are no spare tiles to
steal.

## A +23% candidate, rejected

The blocktime A/B harness is generalised to vary any single env knob
(thresholds, A/A arm, rotation and the w=8 guard untouched; replaying
the archived blocktime JSON through the refactored scorer reproduces the
published numbers exactly). Pointed at that default, steal tiles 1 vs 2,
blocktime held at the shipped 500 µs in both arms, 8 trusted:

| w | ratio | sign | A/A | sys_frac | cpu_s/tok |
|---:|---:|---:|---:|---|---|
| 16 | **1.2327** | 88% | 1.1301 | 0.280 → 0.192 | −11.7% |
| 8 | 1.0463 | — | 1.0211 | 0.038 → 0.030 | −2.5% |

**REJECTED and not proposed.** The rule requires the effect to clear 3x
the A/A half-width, and that half-width is **0.2154** in the same run.
Re-running until the null comes in narrow would be choosing the sample
that licenses the conclusion, so it is not done. The mechanism moving in
the predicted direction, and the absence of the expected w=8 regression,
are recorded as observations rather than as a result.

**This makes the width-16 A/A null the binding constraint** — ±21.5%
here, ±35% in the earlier width-16 study — large enough that no
improvement of realistic size can clear a pre-registered bar at this
width. It moves ahead of further kernel work in the ledger.

New record:
`docs/benchmarks/2026-08-23-acc0-width-16-worker-attribution.md`.

---------

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
justinchuby and others added 4 commits August 25, 2026 07:20
Take main's bench_generic.rs wholesale rather than re-applying the
extraction: the file has moved 469 commits and is actively edited by
other lanes, and the harness does not need it refactored. The branch is
now purely additive.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
… a bug

The smoke run of this harness reported `0.00 dispatches/iter` while burning
7.85 cpu-s per wall-s. Eight cores of work and a row of zeroes from the
instrument that is supposed to explain it is exactly what a dead counter looks
like, so I chased it as one. It is not: an fp32 `MatMul` fans out on rayon,
not on `task_runtime`, so the zero is true and the harness was measuring a
pool the model never touched.

That is the defect worth fixing. The pool counters answer "how hard did
`task_runtime` work"; they cannot answer "did this model use `task_runtime` at
all", and the two questions produce identical output. Only one of them means
the harness is broken, and the reader had no way to tell which.

So the run now attributes its own routes through `dispatch_ledger`, and a
zero-dispatch row is annotated with which of the two cases produced it:

  native pool:   0.00 dispatches/iter  0.02 parks/iter  ...
  ATTRIBUTION:   this model never dispatched to task_runtime -- the pool row
                 above is a true zero, not a dead counter.
  route:         MatMulF32 -> Native (f32, 8 calls, up to 8 threads)

Recording is on for a single attribution inference and never during the timed
window, since `record_with` builds an `Observation` per dispatch.

Both branches are proved rather than asserted:
  - ledger on, 8-layer model  -> `MatMulF32 -> Native, 8 calls, 8 threads`
  - ledger on, 4-layer model  -> `MatMulF32 -> Native, 4 calls, 2 threads`
  - `enable()` commented out  -> "zero dispatches AND zero routes recorded ...
    this is a dead instrument, not a measurement -- do not quote the pool row"

The last one is the point: without it the dead case and the true-zero case
print the same thing.

The route line also makes each run state whether it was pure native, MLAS or
an ORT fallback, which until now was an assumption carried in the operator's
head rather than a column in the output.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
…y cover

Both are the same failure the attribution commit was written to prevent, so
they are worth naming rather than folding in quietly.

1. The concurrent arm called a good measurement dead.

Attribution was only wired into the single-session path. `run_concurrent_native`
left `routes` empty, so `--sessions 2` on any model that does not use
`task_runtime` -- which includes every fp32 model, since `MatMul` fans out on
rayon -- printed "zero dispatches AND zero routes recorded ... this is a dead
instrument, not a measurement". The run was fine; the verdict was wrong. A
false "do not quote this" is no better than a false number.

Attribution now runs on one session *before* the barrier region rather than
inside it: the ledger takes a mutex per observation, so recording across N
synchronised threads would serialise the exact contention this arm exists to
measure. Routing does not depend on how many sessions are live, so one
session's routes describe them all.

2. Per-iteration counters were divided by the wrong interval.

Counters are sampled every `--snapshot-every` iterations, so the snapshot at
or before the steady boundary is generally earlier than the boundary: the
counter window is up to `--snapshot-every - 1` iterations wider than the sample
window. Dividing by the sample count overstated dispatches/iter, parks/iter,
spin-hits/iter and both context-switch rates -- and `parks_per_iter` is the
park/wake figure this harness exists to produce.

Worse, when steady state is reached before the first interior snapshot there is
no qualifying snapshot at all and the window falls back to iteration zero, so
the "steady" counters silently span the whole run. The comment there claimed
"the steady window's counters never include warm-up", which was exactly wrong
in that case.

Neither is fixable by sampling counters every iteration -- that perturbs what
is being measured. So both are now measured and stated instead: per-iteration
figures divide by the interval the counters actually span, the report prints
that interval next to the sample count, and the fall-back-to-zero case prints
an explicit warning that the numbers include the transient.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Two defects in text I added one commit ago, both found by running the thing
rather than reading it.

The line said "counters are sampled every N iters, so the two differ" and then
printed 512 and 512. A message that asserts a discrepancy next to two equal
numbers teaches the reader to stop reading the message. It now says which case
it is, and only claims the windows differ when they do -- in which case it also
names both divisors, since that is the number a reader would otherwise have to
reconstruct.

Worse, both new messages told the reader to lower `--snapshot-every`. There is
no such flag. The snapshot cadence is `--steady-window`, passed through to
`timed_loop` as `snapshot_every`, and I named the internal parameter instead of
the knob. Advice that cannot be followed is not advice.

Verified end to end rather than by inspection: the concurrent arm now prints
its routes and the true-zero attribution instead of the "dead instrument"
warning, and the fall-back-to-iteration-zero case does fire its warning on a
real run.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@justinchuby
justinchuby marked this pull request as ready for review August 25, 2026 11:36
@justinchuby

Copy link
Copy Markdown
Owner Author

Out of draft. Independent (Opus) review done; it found two real defects, both of which would have published a misleading line, and both are fixed in fa2f19fbc and c0ee1e400.

1. The concurrent arm called a good measurement dead

Route attribution was only wired into the single-session path, so --sessions N > 1 left routes empty. Any fp32 model routes MatMul to rayon rather than task_runtime, so the pool row is legitimately zero — and with no routes recorded the report fell through to:

ATTRIBUTION: zero dispatches AND zero routes recorded ... this is a dead
             instrument, not a measurement -- do not quote the pool row.

The run was fine. The verdict was wrong. A false "do not quote this" is no better than a false number, and it is worse than the original silence because it sounds authoritative.

Attribution now runs on one session before the barrier region, not inside it: the ledger takes a mutex per observation, so recording across N synchronised threads would serialise the exact contention that arm exists to measure. Verified — --sessions 2 now prints route: MatMulF32 -> Native (f32, 4 calls, up to 2 threads) and the true-zero attribution.

2. Per-iteration counters were divided by the wrong interval

Counters are sampled every --steady-window iterations, so the snapshot at or before the steady boundary is generally earlier than the boundary and the counter window is wider than the sample window. Dividing counter deltas by the sample count overstated dispatches/iter, parks/iter, spin-hits/iter and both context-switch rates — and parks_per_iter is the park/wake figure this harness exists to produce.

Worse: when steady state is reached before the first interior snapshot, no snapshot qualifies and the window falls back to iteration zero, so the "steady" counters silently span the whole run. The comment there claimed "the steady window's counters never include warm-up", which was precisely wrong in that case.

Neither is fixable by sampling every iteration — that perturbs what is being measured. So both are measured and stated instead: per-iteration figures divide by the interval the counters actually span, the report prints that interval beside the sample count, and the fall-back case prints a warning. That warning fires on a real run, so the case is not hypothetical:

counter window: 512 iters, same span as the samples above
WARNING: steady state was reached before the first interior counter snapshot, so
         every counter and cpu figure above spans the whole run and INCLUDES the
         warm-up transient. Lower --steady-window to separate them.

3. Two defects in my own new text, found by running it rather than reading it

The counter-window line originally said "so the two differ" and then printed 512 and 512. A message asserting a discrepancy next to two equal numbers teaches the reader to stop reading messages. It is now conditional, and when the windows do differ it names both divisors.

Both new messages also told the reader to lower --snapshot-every. There is no such flag — that is the internal parameter name; the knob is --steady-window. Advice that cannot be followed is not advice.

Review items that did not survive

The reviewer traced and cleared: gap busy-wait/sleep correctness and seeded jitter; /proc/self/stat CPU, per-task context-switch summing and VmHWM peak RSS; the hardcoded CLK_TCK of 100; steady-state detection under tiny --iters; and the dispatch_ledger reset/enable/dropped() ordering across the two null arms.

Validation

  • cargo test -p onnx-genai-bench --features bench-native --lib — 32 passed, 0 failed
  • cargo clippy -p onnx-genai-bench --features bench-native --bin bench_decode_gap -- -D warnings — clean
  • cargo fmt --all -- --check — clean
  • End-to-end under scripts/hostlock.sh: single and concurrent arms, both ledger states, both counter-window cases

Still no timing claim from any of it — these are correctness and instrument-liveness runs on synthetic MatMul fixtures.

`.seb_fixt/make_model.py` and `.seb_fixt/verify.sh` are throwaway smoke-test
scaffolding -- a synthetic MatMul-chain generator and the two commands I used
to exercise the report branches. They belong in neither the branch nor the
history. Committed by a careless `git add -A`.

Noting it rather than force-pushing it away, since I flagged the identical
mistake in someone else's PR earlier this week and it would be poor form to
quietly erase my own.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
justinchuby added a commit that referenced this pull request Aug 25, 2026
## The defect

`SharedState::worker_wait` spins 4096 times on `spin_loop`, then calls
`thread::yield_now()` on **every subsequent iteration** until the
blocktime window expires. Its own doc says why:

> then relax to `yield_now` so a busy host can schedule other work while
we finish out the blocktime window

On the cpuset a decode budget confines the process to, there is nobody
to hand the core to. `bound_process_to_decode_budget`
(`provider.rs:344`, at EP `initialize()`) pins the process to exactly
its budget's CPUs and caps the global Rayon pool to match. Mid-barrier,
every other runnable thread is a peer in this same wait. `sched_yield`
finds nothing eligible, returns immediately, releases nothing — and
still pays a syscall and a full scheduler pass.

The politeness mechanism was occupying the cores it meant to hand back.

## Measurement

`int4_decode_loop_ab`, width 16, production-confined, `PROBE_TOKENS=1024
PROBE_REPS=2`. Two binaries from the same tree differing only in
`worker_wait`. 10 rounds of `[base, fixed, base', fixed']` so host drift
lands inside every contrast, with `base` vs `base'` as the A/A null.
n=20 per arm.

| | main | this PR | paired ratio (A/B) | A/A null | resolvable? |
|---|---|---|---|---|---|
| **kernel time** | 2.61 cores [2.34, 3.25] | **0.22 cores** [0.19,
0.24] | 0.088 / 0.085 | 1.028 [0.83, 1.11] | **yes, disjoint** |
| yields per 20ms window | 14896 | **384** | — | — | 38.8x |
| tokens/s | 279.6 [217.7, 287.3] | 276.2 [252.8, 279.6] | 0.991 / 0.978
| 1.004 [0.92, 1.16] | no |
| total occupied cores | 15.76 | 15.88 | — | — | no |

Kernel time is disjoint and every one of the 20 paired ratios sits far
outside the A/A null. Throughput overlaps, and its paired ratios poke
outside the null in *both* directions, which is what noise looks like.

## What this does and does not buy

**Does not**: free a core. Occupancy is unchanged (15.76 → 15.88)
because the worker still holds it, now spinning in user space instead of
in the kernel. A co-tenant gets the runqueue lock and the scheduler
passes back, not the CPU.

**Does**: remove ~2.4 cores' worth of syscalls that returned without
doing anything, and make `sys_frac` a usable signal again. At width 8
the old loop was bimodal — 0.4% kernel time and 216 tokens/s in one run,
15.7% and 130 tokens/s in the next — which made "are we thrashing" and
"are we waiting" indistinguishable in my own matrices.

The larger question — whether the 500us window earns its occupancy at
all — is **#2071**, deliberately not answered here. It needs the
inter-token gap regime the window was designed for, not the tight loop
this bench runs, and that harness (#1395) is not merged.

## Preserving #1825

The deadline is now evaluated on a stride of 64 pure `spin_loop`s
(~640ns) rather than after every yield. That is **not** the stride #1825
removed: that one was a stride of *yields*, each costing microseconds to
milliseconds of an already-starved thread. Checking every ~640ns is
strictly more often in wall-clock terms than "on every yield" ever
achieved, and
`the_blocktime_deadline_is_evaluated_on_every_yield_not_on_a_stride`
passes unchanged.

`YIELD_CLOCK_STRIDE` is kept a divisor of `SPIN_LOOP_BUDGET` so the
yield phase gets its first clock read on the iteration it begins at.

## The test, and why it is shaped this way

`the_active_window_yields_on_an_interval_not_on_every_iteration` counts
yields over a 20ms window and asserts the phase cannot exceed one yield
per 20us.

The bound is **arithmetic, not empirical**: a yield happens only when
`elapsed` reaches `next_yield`, and `next_yield` advances by at least
`YIELD_INTERVAL` each time, so the count is capped no matter how fast
the loop spins. Load can only reduce it.

The ceiling is **stated absolutely rather than derived from
`YIELD_INTERVAL`**. A ceiling computed from the constant under test
moves with it — setting the interval to one nanosecond restores the
exact defect and still satisfies a derived bound. That is the same shape
as an A/B whose control is latched (#1736), and mutation M2 below is the
proof it would have mattered.

`slow_yield` now counts unconditionally and only *sleeps* when injected.
The test has to count yields in the uninjected regime it asserts about;
injecting a sleep to make them countable would have set the interval
under test.

## Mutation-proved, three ways

Each kills only the new test:

| mutation | observed | fails on |
|---|---|---|
| yield on every iteration, ignoring the interval | 4884 yields | rate
bound |
| `YIELD_INTERVAL = 1ns` | 4837 yields | rate bound — the reason the
ceiling is absolute |
| window shortened below the spin phase | 0 yields | **non-vacuity**,
not a silent pass on a bound nothing reached |

And the main-equivalent loop (no stride, yield every iteration) measures
**14896**, which is the baseline quoted above.

## A note on instruments

`strace` cannot confirm this. At ~55us per traced syscall the
instrument's own cost exceeds the 50us interval it is measuring, so both
arms yield on every check and the difference collapses to 17797 vs 13701
— a 1.3x that looks like a weak result and is actually the instrument
setting the property. The in-process counter is the only tool here that
does not. `perf` tracepoints are unavailable at `perf_event_paranoid=1`.

## Validation

- `cargo test -p onnx-runtime-ep-cpu --lib` — **1752 passed, 0 failed**,
25 ignored
- `--features mlas` — **1778 passed, 0 failed**, 36 ignored
- `cargo clippy --lib --all-targets -- -D warnings` clean on both lanes;
`cargo fmt --check` clean
- All benchmark runs took `scripts/hostlock.sh` for the whole window

---------

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@justinchuby
justinchuby merged commit 18f23e6 into main Aug 25, 2026
18 checks passed
@justinchuby
justinchuby deleted the squad/sebastian-gap-harness branch August 25, 2026 13:13
justinchuby added a commit that referenced this pull request Aug 25, 2026
…ured (#2117)

Adds the counter #2075 needs, and reports it. **No behaviour change** —
this is the instrument, not the fix.

## Why the issue could not be answered as written

#2072 fixed a yield-every-iteration wait in `decode_spmd` that cost 2.61
of 16 cores in kernel time. #2075 asks whether `task_runtime::pool` has
the same tax. It could not be answered, for two reasons — and **the
first is that my own issue is wrong**.

**#2075 names two yield-every-iteration sites. There is one.** The
dispatcher's straggler wait yields on a stride of
`DISPATCHER_YIELD_STRIDE` (4096 spins), and `git log -S` puts that
stride in the pool's introducing commit (#1201), so it was never the
shape I filed it as. Only the worker's `spin_for_dispatch` second phase
yields on every iteration. I'll correct the issue.

**The one real site had no counter.** `straggler_yields` counts the
dispatcher's side — already rate-limited, so the cheap half was
instrumented and the expensive half was not. A release build could
report parks and spin hits but not a single worker yield.

## What it measures

`PoolCounters::spin_yields`, accumulated in a local and published with
one relaxed add when the window ends. Per-yield `fetch_add` was rejected
for the same reason the neighbouring `SPIN_COUNT` is recorded on exit:
an instrument built to answer a *contention* question should not add
shared-atomic traffic to the loop it is measuring.

## The number, and how far I'd trust it

Softmax-chain fixture, 400 µs sleep gap, default width, under the host
lock:

```
native pool:  8.00 dispatches/iter  11.25 parks/iter  108.75 spin-hits/iter
spin yields:  3606.26/iter  30.1/window over 12960 windows
```

**A/A null control**, the two arms differing only in being second:

| arm | yields/iter | yields/window | wall p50 |
|---|---|---|---|
| null-a | 4177.78 | 34.8 | 0.7450 ms |
| null-b | 4169.35 | 34.7 | 0.7366 ms |

The counter reproduces to **0.2%**, inside a wall-time null band of
0.989x — it is a tighter instrument than the wall clock for this
question.

Per-*window* is the figure to quote. Per-iteration moved 3606 → 4178
across invocations while per-window moved 30.1 → 34.8, because yields
only accrue inside a window and the per-iteration figure therefore
tracks iteration time. That is why the report prints both.

**What this does not establish.** The count is measured; the *cost* is
not. Converting ~30 yields/window into kernel time needs a per-yield
cost, and the only figure I have for that is a code comment (~1.2 µs
uncontended). So I am not claiming a core count here, and #2075 stays
open on its kernel-time item. What the count does establish is that the
phase is reached constantly in the decode-gap regime — which was the
open question, since the window halves on every park and a
converged-idle pool would never reach it at all.

## Test


`the_spin_phase_yield_counter_counts_exactly_the_yields_the_window_performed`
asserts the count **exactly**, not `> 0`. Mutation-proved both ways:

- bump deleted → fails, `the window ran 4322 spins, so it yielded on 227
of them ... but the counter recorded 0`
- bump moved into the pure-spin phase → fails, `counter recorded 4324`
against 229 real yields

A `> 0` assertion passes both. The second mutation is the dangerous one:
it over-reports by ~19x, which would manufacture exactly the tax the
issue is trying to detect.

Reaching the yield phase is inherently timing-dependent (4096
`spin_loop`s, ~130 µs here, must fit inside the window), so the
assertion is an **iff**: reached the phase → count matches exactly;
expired before it → count is zero. One branch or the other is real on
any host, including Miri and a saturated runner, so the test cannot go
quiet the way a skip would.

## Harness

Both report branches were run, not reasoned about. An fp32 model never
dispatches to the pool, so it prints the unused-pool verdict rather than
`0.00/iter` — a rate about a pool the model does not use is a number
about somebody else's workload, which is the failure the attribution
line already exists to prevent.

Sequenced deliberately behind #1395: the new field breaks that PR's
exhaustive `PoolCounters` literal, so this branch was rebased onto it
rather than racing it. Each PR is green alone; only this order is green
combined.

Validation: ep-cpu 1815/0 default, 1841/0 `--features mlas`, bench 32/0,
clippy `-D warnings` clean on both crates, fmt clean.

Refs #2075

---------

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
justinchuby added a commit that referenced this pull request Aug 27, 2026
… the prior A/A-null result

Independent review found four precision defects in the replacement text, which
would have been self-defeating in a change whose whole point is that a comment
must say what was measured.

  * "CI [0.960, 1.013]" was the raw min-max of 7 paired ratios, not a
    confidence interval. A t-based 95% CI on the same data is [0.978, 1.008].
    Now stated as a range with its n.
  * "the median worker parks 0.533 times" conflated two aggregations: it is the
    median over launches of the mean over workers.
  * "on either baseline" referenced #2245's baseline bug, which is not context
    a reader of this file has. Dropped; "at either blocktime" carries it.
  * "~5% of pool width" was the low end. It is ~5.6% at t=8 and ~8% at t=16
    (1.3 of 16 cores). Now "~5-8% ... ~1.3 cores at width 16".

The review also surfaced a prior result I had not credited, and it corrects my
framing rather than merely my wording. `CPU_MATMUL_ASSIGNMENT.md` already
records removing the ramp as throughput-neutral at t=16 -- ratio 0.9960 against
a 5.24% A/A null. So the throughput half is not "unresolved" as I wrote: at zero
gap it is measured neutral, with the control my own batch lacked.

What is actually unmeasured is narrower and more pointed: every result on both
sides is a zero-gap decode loop, which is exactly where parking looks falsely
free, and the window's justification is inter-token gaps. The comment now says
that, and names #1395's gap-aware harness alongside #2071's arms.

fmt clean, clippy -D warnings clean, rustdoc warning count unchanged at 112.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant