From 9208eff20b6667d959830b1ffe37d334a60775cf Mon Sep 17 00:00:00 2001
From: Chao Wang <26245345+ChaoWao@users.noreply.github.com>
Date: Sun, 26 Jul 2026 08:16:50 -0700
Subject: [PATCH] Add: per-worker timeline to the parallel wall-time assertion
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

`test_parallel_wall_time` fails on macOS CI in ~2% of runs (4 of 218
sampled jobs; 0 of 101 on Ubuntu) with a total wall time of 0.49-0.57 s
against a 0.203 s Linux median. That is near-serial, not a marginal
threshold, but the assertion reports only the total — which cannot
distinguish "the parent was descheduled between its three sequential
dispatch() calls, so later workers started a full sleep period behind"
from "every worker was slow".

Record each worker's dispatch and completion offset and include them,
plus the visible CPU count, in the failure message. On the next
occurrence the timeline reads the answer directly instead of leaving it
to be inferred.

The assertion itself is unchanged. At 0.49-0.57 s against a 0.203 s
baseline something is serialising three sleeping processes, so widening
the bound would hide the signal this test exists to produce.

`sched_getaffinity` is Linux-only, hence the guard: `cpu_count()` alone
can overstate what a container actually lets the process run on, and the
runner's real width is one of the unknowns in #1496.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
---
 tests/ut/py/test_hostsub_fork_shm.py | 22 +++++++++++++++++++++-
 1 file changed, 21 insertions(+), 1 deletion(-)

diff --git a/tests/ut/py/test_hostsub_fork_shm.py b/tests/ut/py/test_hostsub_fork_shm.py
index 372da6bb71..5f136dd54d 100644
--- a/tests/ut/py/test_hostsub_fork_shm.py
+++ b/tests/ut/py/test_hostsub_fork_shm.py
@@ -300,19 +300,39 @@ def test_parallel_wall_time(self):
         pool = _SubWorkerPool(num_workers=n_workers, registry=registry)
 
         try:
+            # Per-worker timestamps, so a failure says *which* worker ran late
+            # rather than only that the total was too high. Workers are
+            # dispatched in a loop, so if the parent is descheduled between
+            # iterations the later workers start a full sleep period behind —
+            # a shape the total alone cannot distinguish from every worker
+            # being slow. See #1496.
+            dispatched: list[float] = []
+            completed: list[float] = []
+
             start = time.monotonic()
             for i in range(n_workers):
                 pool.dispatch(i, i)
+                dispatched.append(time.monotonic() - start)
             for i in range(n_workers):
                 result, err = pool.wait(i, timeout=5.0)
+                completed.append(time.monotonic() - start)
                 assert err == 0
                 assert result == int(sleep_sec * 1000)
             elapsed = time.monotonic() - start
 
             serial_time = n_workers * sleep_sec
+            timeline = ", ".join(
+                f"w{i}: dispatched +{dispatched[i] * 1000:.1f}ms, done +{completed[i] * 1000:.1f}ms"
+                for i in range(n_workers)
+            )
+            # macOS has no sched_getaffinity; cpu_count alone can overstate what
+            # a container actually lets this process run on.
+            affinity = len(os.sched_getaffinity(0)) if hasattr(os, "sched_getaffinity") else "n/a"
             assert elapsed < serial_time * 0.8, (
                 f"expected parallel wall time < {serial_time * 0.8:.2f}s "
-                f"(serial would be {serial_time:.2f}s), got {elapsed:.2f}s"
+                f"(serial would be {serial_time:.2f}s), got {elapsed:.2f}s\n"
+                f"cpu_count={os.cpu_count()} affinity={affinity}\n"
+                f"{timeline}"
             )
         finally:
             pool.shutdown()