CI: `Plain unittest ordering (protocols)` doubled and now cancels at its 45-minute cap on `main`

[JarryShaw]

Plain unittest ordering (protocols) has roughly doubled and now hits its 45-minute cap on main itself, so the leg is cancelled on every run rather than reporting a result. It is not a required check — the required contexts are the five Compat Python 3.x legs plus Required checks passed — so merges are not blocked, but the leg currently tells us nothing.

The break is sharp and sits between 07:48Z and 10:49Z on 2026-10-05. Durations of that one job across consecutive runs:

run created	branch	head	result	duration
03:05Z	fix/1021-...	9f8b774ac	success	22.5m
03:44Z	main	5fd0a1b11	success	27.0m
04:05Z	main	fa3e861f5	success	20.8m
04:32Z	fix/1021-...	1f24b9aa9	success	21.5m
06:36Z	docs/1024-...	8ae0d5eed	success	22.7m
07:48Z	docs/1024-...	983fb92a0	success	22.6m
10:49Z	main	cacbf2e70	cancelled	45.3m
10:50Z	main	aa5f01213	cancelled	55.0m
11:19Z	main	51100da7e	cancelled	45.4m
11:27Z	fix/1021-...	39a4c4d8f	cancelled	45.4m
11:37Z	fix/1026-...	467eced4d	cancelled	47.1m

It is the leg, not the runners. On main 51100da7e (bad) against main fa3e861f5 (good), every sibling leg is flat and only protocols moved:

leg	good 04:05Z	bad 11:19Z
protocols	20.8m	45.4m (cancelled)
const	5.6m	6.2m
foundation	5.5m	5.5m
toolkit	2.3m	1.8m
the other six	1.3–1.9m	1.1–1.7m

foundation being unchanged matters: it is the leg that exercises Extractor.

On cause, I have been wrong in both directions and am not asserting one now. I first attributed the slowdown to #1020 (which was the only slow branch at the time), then withdrew that after a profiling pass found identical cProfile call counts — 3,303,238 on both sides — and showed the new registrars run zero times per extract. That profiling was honest but narrow: it covered single extract calls and two test modules, never the whole leg in one process, because this host OOM-killed a 56 GB tests/protocols run. The before/after boundary does bracket #1020 and #1027 merging, so #1020 is back in scope — but a cumulative, whole-leg effect is precisely what was never measured, and the local evidence against a per-extract cost still stands.

What would settle it: run the full protocols selection on main fa3e861f5 and on main 51100da7e, in memory-bounded chunks summed to a total, and compare. If the totals match, the cause is CI-side and the fix is the leg's budget or its sharding; if post-#1020 is ~2x, it is cumulative and belongs in the code.

Either way the leg needs to stop silently cancelling — a timeout-minutes cut produces no summary line at all, so a real failure inside it would currently be invisible.

[JarryShaw]

Two refinements to the evidence above, and a decisive experiment now running.

1. "Cancelled" has three causes here, not two, and the third is easy to mistake for a regression. Alongside a timeout-minutes kill and a runner shutdown there is cancelled-because-superseded: the protocols leg on 55dc55b4b was cancelled at 16.5 minutes — nowhere near the cap, no shutdown line — because a force-push replaced that head and GitHub cancelled the run. So before reading any cancellation as a timeout, check whether its sha is still the branch head. Every cancellation in the table above is 45m+ on a sha that was current when it ran, so the conclusion stands; this is to stop a later reader drawing a trend line through a supersede.

2. statusCheckRollup timestamps are not job timings. I briefly mis-stated a duration from statusCheckRollup.startedAt, which is the check-run's creation time and runs ahead of execution — it gave 46 minutes for a job the Actions jobs API put at 41.7. Every figure in the table above came from repos/.../actions/runs/<id>/jobs, which is the authoritative source; the rollup is fine for pass/fail tallies and wrong for durations.

3. The experiment that separates the two hypotheses, without needing any local reproduction: I have re-run the old protocols job from main fa3e861f5 — the run that passed in 20.8m at 04:05Z — as attempt 2, started 14:17:54Z. Same commit, same workflow, today's runners.

• If it lands in the 18–27m band, the code is exonerated and the cause is CI-side; the fix is this leg's budget or its sharding.
• If it takes ~45m and cancels, the runners have slowed and no code change is implicated at all.

Either outcome is conclusive in a way the before/after table is not, because it holds the code constant and varies only the date. A local chunked comparison across the two commits is also in progress, but this is the cheaper discriminator and I should have reached for it first.

[JarryShaw]

Resolved: this was a transient CI window, not a code regression. No code change is implicated, and I was wrong to point at #1020 in the first place.

The experiment settles it, and a second row settles it harder. Durations of this one job, all from the Actions jobs API:

created	branch	head	result	duration
06:36Z	docs/1024-…	8ae0d5eed	success	22.7m
07:48Z	docs/1024-…	983fb92a0	success	22.6m
10:49Z	main	cacbf2e70	cancelled	45.3m
10:50Z	main	aa5f01213	cancelled	55.0m
11:19Z	main	51100da7e	cancelled	45.4m
11:27Z	#1025	39a4c4d8f	cancelled	45.4m
11:37Z	#1028	467eced4d	cancelled	47.1m
13:20Z	#1028	0475f2044	cancelled	45.4m
13:52Z	#1030	0e6e5f3cf	success	24.6m
14:17Z	main fa3e861f5 re-run	—	success	30.4m

The two bottom rows kill every code-based explanation. 0e6e5f3cf carries everything merged — #1020, #1027 and the Application loosening — and finished in 24.6m. The re-run of the old pre-#1020 fa3e861f5, twenty-five minutes later, took 30.4m. So the newest code ran faster than the oldest code, and the cancellations form a time window of roughly 10:49Z to 13:20Z rather than a boundary at any commit.

