CI node runs jobs at ~31x local under concurrency; a 1.5s production broker deadline is missing because of it #1349

Open
opened 2026-08-21 00:19:44 +00:00 by fred · 0 comments
Collaborator

Attribution

Diagnosed by @fargo while debugging #1297's CI reds. Filed by @fred as an infrastructure
defect in its own right: it is not a property of that PR and #1297 must not wait on it.

The finding

The CI node runs some jobs at roughly 31x their local wall time under concurrency, and at
least one production timeout is tight enough to miss because of it.

Measured in pipeline 2587 (04a87262, mosaicstack/stack, event pull_request):

Job CI Local Ratio
gateway app.module 100,081 ms 3,227 ms 31x

That job passed. It passed because #1138 had already raised its ceiling to 120 s, so it
finished with under 20 s of headroom. Nothing reports a job that consumed 83% of its timeout.

What it broke in the same run

launch-runtime.py's register_anchor was DENIEDMosaic lease broker registration failed, exit 1 against an expected 0 — in the mutator-gate acceptance test (yolo claudex).

BROKER_TIMEOUT_SECONDS = 1.5 (launch-runtime.py:27). A python select-loop daemon on a node
demonstrating a 31x slowdown missing a 1.5 s deadline is consistent with the meter above.

Boundary — what is and is not proven

Proven:

  • A different test fails on each red. 2578 was gateway app.module timeout +
    KeyboardInterrupt; 2587 was the broker registration above. These are not one flaky test.
  • Every instance has coincided with an overlapping pipeline. 2586 (next publish, build-gateway)
    overlapped 2587's entire test window.
  • Local reproduction fails: 5/5 single runs green, full file green, full file green under 4x-core
    oversubscription. The miss is CI-node-specific.

Not proven: the deadline miss itself. Nobody has instrumented the broker RPC on the CI node
and watched it exceed 1.5 s.

Why this is filed rather than worked around

The available workaround is to raise BROKER_TIMEOUT_SECONDS from 1.5 s to 5 s. Refused.
That is a production fail-fast knob, not a test knob. Changing what the broker promises under
real load, in order to stop a CI node complaining, is a production semantics change bought with
test convenience. If 1.5 s is the wrong deadline it is wrong on its own evidence, in its own PR.

Relationship to other issues

Same node-capacity family as Q1 and #1344 (ci-queue-wait --purpose merge is trunk-blind,
so nothing serialises these overlaps). This issue is the measured cost of that gap.

Suggested direction

  1. Report timeout headroom. A job at 83% of its ceiling is a warning today and a red
    tomorrow. Nothing currently surfaces it.
  2. Instrument the broker RPC on the CI node to convert the unproven half above into
    evidence, before anyone argues about the 1.5 s value.
  3. Serialise, or size the node. Every instance so far has had an overlap. #1344 is the
    first line of defence.

Evidence

/tmp/t2587.log and /tmp/t2578.log on sb-it-1-dt; epochs in @fargo's phase-D notes on the
brain. A serialized retry of 04a87262 on a drained queue is running as pipeline 2588
if it is red, the concurrency explanation is dead, because a drained queue removes the overlap
every instance has had.

## Attribution Diagnosed by **@fargo** while debugging #1297's CI reds. Filed by **@fred** as an infrastructure defect in its own right: it is not a property of that PR and #1297 must not wait on it. ## The finding The CI node runs some jobs at roughly **31x** their local wall time under concurrency, and at least one production timeout is tight enough to miss because of it. Measured in pipeline **2587** (`04a87262`, `mosaicstack/stack`, event `pull_request`): | Job | CI | Local | Ratio | |---|---|---|---| | gateway `app.module` | **100,081 ms** | 3,227 ms | **31x** | That job **passed**. It passed because #1138 had already raised its ceiling to 120 s, so it finished with under 20 s of headroom. Nothing reports a job that consumed 83% of its timeout. ## What it broke in the same run `launch-runtime.py`'s `register_anchor` was **DENIED** — `Mosaic lease broker registration failed`, exit 1 against an expected 0 — in the mutator-gate acceptance test (`yolo claudex`). `BROKER_TIMEOUT_SECONDS = 1.5` (`launch-runtime.py:27`). A python select-loop daemon on a node demonstrating a 31x slowdown missing a 1.5 s deadline is consistent with the meter above. ## Boundary — what is and is not proven **Proven:** - A **different test** fails on each red. 2578 was gateway `app.module` timeout + `KeyboardInterrupt`; 2587 was the broker registration above. These are not one flaky test. - Every instance has coincided with an overlapping pipeline. 2586 (next publish, build-gateway) overlapped 2587's entire test window. - Local reproduction fails: 5/5 single runs green, full file green, full file green under 4x-core oversubscription. The miss is **CI-node-specific**. **Not proven:** the deadline miss itself. Nobody has instrumented the broker RPC on the CI node and watched it exceed 1.5 s. ## Why this is filed rather than worked around The available workaround is to raise `BROKER_TIMEOUT_SECONDS` from 1.5 s to 5 s. **Refused.** That is a production fail-fast knob, not a test knob. Changing what the broker promises under real load, in order to stop a CI node complaining, is a production semantics change bought with test convenience. If 1.5 s is the wrong deadline it is wrong on its own evidence, in its own PR. ## Relationship to other issues Same node-capacity family as **Q1** and **#1344** (`ci-queue-wait --purpose merge` is trunk-blind, so nothing serialises these overlaps). This issue is the measured cost of that gap. ## Suggested direction 1. **Report timeout headroom.** A job at 83% of its ceiling is a warning today and a red tomorrow. Nothing currently surfaces it. 2. **Instrument the broker RPC on the CI node** to convert the unproven half above into evidence, before anyone argues about the 1.5 s value. 3. **Serialise, or size the node.** Every instance so far has had an overlap. #1344 is the first line of defence. ## Evidence `/tmp/t2587.log` and `/tmp/t2578.log` on `sb-it-1-dt`; epochs in @fargo's phase-D notes on the brain. A serialized retry of `04a87262` on a drained queue is running as pipeline **2588** — if it is red, the concurrency explanation is dead, because a drained queue removes the overlap every instance has had.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: mosaicstack/stack#1349