Repository navigation
fix(cpu-ep): stop the decode pool before a child exits, and say where it died - #1889
Conversation
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #1889 +/- ##
===========================================
+ Coverage 72.56% 80.70% +8.14%
===========================================
Files 12 415 +403
Lines 5231 204577 +199346
Branches 5231 204577 +199346
===========================================
+ Hits 3796 165109 +161313
- Misses 1307 33896 +32589
- Partials 128 5572 +5444
Flags with carried forward coverage won't be shown. Click here to find out more.
🚀 New features to boost your workflow:
|
29aaa25 to
9209345
Compare
Independent review responseRan an independent Opus review over the commit. It found one real bug that would have turned CI red on the default runner, plus two doc claims that were wrong. All three fixed in 1. The teardown assertion was off by one, and only on hosts narrower than mine — fixed
I asserted The test's own printed diagnostics said Fix: added And the part that matters more than the fix. The defect was invisible on my host and visible on a narrower one. So I made the test reproduce the narrow regime everywhere rather than trusting that CI would: it now runs two widths, one of them the whole machine, which forces the headroom reservation on any host wide enough to have one — and it asserts that some arm actually reached that regime rather than assuming it. Verified against the off-by-one as a re-injected mutant:
Clean tree passes at every width from
2.
|
… it died #1745 is an intermittent `STATUS_ACCESS_VIOLATION` (0xC0000005) in the SPMD parity child on Windows ARM64. The child *faulted*; it did not fail the parity assertion, which `child_status_detail` already distinguishes. Three test children build the process-wide decode pool. Exactly one of them -- `affinity_defer_routing_child` -- stops it before exiting, and its comment names this same 0xC0000005 on native Windows ARM64 as the reason it was added. The parity child and the realized-width child never got the same treatment, and #1745 is reported against exactly those two. The pool lives in a module-level `static`, which Rust never `Drop`s, so those children exit with workers still spinning or parked on `Arc<SharedState>`; on Windows `ExitProcess` then terminates them at an arbitrary instruction, including inside a CRT or heap lock that exit-time cleanup goes on to take. Applying the existing remedy to the other two children is the cheapest way to find out whether it is the same bug. This does not claim to have proven it is: the crash is rare, intermittent, and on a platform this workspace cannot execute. So the change also makes the next occurrence say something. What this adds: * `quiesce_pools_for_child_exit` -- one teardown path for all three children, rather than one that was fixed and two that were not, which is how #1745 came to be filed against the other two. In the two children that never had a teardown it is called *after* the result marker, so a crash inside our own teardown keeps the marker on stdout, reads as non-environmental to `is_environmental_access_violation_crash`, and is reported rather than retried away -- a bug in this code is not a flaky runner. `affinity_defer_routing_child` keeps its existing marker-last order; flipping it would change a currently green lane's red/green semantics on an untestable platform to probe an unconfirmed hypothesis. * Stage breadcrumbs on stderr (`NXRT_CHILD_STAGE: site=... stage=...`). A #1745 report today says the child faulted and nothing else: between process start and the single result line the child builds a pool, runs a kernel, encodes bytes and tears the pool down, and a fault anywhere in that span produces the same report. `body-complete` and `pools-stopped` separate "crashed doing the work" from "crashed at exit after the work" -- different bugs with different fixes. Checked rather than assumed: the detail was never printed-and-lost. Rust's stdout is a `LineWriter` on every platform, so a newline-terminated `println!` has already reached the pipe before the fault. A child that writes one newline-terminated line, one unterminated `print!` and one flushed stderr line and then `abort()`s under `Command::output()` delivers the first and the third and loses only the fragment. The gap is that nothing was emitted between "started" and "produced the result". Breadcrumbs go to stderr because both readers of these children key on stdout by content, so extra stdout lines would change two lanes' verdicts. Extra stderr lines do not, provided they never contain `panicked at` or `assertion` -- the only two strings the classifier reads from stderr. Asserted, not assumed, in `a_stage_breadcrumb_is_invisible_to_the_crash_classifier`. * `SpmdDecodePools::workers_exited` -- the mirror of `ready`. `ready` makes "the workers started" observable so `build` can block on it; nothing made "the workers stopped" observable, so the only available evidence was the absence of thread names in `/proc/self/task`. One `fetch_add` per worker per process, on a `Drop` guard so it counts a panicking worker out too. Tests: three, each mutation-verified to fail under its own defect and no other (6 injected defects, 6 caught uniquely, no over-catch). `shutdown_pools_is_a_barrier_not_a_request` asserts that shutdown is a barrier rather than a request: without a join the child would still be racing its own runtime teardown and the call would be decoration. It is in a child process because `comm` truncates at 15 bytes, so in a shared binary another test's pool is indistinguishable from this one's. Its first version compared the exit count against `total_workers()`, which was wrong by exactly one whenever `reserve_single_group_headroom` hands a shard to the dispatching thread inline -- a participant that never enters `worker_loop` and can never be joined. That is the common case on a fully-subscribed host: a stock 2-core runner would have failed on every run while the shutdown it was accusing was entirely correct. Invisible on this 32-CPU host, which is why the test now runs two widths, one of them the whole machine, so the inline-shard regime is reproduced on any host wide enough to have it -- and asserts that some arm reached it rather than assuming so. `spawned_workers()` exists to name the right reference count. Found by independent review. A width narrow enough to spawn nothing at all reports a loud SKIP rather than passing quietly, and that skip is itself gated on the host reporting <= 2 CPUs, so it cannot swallow a pool that spawned nothing on a wide host. An earlier version asserted zero live worker threads instead and *flaked under load*: the futex that unblocks `join` is signalled at `mm_release`, before the kernel unhashes the task, so a joined thread's `/proc` entry can outlive the join. That is a race in the instrument, and an intermittently-red teardown test would teach exactly the wrong lesson about intermittently-red teardown. The assertion moved to the counter, which is ordered by the join itself; the thread counts are still printed, as a report rather than an assertion. Removing the join is caught 18/20 runs -- the thread count caught 20/20 in that same batch and is still the wrong instrument, because it also fails a correct implementation and a test that is red for two reasons cannot tell you which. Refs #1745, #983, #1672. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
9209345 to
6a18eb7
Compare
|
Amended in Doc-only change on top of the reviewed tree; no code or test behaviour altered. CI restarted from the amend. |
1 participant
Closes #1745.
What #1745 actually reports
0xC0000005isSTATUS_ACCESS_VIOLATION. The child faulted — it did notfail the parity assertion.
child_status_detailexists to distinguish those andsays fault. Roy did the elimination work on his PR (#1741): the diff didn't
touch the test, the converted env vars are inert on that lane, and an identical
tree with one empty commit added passed. He also checked that
Rust (Windows ARM64)is green on main — it is not in the #1600 chronic-redset, so this is a real crash rather than a known-red lane.
The asymmetry this fixes
Three test children build the process-wide decode pool. Exactly one of them,
affinity_defer_routing_child, stops it before exiting — and its comment namesthis same
0xC0000005on native Windows ARM64 as the reason it was added. Theparity child and the realized-width child never got the same treatment, and
#1745 is reported against exactly those two.
The pool is a module-level
static, which Rust neverDrops. So those twochildren exit with workers still spinning or parked on
Arc<SharedState>, andon Windows
ExitProcessterminates them at an arbitrary instruction — includinginside a CRT or heap lock that exit-time cleanup then takes.
Applying the existing remedy to the other two is the cheapest way to find out
whether it is the same bug.
What I am not claiming
I am not claiming this is proven to be the cause. The crash is rare,
intermittent, and on a platform this workspace cannot execute; I have no
reproduction and no crash dump. This is a hypothesis with in-repo precedent.
Which is why the other half of the change exists.
Saying where it died
A #1745 report today says the child faulted and nothing else. Between process
start and its single result line the child builds a pool, runs a kernel, encodes
bytes and tears the pool down — a fault anywhere in that span produces the same
report. "Crashed doing the work" and "crashed at exit after the work" are
different bugs with different fixes, and nothing in the log separates them.
Breadcrumbs (
NXRT_CHILD_STAGE: site=… stage=…) fill that in. If the nextoccurrence shows
body-completewith nopools-stopped, the crash is insideteardown and this PR's remedy is where to look. If it shows neither, it is in
the work and this PR is a red herring. Either way the next report is worth more
than this one.
One thing I checked rather than assumed
The natural suspicion is that the detail was printed and lost — the child writes
to a pipe and dies. That is not what happens. Rust's stdout is a
LineWriteron every platform, so a newline-terminated
println!has already reached thepipe before the fault.
Verified rather than reasoned about: a child that writes one newline-terminated
line, one unterminated
print!and one flushed stderr line, thenabort()sunder
Command::output(), delivers the first and the third and loses only theunterminated fragment. So the gap is not lost output — it is that nothing is
emitted between "started" and "produced the result".
I mention it because I believed the buffering story first and wrote it into a
doc comment before testing it. It was wrong.
Why stderr, and why the order matters
Both readers of these children key on stdout by content:
is_environmental_access_violation_crashtreats the result marker's presence as"the child produced its result", and
parity_child_output_modescans stdout forthe parity payload. Extra stdout lines are a change to two lanes' red/green
semantics. Extra stderr lines are not — provided they never contain
panicked atorassertion, the only two strings that classifier reads out ofstderr. That is asserted, not assumed.
The teardown call is placed after the result marker in the two children that
never had one, so a crash inside our own teardown keeps the marker on stdout,
classifies as non-environmental, and is reported rather than retried away. A
bug in this code is not a flaky runner.
affinity_defer_routing_childkeeps its existing marker-last order. Flipping itwould change the red/green semantics of a currently-green lane, on a platform I
cannot execute, to probe a hypothesis that is not yet confirmed. Its breadcrumb
answers the same question without touching the verdict.
workers_exited, and a test that flakedreadymakes "the workers have started" an observable fact thatbuildblockson. Nothing made "the workers have stopped" observable, so the only available
evidence of a completed teardown was the absence of thread names in
/proc/self/task.My first version of the teardown test asserted exactly that — and it flaked
under load. The futex that unblocks
joinis signalled atmm_release, beforethe kernel unhashes the task, so a joined thread's
/procentry can still existwhen the next statement runs. That is a race in the instrument, and an
intermittently-red teardown test would teach precisely the wrong lesson about
intermittently-red teardown.
So the assertion moved to a counter incremented by the worker before it returns,
which is ordered by the join that observes it. The thread counts are still
printed — as a report, not an assertion. Same demotion Roy applied to the
recycled-address falsifier in #1738.
Cost: one
fetch_addper worker per process, on aDropguard so a panickingworker is counted out too.
Tests — 3 added, 6 mutations, 6 caught uniquely
assertion…invisible_to_the_crash_classifier…invisible_to_the_crash_classifiersite=…names_both_the_site_and_the_stagestage=…names_both_the_site_and_the_stageshutdownstops joiningshutdown_pools_is_a_barrier_not_a_requestshutdown_pools_is_a_barrier_not_a_requestBaseline clean. The join falsifier is probabilistic by nature — the workers
do leave, just not before the next statement — measured at 18/20 on this
host, and stated as such in the test's own doc rather than left as an implied
certainty.
shutdown_pools_is_a_barrier_not_a_requestruns in a child process becausecommtruncates at 15 bytes, so in a shared test binary another test's pool isindistinguishable from this one's — same reasoning as the existing
a_failed_build_leaves_no_workers_running. It builds withblocktime=0so theworkers are parked, not spinning: a spinning worker would drift out on the
stop flag alone, which would let a shutdown that never woke anyone pass.
Adjacent, not claimed
Roy notes the crash lands at
workers=3under the persistent pool, i.e. insidethe only path that checks realized width, and that this is uncomfortably close to
the t=2 dispatch anomaly I own. I have no evidence they are the same bug and am
not asserting it. #983 and #1672 carry the same
0xC0000005signature on otherWindows lanes and may share a root cause; #1123 (LoggingManager race) is not yet
ruled in or out.
Validation
cargo test -p onnx-runtime-ep-cpu --lib -- spmd— 97 passed, 3 ignored.cargo test -p onnx-runtime-ep-cpu --lib -- affinity_defer realized_width parity— 28 passed.cargo clippy -p onnx-runtime-ep-cpu --all-targets -- -D warnings, default and--features mlas— clean.cargo fmt --all— clean.Note
mainis currently red onFast (Linux x86_64)(
the_matrix_holds_for_every_maintained_workflow, from7a0cb6c39), which isunrelated to this change and will need to go green before this can merge through
the gate. Waiting, not bypassing.