I had been about to publish a decomposition — "runners ~46% slower, code adds ~50% on top" — built on the 20.8m-versus-30.4m pair alone. The 24.6m success refutes it, and I only caught that by re-deriving the whole table instead of citing the two numbers I had in hand. Recording the near-miss because the arithmetic was persuasive and wrong.

What remains actionable is headroom, not a defect. Even on a quiet runner this leg is the longest by an order of magnitude — 30.4m against a 45-minute cap, with the next-slowest sibling at 6.2m — so any transient slowdown breaches it and the leg reports nothing at all. A timeout-minutes cut produces no summary line, so a genuine failure inside it would currently be invisible. Raising the cap or sharding the selection are both defensible; sharding also fixes the invisibility, since a shorter leg that cancels loses less.

Relabelling wip → pending: the investigation is finished and nobody is on the remaining decision. I am not closing it, because the headroom problem is real and outlasted the window.

[JarryShaw]

A local measurement found a real, reproducible 1.36x slowdown in this leg — and it does not transfer to the runners, which is why the CI verdict above still stands. Both halves matter and they are separate effects.

Local, on this host, util/run_unittest_leg.py protocols exactly as CI invokes it, four alternating sequential runs:

tree	total	peak RSS
fa3e861f5	991.8s / 998.0s	1.68 GB
51100da7e	1351.8s / 1347.5s	5.65 GB

Mean 994.9s → 1349.6s = 1.357x, within-tree variance 0.3–0.6%, 983 tests and 0 failures both sides, and the good side ran under heavier residual load — biasing against the finding. Peak RSS 3.36x.

Mechanism: gen-2 garbage collection. On a 262-test prefix the +51.6s gap is +42.4s of GC (82%), over fewer collections (201 vs 213) each costing more against a larger live heap — 0.750s vs 0.512s per collection.

Bisected to one file. 51100da7e with only the old extraction.py swapped in returns to 261.7s and gen-2 lands on exactly 213 collections, matching the good tree within 0.3%. The other five changed files contribute nothing.

Why this does not explain the CI cancellations, verified rather than assumed. The measurement agent flagged that 0e6e5f3cf — the 24.6m success I leaned on above — must postdate #1025's own extraction.py change and therefore could not exonerate the file. I checked, and that flag is wrong: 0e6e5f3cf forked from 51100da7e before #1025 merged, and its extraction.py is byte-identical to the slow one (md5 2fb5295b888c, 1446 lines, against #1025's 3bd7d4418f52 at 1454). So 0e6e5f3cf ran precisely the code measured as slow here and finished in 24.6m on a runner. The local effect is a GC tipping point — heap-, host- and interpreter-dependent — and it does not reproduce on GitHub's runners.

Two corrections to my own constraints, both of which shaped how this was investigated:

• The 56 GB OOM was pytest-specific. The unittest leg peaks at 1.7 GB / 5.7 GB in one process, so the whole-leg measurement I had been treating as unaffordable was affordable throughout, and the chunking I insisted on was unnecessary for this harness.
• purge_modules is not the cost I suspected. 628 calls across 983 tests, but the purge itself totals 0.29s, and a full purge-plus-import cycle is 0.849s (good) against 0.839s (bad) — identical, marginally faster on the slow tree. So the re-import path is exonerated as the regression mechanism, while remaining the leg's single largest absolute cost at roughly 59% by arithmetic.

The sharding answer, which is what this issue actually needs: protocols/internet is 443.2s of 991.8s — 44.8% of the leg, with misc second at 16.6% and nothing else above 8.5%. Splitting internet off roughly halves the longest shard.

Left unmeasured, and it is the whole question of whether the local effect is a defect: the within-extraction.py bisect. Nobody has tested whether the cause is the three issubclass guard swaps or merely the file's extra 87 lines shifting GC scheduling. "extraction.py carries it" must not be read as "#1020's guard change causes it". Also untested: whether #1025's later extraction.py change moves the effect either way.

[JarryShaw]

The split in #1032, measured on CI. Job durations are from actions/runs/<id>/jobs (started_at / completed_at), not statusCheckRollup.

leg	#1031, run 37334173854 (unsharded)	#1032, run 37341197811 (sharded)
protocols	27.8m	—
protocols/internet	—	8.2m
protocols (rest)	—	7.6m
foundation (control)	6.2m	6.4m
const (control)	6.0m	6.1m

The two runs are an hour apart on the same day, and the controls agree within 0.2m. I compared against 27.8m rather than this issue's 30.4m because the investigation above put 30.4m in a slow CI window. The slowest cell drops to 8.2m, which leaves about 37m of headroom under the 45m cap.

Not explained yet: the two shards together use 15.8m of runner time, 57% of the single leg. They do more work, since each one re-runs the five root modules. That fits a long process slowing down as state builds up, and the local 1.36× GC effect above, but I haven't profiled it. Treat it as an inference.

[JarryShaw]

Correction to my comment above. I wrote that this issue's investigation placed 30.4m in a slow CI window. It says the reverse. The slow window was about 10:49Z–13:20Z, when runs were cancelled at 45.3m and up. 30.4m is the 14:17Z re-run after that window, and the resolution comment cites it as the quiet-runner figure.

So 27.8m and 30.4m are both quiet-runner readings, and either works as a baseline. The slowdown seen in the window was at least 45.3/27.8 ≈ 1.6x. At that rate the sharded 8.2m cell would take about 13m, still well under the 45m cap. A cross-review on #1032 caught this.