Repository navigation
perf(ep-cpu): stop the decode wait yielding on every iteration - #2072
Conversation
Independent adversarial reviewReviewed by an independent Opus agent with no context from the work that produced the change, explicitly asked to find defects and to report what it cleared as well as what it found. Verdict: SAFE TO MERGE AS-IS. No serious findings. Six minor; I have taken five ( Taken
Not taken
Cleared, with evidenceThe review's most useful section. It suspected and then disproved: One follow-up it surfaced
|
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #2072 +/- ##
==========================================
+ Coverage 80.32% 81.21% +0.88%
==========================================
Files 426 429 +3
Lines 204769 214164 +9395
Branches 204769 214164 +9395
==========================================
+ Hits 164483 173927 +9444
+ Misses 34665 34474 -191
- Partials 5621 5763 +142
Flags with carried forward coverage won't be shown. Click here to find out more.
🚀 New features to boost your workflow:
|
The two red Windows lanes here are not this PR's — they are the #2059 regression, and #2078 already fixes itRun 32810586898 failed
This PR's diff is one file, Ruling out the other candidate explicitly, because I owe an honest answer on this lane: this is not #1745. #1745 is Status of this PRThe other 17 checks are SUCCESS. I am not merging on that basis — |
50191cb to
29fc40a
Compare
|
Rebased onto Local re-validation after the rebase: Waiting on required CI. Will merge only when the Windows lanes are actually green — not on the strength of the other 17. |
…test (#2093) Closes #2089. Filed by @holden — thanks, the diagnosis in the issue was already correct and I only added the `n >= 4` eligibility detail. ## The bug `kernels::stft::tests::real_unwindowed_overlapping_frames_match_independent_reference` asserts that every power-of-two frame took a fast path, and it does so by reading `DFT_FFT_TEST_HITS`. That counter is bumped **only** by the portable radix-2 branch of `DftPlan::transform`. On Apple targets `DftPlan::new` builds a vDSP setup whenever `n.is_power_of_two() && n >= 4`, and `transform` bumps `DFT_VDSP_TEST_HITS` and **returns** before ever reaching the radix-2 block. The test uses a frame length of 4 — the first vDSP-eligible size — so on macOS the frames took a fast path and the counter the test was watching stayed at zero. Deterministic red on `Rust coverage (macOS arm64)` since 08022b6 (#2083); it is blocking the macOS lane on every open PR, including my own #2072. ## The fix The property the assertion is actually about is *"we did not fall back to the naive O(n^2) transform"*, not *"we took this particular one of the two fast paths"*. So it now reads a `dft_fast_path_hits()` helper that sums both counters. The helper lives in `dft.rs` rather than inline at the call site because `DFT_VDSP_TEST_HITS` is itself `#[cfg(any(target_os = "macos", target_os = "ios"))]` — it does not exist on Linux, so summing it at the `stft.rs` call site would need a second cfg block in a file that has no business knowing about vDSP. **`fft_fallback_reachability` is deliberately untouched.** It uses `n = 2`, which is below the vDSP minimum, so it still exercises and still asserts on the portable radix-2 path specifically, on every target. Weakening that one to use the sum would have thrown away the only real radix-2 check we have. Instead I added `an_eligible_power_of_two_takes_a_fast_path_on_every_target` at `n = 4` — the first vDSP-eligible size — which is the cross-platform counterpart and which nothing previously covered. ## Why this is not a mute button Broadening an assertion to make a red lane green is exactly the shape of change that can silently delete the test, so I did not want to ship it on the argument that it looks right. Neither of us has a Mac, so I reproduced the Apple shape on Linux: I added an early-returning arm for `n >= 4` that bumps a separate counter, mirroring what the vDSP arm does. - **Pre-fix code under the simulation: FAILS**, at `stft.rs:363`, with `each power-of-two frame must use the radix-2 FFT path` — the same line and the same message as the macOS runner. So the simulation is a faithful reproduction, not an approximation. - **Fixed code under the same simulation: PASSES.** - **Radix-2 disabled entirely (`if false && ...`): both `fft_fallback_reachability` and the new test FAIL.** So the fixed assertion still detects a genuinely absent fast path rather than accepting anything. That third arm is the one that matters: it shows the widened assertion has not lost its teeth. A change that only satisfied the first two would be indistinguishable from deleting the check. One more note in the code: the counters are process-global and tests run in parallel, so a concurrent test can inflate `after - before`. The assertion is `>=`, and inflation can only ever mask a *failure to under-count* — which is not the failure mode being guarded — so it cannot produce a false green here. I left a comment saying so rather than reaching for serialisation. ## Validation - `cargo test -p onnx-runtime-ep-cpu --lib` — **1797 passed, 0 failed**, 26 ignored - `cargo test -p onnx-runtime-ep-cpu --lib --features mlas` — **1823 passed, 0 failed**, 37 ignored - `cargo clippy -p onnx-runtime-ep-cpu --lib --all-targets -- -D warnings` — clean - `cargo fmt --all -- --check` — clean Linux can only prove the negative half of this directly; the macOS lane on this PR is the actual verdict, and I will not merge before it is green. --------- Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
`worker_wait`'s active window spun 4096 times and then called `sched_yield` on every subsequent iteration until the blocktime expired. The intent, per its own doc, was politeness: release the core so a busy host can schedule other work while we finish the window. On the cpuset a decode budget confines the process to, there is nobody to release it to. `bound_process_to_decode_budget` pins the process to exactly its budget's CPUs, so mid-barrier every other runnable thread is a peer in this same loop. The yield finds nothing eligible, returns immediately, releases nothing, and still pays a syscall and a full scheduler pass. The politeness mechanism degenerated into a syscall storm that occupied the very cores it meant to hand back. Measured at width 16 on a 16-CPU cpuset, `int4_decode_loop_ab`, 20 runs per arm interleaved with an A/A null arm: | | main | this | |---------------------|--------------------|--------------------| | kernel time | 2.61 of 16 cores | 0.22 of 16 cores | | yields per 20ms | 14896 | 384 | | tokens/s | 279.6 | 276.2 | | total occupancy | 15.76 cores | 15.88 cores | Kernel time is disjoint between the arms (base [2.34, 3.25] against [0.19, 0.24]) and every paired ratio is far outside the A/A null envelope. Throughput overlaps and its paired ratios sit inside the null in both directions, so the storm was buying nothing. The core is still held -- this converts kernel time into user-space `spin_loop`, it does not park earlier -- so co-tenants gain the runqueue lock and the scheduler passes back, not the core. The separate question of whether the window earns its 500us at all is #2071, and is deliberately not answered here: it needs the inter-token gap regime the window was designed for, not the tight loop this bench runs. The deadline is now evaluated on a stride of 64 pure `spin_loop`s (~640ns) rather than on 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. The guarantee is strengthened, and `the_blocktime_deadline_is_evaluated_on_every_yield_not_on_a_stride` still passes unchanged. `slow_yield` now counts unconditionally and only sleeps when injected, because the new test has to count yields in the uninjected regime it asserts about -- injecting a sleep to make yields countable would set the interval under test. A counter that only counts when its subject has been perturbed cannot observe the unperturbed case, which is the same defect shape as #1736. Mutation-proved three ways, each killing only the new test: * yield on every iteration regardless of the interval -> 4884 yields, fails the rate bound * `YIELD_INTERVAL` set to 1ns -> 4837 yields, fails. This is why the ceiling is stated absolutely rather than derived from the constant under test: a derived ceiling moves with it and would have passed. * window shortened below the spin phase -> 0 yields, fails the non-vacuity assertion rather than passing on a bound nothing reached Note for anyone tempted to confirm the syscall count with `strace`: it cannot. 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 against 13701. The in-process counter is the only instrument here that does not set the property. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
* Reset `SLOW_YIELD_US` alongside `YIELD_COUNT` before the new test's assertions, matching the sibling. It is already 0 on this path, so the reset is a no-op today -- it exists so the cleanup does not have to be re-derived if the test grows an injected arm. * Reset `YIELD_COUNT` in `the_readiness_backstop_fires_within_its_ deadline_not_a_stride_later`. That test drives the *other* `slow_yield` site, which now counts unconditionally, so it was leaving a tally behind for whatever libtest ran next on the thread. Harmless today because both readers zero the counter on entry, but that invariant was unspoken. * Drop the "~640ns" figure for 64 `spin_loop`s. `pause` is ~5ns on Skylake and ~47ns on Ice Lake and later, and `spin_loop` lowers to `yield`/`isb` on aarch64, so one number was a single-microarchitecture ballpark presented as general. The claim that survives everywhere is that the stride is hundreds of nanoseconds to a few microseconds. * Say that the yield offers scale linearly with the blocktime knob, since "~10 per window" is only true at the default. * Say that 14896/384 were measured out-of-band by running the test against each version of the loop, and that the test asserts a rate bound rather than those numbers -- so nobody reads them as CI-verified. * Record why a low yield count is reported as inconclusive: reaching 0 or 1 needs a stall the length of the whole window, which a saturated runner can produce, so a red there is a re-run rather than a defect in `worker_wait`. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
|
Rebased onto Only I will merge once |
29fc40a to
1e2a56a
Compare
…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>
`user_us` and `sys_us` are read from /proc/self/stat, summed into `cpu_us`, and the split is then discarded at the report. Kernel time is the quantity a scheduler question actually needs -- `sched_yield` and futex traffic land there and nowhere else -- and it is what #2072 used to show its fix worked (2.61 cores of kernel time down to 0.22). #2075 asks the same question of `task_runtime`, and the harness could not answer it despite already having both halves in hand. Adds a `cpu split` line and a `sys_share` key on the machine-readable line. First numbers, and they are deliberately not a #2075 answer. A softmax route that dispatches to the native pool runs 52.0% sys; an fp32 route that never touches that pool, on the same host and the same gap, runs 39.2% sys with zero native yields. So a high sys share is not evidence of the yield tax -- Rayon's own park/wake produces one too. Those are different models doing different work, which makes the pair an observation and not a comparison. Attributing kernel time to the yields needs one model measured with and without the rate limit, which is the fix, not this. Refs #2075 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
#2128) The harness reads `utime` and `stime` from `/proc/self/stat`, sums them into `cpu_us`, and throws the split away at the report. Kernel time is exactly the quantity a scheduler question needs — `sched_yield` and futex traffic land there and nowhere else — and it is the quantity #2072 used to demonstrate its fix (2.61 cores of kernel time down to 0.22). #2075 asks the same question of `task_runtime`, and the harness could not answer it while already holding both halves. Adds a `cpu split` line and a `sys_share` key on the machine-readable line. ## First numbers, and why they are not yet a #2075 answer | route | dispatches/iter | spin yields | cpu-s/wall-s | sys share | |---|---|---|---|---| | softmax (uses the native pool) | 8.00 | 31.3/window | 12.93 | **52.0%** | | fp32 MatMul (Rayon, never touches it) | 0.00 | none | 10.38 | **39.2%** | 52% sys on the dispatching route looks like a headline. It is not one, and the control is the reason I ran it: a route with **zero** native-pool yields still burns 39.2% sys, because Rayon's own park/wake is also kernel time. These are two different models doing different work on the same host and gap, which makes the pair an **observation, not a comparison**. Attributing kernel time to the yields specifically needs one model measured with and without the rate limit — that is the fix, and it is not this PR. What this does deliver is that #2075's second checklist item is now answerable at all, without `strace` (ruled out on that issue: at ~55 µs per traced syscall the instrument costs more than the interval under test and both arms collapse to the same rate). ## Validation `cargo test -p onnx-genai-bench --features bench-native --lib` 32/0, clippy `-D warnings` clean on the bin, fmt clean. Both new outputs were produced by real runs under the host lock, not reasoned about. Refs #2075 --------- Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The defect
SharedState::worker_waitspins 4096 times onspin_loop, then callsthread::yield_now()on every subsequent iteration until the blocktime window expires. Its own doc says why: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 EPinitialize()) 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_yieldfinds 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 inworker_wait. 10 rounds of[base, fixed, base', fixed']so host drift lands inside every contrast, withbasevsbase'as the A/A null. n=20 per arm.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_fraca 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_loops (~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, andthe_blocktime_deadline_is_evaluated_on_every_yield_not_on_a_stridepasses unchanged.YIELD_CLOCK_STRIDEis kept a divisor ofSPIN_LOOP_BUDGETso 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_iterationcounts 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
elapsedreachesnext_yield, andnext_yieldadvances by at leastYIELD_INTERVALeach 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_yieldnow 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:
YIELD_INTERVAL = 1nsAnd the main-equivalent loop (no stride, yield every iteration) measures 14896, which is the baseline quoted above.
A note on instruments
stracecannot 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.perftracepoints are unavailable atperf_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 ignoredcargo clippy --lib --all-targets -- -D warningsclean on both lanes;cargo fmt --checkcleanscripts/hostlock.shfor the whole window