[Bug] test_parallel_wall_time: forked workers run near-serially on macOS CI (~2% of runs)

[ChaoWao]

Platform

All / Unknown

Runtime Variant

All / Unknown

Description

tests/ut/py/test_hostsub_fork_shm.py::TestParallelExecution::test_parallel_wall_time fails on macOS CI in roughly 2% of runs (4 of 218 sampled ut (macos-latest, 3.10) jobs over Jul 20-26; 0 of 101 Ubuntu jobs).

The test forks 3 workers, dispatches a time.sleep(0.2) callable to each, and asserts the wall time is under 80% of fully-serial.

This is not a marginal threshold. Measured on aarch64 Linux over 7 consecutive runs:

	elapsed
ideal parallel	0.200 s
Linux actual	median 0.203 s, max 0.204 s
assertion threshold	0.480 s
macOS when failing	0.49 - 0.57 s
fully serial	0.600 s

Linux lands 1.5% above ideal with a 2 ms spread. The macOS failures are 2.5-2.9x that, and 85-95% of fully serial — parallelism essentially did not happen. Raising the threshold would silence exactly the signal this test exists to produce.

Steps to Reproduce

python -m pytest tests/ut/py/test_hostsub_fork_shm.py::TestParallelExecution::test_parallel_wall_time

Only observed on macOS runners, ~1 in 50. I have no macOS box and could not reproduce it; everything below is from CI logs plus controlled Linux experiments.

Expected Behavior

Three children that each only time.sleep(0.2) finish in ~0.2 s wall time, as they do on Linux.

Actual Behavior

expected parallel wall time < 0.48s (serial would be 0.60s), got 0.57s

Git Commit ID

b28bd58

CANN Version

N/A (pure-Python unit test, no NPU)

Driver Version

N/A

Host Platform

macOS (aarch64)

Additional Context

Ruled out, with the evidence:

• Not the product's worker code. _SubWorkerPool and its _worker_loop are defined locally in the test file; it never imports simpler.worker. Neither Refactor: fold the three child mailbox loops into one state machine #1494 (unifying the child mailbox loops) nor Fix: exit a forked worker child once its parent is gone #1495 (parent-death detection) can affect it.
• Not a different flake's twin. Fix: give each process its own counter slot in test_l4_sub_and_l3_dispatch #1490 fixed a separate macOS-only failure in test_l4_sub_and_l3_dispatch (a lost update on a shared counter). Unrelated mechanism, unrelated file.
• Not CPU scarcity, which was my leading hypothesis. The test's _worker_loop is a deliberate tight spin (# tight spin (same as L2 AICPU spin-wait — no yield)), so I expected 3 spinning children plus the parent to oversubscribe a narrow runner and starve the parent between its three sequential dispatch() calls. Pinning the test to 2 and to 3 cores with taskset on Linux gives 5/5 passes at each width. The mechanism does not hold: during the 0.2 s work window the children are inside time.sleep() and consume no CPU, so only the parent needs a core.
• Not fork cost. The pool is constructed before start = time.monotonic().

Still unknown — and not resolvable without a macOS runner:

• The runner's actual core count. No CI log line reports it.
• Whether macOS thread QoS / scheduler behaviour deprioritises a process that has been spinning, delaying the parent's 2nd and 3rd dispatch() by ~0.2 s each. This is the shape the numbers suggest (near-serial = each worker starting a full sleep-period late), but I have no way to observe it.

Please do not "fix" this by relaxing the threshold or adding a retry. At 0.49-0.57 s against a 0.203 s Linux baseline, something is serialising three sleeping processes. A wider bound makes the symptom disappear while leaving whatever does that in place.

A cheap first step for whoever has a macOS machine: print os.cpu_count() and per-worker dispatch/completion timestamps from the test, then read which of the three workers started late.

[ChaoWao]

#1503 makes the next occurrence self-diagnosing without touching the assertion.

The total wall time cannot separate the two shapes this could be — parent descheduled between its three sequential dispatch() calls (later workers start a sleep period behind), versus every worker dispatched on time and finishing late. Those are different bugs with an identical total. The failure message now carries each worker's dispatch and completion offset plus the visible CPU count, so the next macOS failure answers it from the CI log alone.

Healthy shape, for comparison when reading a future failure:

cpu_count=320 affinity=320
w0: dispatched +0.1ms, done +200.6ms, w1: dispatched +0.1ms, done +200.6ms, w2: dispatched +0.1ms, done +204.5ms

Status of the investigation itself: still open, still blocked on a macOS machine. What is settled:

