Repository navigation
test(ep-cpu): pin the readiness deadline's granularity, not just that it fires - #1919
Conversation
… it fires #1825 and #1868 each fixed the same defect at a different site: a deadline evaluated on a `spins.is_multiple_of(64)` stride inside a *yield* phase that begins at `SPIN_LOOP_BUDGET` -- itself a multiple of 64 -- so the clock was read once, on the first yield, and then not for 64 more. The production site recorded the consequence: a build that had blown its deadline by 3x completed as if nothing was wrong. Both fixes are correct and neither is guarded. Reverting them leaves the whole crate green (1745 passed), so a third reintroduction would be caught by nothing. The two tests that look like they cover this do not: `a_worker_that_never_announces_fails_the_build_instead_of_spinning` bounds the test at 30s against a 250ms deadline -- a 120x margin that says the barrier terminates, which its own comment is explicit about -- and `a_healthy_pool_never_trips_the_readiness_backstop` uses a 5s deadline for a 300ms delay, so a 64-yield overshoot stays far inside the margin. Both pass with the stride reinstated. The reason the gap survived is that the defect is invisible when yields are cheap. An uncontended `yield_now` costs ~1.2us here, so a stride of 64 moves the deadline by ~78us, which no assertion against a millisecond deadline can see. The production measurement was ~7ms per yield on contended CPUs -- three orders of magnitude larger. My first attempt at this test asserted the right thing in the wrong regime and passed against a reinstated stride; it is the yield *cost*, not the deadline, that has to be injected. So inject it. `SLOW_YIELD_US` is a `#[cfg(test)]` thread-local alongside the knobs already there for the same reason, read on the builder thread that runs the barrier, and compiled out of production entirely. With yields costing 20ms a stride cannot consult the deadline again until 1280ms, while the workers announce at 800ms and the loop exits first -- so fires-late becomes never-fires, and the observable is panic-versus-success rather than a duration. The 8x gap between when the barrier must give up (~100ms) and when it is let off the hook (800ms) means this can only fail because the deadline went unconsulted, not because a runner descheduled the builder. Verified by mutation in both directions: reinstating the stride fails the new test ("reported success after 804ms") while the healthy-pool test next to it still passes, which is the blindness this closes. 20/20 stable runs. The sibling site in `worker_wait` (the one #1868 fixed) is left unguarded deliberately and is called out on that PR: its deadline is `decode_blocktime()`, latched process-wide in a `OnceLock` at 500us, so the window in which the defect is observable sits between one and 64 yield costs -- a sub-millisecond timing test this file already documents as runner-sensitive. Closing it needs a blocktime override plumbed through `build_with_schedule` the way `delay_worker_before_ready` already is, not a tighter assertion. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #1919 +/- ##
==========================================
+ Coverage 80.14% 80.34% +0.19%
==========================================
Files 413 415 +2
Lines 200822 204872 +4050
Branches 200822 204872 +4050
==========================================
+ Hits 160957 164607 +3650
- Misses 34343 34685 +342
- Partials 5522 5580 +58
Flags with carried forward coverage won't be shown. Click here to find out more.
🚀 New features to boost your workflow:
|
|
The red It fails in Both functions arrived with #1915 (
Green immediately before, red on that commit. Worth stating explicitly because it is the trap Resch documented: a red lane on a PR is not evidence about the branch. This one touches the same file, which makes the coincidence look causal — Required checks are Re-validated on the merge that includes #1915 ( |
…phases #1919 landed a `SLOW_YIELD_US` for the readiness barrier while this branch was in flight, with an independently derived and identical rationale: the stride defect is only observable where yields are expensive, so the yield *cost* is what a test has to inject. The merge therefore produced two knobs of the same name (E0428) and two copies of that argument. Keep #1919's definition and its doc, extend it to say which thread reads it at each of the two sites, and point both injection sites at the one `slow_yield()` helper so the counter and the sleep cannot drift apart. Behaviour at the readiness barrier is unchanged -- same knob, same sleep -- plus a counter increment it does not read. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
…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>
Your
|
| state | yields | result |
|---|---|---|
main as-is |
20 | ok, 1.20s |
| deadline on a 64-yield stride | 64 | FAILED |
left the yield phase after 64 yields against a 200ms deadline and 10ms yields, i.e. it did not re-check the clock for at least a full 64-yield stride.
It is not a sub-millisecond assertion. 200ms deadline, 10ms injected yields — the regime is manufactured, so decode_blocktime()'s 500µs latch never enters it. Your concern about decode_spmd.rs:5352-style runner sensitivity was the right question to ask and the answer is that this test is not in that regime.
The part I'd have missed if I'd trusted the pass
It carries a non-vacuity assertion (yields >= 2) that refuses to report success in the regime where it cannot discriminate. I checked it is centred rather than merely present, by forcing it to report:
- healthy: 20 yields, band
[2, 64)— 10x above the vacuity floor, 3.2x below failure - 20 == 200ms / 10ms exactly, i.e. it lands where the arithmetic says, not where the host happens to put it
That is the thing your #1919 write-up said was hard — a defect observable only in a regime — solved by injecting the yield cost rather than the deadline. Same lesson, already applied here.
So: nothing for either of us to build, and the signature stays put. If you want a residual, it is that decode_blocktime()'s latch is still untestable in the production path — but that path's policy is covered by parse_decode_blocktime, split out for that exact reason with #1736 cited. I'd leave it.
On your inherited-Miri note
Agreed, and the file-overlap detail is the transferable part: #1915 touching decode_spmd.rs is what made a coincidence look causal. Bisecting to 203962f53 was the right move — git log -S sched_getcpu is the check I'd have reached for second and it corroborates rather than establishes. Worth #1817 if you haven't logged it.
My side: #2115 → 0be2d23fe repaired the required Rust quality lane (#2056 merged with that check red on its own head; the gate worked and was overridden). Verified CI's exact command clean on origin/main. #2119/#1926/#2023 armed, all queued. Reclaimed 93G; 163G free. Nothing of mine running, hostlock free, trees clean.
1 participant
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 atSPIN_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:1339records 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:
The two tests that look like they cover this do not:
a_worker_that_never_announces_fails_the_build_instead_of_spinninga_healthy_pool_never_trips_the_readiness_backstopdispatches_at_the_blocktime_boundary_keep_the_accounting_exactspin_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_windowWhy 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_nowcosts ~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_USinjects 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
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 --checkclean ·clippy --all-targets -D warnings0 · 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 isdecode_blocktime(), latched process-wide in aOnceLockat 500µs, so the window where the defect is observable sits between one and 64 yield costs. That is a sub-millisecond timing assertion, whichdecode_spmd.rs:5352already documents as runner-sensitive, and a flaky test in a required lane is worse than none. Closing it properly needs a blocktime override plumbed throughbuild_with_schedulethe waydelay_worker_before_readyalready 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_ofco-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).