• Not a marginal threshold. 0.49-0.57 s against a 0.203 s Linux median (max 0.204 s over 7 runs) is 85-95% of fully serial.
• Not the product's worker code. _SubWorkerPool is defined in the test file and never imports simpler.worker, so Refactor: fold the three child mailbox loops into one state machine #1494, Fix: exit a forked worker child once its parent is gone #1495 and Update: forbid sleeping on the dispatch path, and stop sleeping on it #1499 cannot touch it.
• Not CPU scarcity, which was the leading hypothesis. Pinned to 2 and to 3 cores with taskset on Linux: 5/5 passes at each width. During the 0.2 s window the children are inside time.sleep() and consume no CPU, so only the parent needs a core.
• Not fork cost — the pool is constructed before the timer starts.

Open: the runner's real core count, and whether macOS thread QoS deprioritises a process that has been spinning. Neither is observable from here.

I am not planning further work on this without a macOS runner; forcing the failure from Linux has been tried and does not reproduce. #1503 is the last thing that can usefully be done blind.

[ChaoWao]

Closing the loop on the "blocked on a macOS machine" status.

I now have a macOS box, and the picture changed:

Condition (bare-metal M4, 10 cores)	Result
Baseline / 3-core sim (7 CPU hogs)	0 failures; perfectly parallel (~201 ms)
taskpolicy -b (background QoS) + 7 hogs	0 failures — but time.sleep(0.2) itself inflated to 234–310 ms; workers stayed parallel

• No code defect — the pool achieves genuine parallelism on real macOS under conditions harsher than the 3-core GHA runner.
• Not reproducible on bare metal — specific to the virtualised GHA macOS runner.
• The real trigger the issue only guessed at: under load, macOS time.sleep over-sleeps (timer coalescing), which alone inflates a correctly-parallel run past the 0.48 s bound — without any serialisation.

Resolution (#1509): the wall-clock assertion elapsed < 0.8·serial is a proxy for concurrency that polices the host scheduler/timer, not the code — so it's dropped, the case keeps only its functional checks (renamed test_multi_worker_dispatch), and the principle is codified in docs/testing.md: off-hardware tests must not assert wall-clock magnitude as a proxy for a non-temporal property. This is the second instance of the pattern — the first was already dropped in test_host_worker.py (TestParallelSubWorkers).

Fix is in #1509; will auto-close this issue on merge.

[ChaoWao]

Correction to my earlier comment — it over-claimed.

The measured macOS time.sleep inflation (0.2 s → 0.24-0.31 s, 1.2-1.55x) is not large enough to explain CI's 0.49-0.57 s for three parallel sleeps (that needs ~2.5-2.9x), and the failure still did not reproduce on bare metal. So "not a code defect" is not established — the root cause (worse inflation on the GHA VM vs. partial serialisation) remains open. This issue stays open.

PR #1509 is revised accordingly: instead of dropping the assertion, it replaces the wall-clock magnitude bound with a relational interval-overlap check (workers report their work windows; assert the three overlap). That is immune to timer inflation but fails under serialisation — so if it flakes on the macOS runner, that is direct evidence for serialisation, which is the open question here. Refs #1496, not Fixes.

[ChaoWao]

Frequency check, because the working assumption was drifting toward "this barely happens any more". It does still happen, and it is landing on other people's PRs.

ut (macos-latest, 3.10) jobs sampled, Jul 20-26	218
test_parallel_wall_time failures among them	4 (~1.8%)
ut (ubuntu-latest, 3.10) jobs sampled	101
failures among them	0
most recent occurrence	2026-07-27T01:58Z — got 0.54s

The latest one was on add-mx-fp8-fp4-dtypes, a PR adding FP8/FP4 dtype support. Nothing to do with fork, shared memory, or scheduling. So the standing cost is a ~2% chance of a red check on unrelated work, plus whatever time that author spends deciding whether it is theirs.

Worth separating two recent macOS ut failure modes, because they were being conflated: of the four most recent failures on that job, three were test_orphan_child_reaping (a defect of mine, deterministic in CI, fixed in #1504) and one was this test. Only the latter is #1496.

got 0.54s also matters on its own: it is the same 0.49-0.57 s band as every earlier occurrence. It has not drifted toward the threshold over time, which is what a marginal-bound problem would look like. Whatever produces it produces the same magnitude every time — and that magnitude is still roughly double what the measured time.sleep inflation (0.24-0.31 s) can account for.

#1509 replaces the assertion with a mutual-overlap check on the workers' [begin, end] windows. That is relational rather than a magnitude bound, so timer inflation cannot trip it, while any actual serialisation will. If it flakes on the macOS runner after that lands, this issue has its answer — direct evidence of serialisation, which is more than the original investigation produced. Reopen with that failure attached rather than filing fresh.

Keeping this open until the macOS job has run the new assertion.