Commit ffec094
authored
ci: the margin table was wrong twice — re-measure the pool, and size the job cap from maxima (#138)
* ci: the margin table in #131 was wrong in every row, and the job cap had already fired
#131 replaced a "~2x headroom" claim with a measured table. The table was
itself wrong -- every row, each in the safe-looking direction -- and the job
cap it left in place was already negative.
MEASURED over all 101 CI runs created 2026-08-01 (`gh api --paginate`),
timing each leg's `Tests (pytest)` STEP and filtering on the STEP's own
conclusion:
leg claimed true (n) old cap true margin
ubuntu-latest 12:27 12:31 (n=57) 19:00 1.518x
windows-2022 18:39 21:34 (n=52) 26:00 1.206x
windows-2025 24:35 25:51 (n=49) 26:00 1.006x
Nine seconds, not 85. Two mechanical causes, both cheap to repeat:
* THE POOL WAS A PAGE, NOT A QUESTION. It came from `gh run list --limit
20` -- a default-sized listing reported as though the sample had been
chosen. 20 of 101.
* FILTERING ON *JOB* CONCLUSION DROPS THE TIGHTEST STEPS BY CONSTRUCTION.
A step near step_timeout is the one most likely to push its job into
job_timeout, so the job is cancelled while the step concluded success.
Five such rows exist that day and they include the maximum.
Only the windows-2025 row was ever a maximum; ubuntu's and windows-2022's
figures were that same run's other two legs.
AND THE TWO-GATED-STEPS HAZARD IS NOT LATENT -- IT FIRED. Both `Tests
(pytest)` and `Web console tests (pytest)` carry `step_timeout`, so a job can
hold 2x step_timeout of gated work that step_timeout cannot bound. Run
30724385719 (main @ 8f01cef):
Tests (pytest) 25:51 SUCCESS (9s under the 26:00 cap)
Web console tests (pytest) CANCELLED
JOB 30:13 CANCELLED <- job_timeout 30 fired
A green first step, then an unattributed job-level kill during the second --
precisely what ci.yml:218's nesting note exists to prevent, by the path it
does not consider. It cannot happen when a step is KILLED (that ends the job
and skips what follows), only when the first step PASSES near its budget.
Sizing job_timeout to hold both gated steps plus setup, rather than
step_timeout plus a constant:
leg step + web(max) + overhead old job new job
ubuntu 19:00 + 1:58 + 0:41 = 21:39 22:00 +21s 26:00 +4:21 (1.20x)
W22/W25 36:00 + 3:27 + 0:41 = 40:08 40:00 -8s 46:00 +5:52 (1.15x)
All three legs sat inside a minute of their job cap and Windows was already
negative: the +4 convention was carried through two cap changes without
anyone summing what it had to cover.
The 36:00 step decision is unchanged and remains correct -- 1.393x over the
true 25:51 maximum, still comfortably above the 5:26 observed spread. Only
its justification moves.
Found by the ADR 0158 verification pass (eight agents re-deriving every
claimed number against the API; 50 claims checked, 6 refuted), reported by
the intersession-communication-hooks session, and re-derived here before
acting. BACKLOG #344 still restates the superseded figures; that edit is
blocked on three live sessions holding docs/BACKLOG.md and follows separately.
* docs: handoff for ci-margin-correction
Written at the owner's stop-work instruction (usage cap). Chat does not
survive; a claim that lives only in a transcript reaches nobody.
Carries: #138's state and its SQL Server blocker (NOT called a flake --
unproven), the corrected margin table, four retractions of my own findings
with their corrected forms, and seven traps stated as fact-plus-measurement.
The load-bearing line: the cap raise in #131 is correct and unchanged; its
justification was wrong in every row, and #138 fixes it.
* ci: re-measure the margin table a third time, and size the job cap from maxima
The correction in this PR fixed #131's maxima but repeated #131's own failure
mode in a new place: it reported a pool and an n that its stated pool cannot
produce. Two independent re-derivations agree the day holds 70 ci.yml runs, not
101, and per-leg n = 42 / 39 / 36, not 57 / 52 / 49. The three MAXIMA
(12:31 / 21:34 / 25:51) re-derive to the second and are unchanged, so the
36:00 step / 46:00 job decision stands on the same numbers it always did.
What actually changed:
* POOL AND n. 70 runs created 2026-08-01 UTC, cross-checked four ways;
n = 42 / 39 / 36. A table whose own point is "state your pool and your n"
has to carry an n the next reader can recompute.
* THE POOL IS RIGHT-CENSORED, and nothing said so. Every run in it predates
#131 (28d186b, 2026-08-02T00:35:28Z), so each observation survived a 26:00
cap. 25:51 is the largest step that FIT, not the largest the suite wants, and
a multiple of a censored maximum under-provisions by construction. This is
why 1.06x read as survivable right up to the moment #119 died.
* THE JOB-CAP ADDENDS WERE TYPICAL VALUES, NOT MAXIMA. 0:41 is the median
setup; the web-console figures 1:58 / 3:27 are each only third-highest on
their leg. Measured maxima are 2:00 / 2:33 / 3:33 (web) and 1:20 / 1:09 /
1:04 (setup). Re-summed, ubuntu was -0:20 and Windows -0:37 against the old
caps: BOTH were already negative, not just Windows.
* THE NESTING INVARIANT IS NOT RESTORED, and now says so. It holds for
`Tests (pytest)` on every leg and for `Web console tests (pytest)` on none:
reaching that step already spends setup plus `Tests`, so its own cap can
never fire first. A hang there still surfaces as an unattributed job kill.
Stating otherwise would rest a compensating control on a false premise.
* The "5:26 spread ... identical code" claim is withdrawn; neither endpoint
re-derives. The true in-pool spread is 9:55, which is wider and supports the
decision more strongly than the figure it replaces.
Also corrects three pre-existing claims in this file that match no
configuration -- the same defect class this note is about:
- the pytest step's cap described as `timeout-minutes: 13` (it is
matrix.step_timeout, 19 or 36)
- "the 15-min job cap" (it is matrix.job_timeout, 26 or 46)
- the mechanical margin guard cited as BACKLOG #341, which does not exist on
main; it is #344 item 1
Drops HANDOFF-ci-margin-correction.md: session ephemera, and no HANDOFF file
has ever been tracked at the repo root on main.
* ci: mark the job-cap exhibit as mechanism, not verdict
Run 30724385719 ran under the retired 26/30 pair and would have passed under
#131's 40:00. It demonstrates that two steps sharing one step_timeout lets the
job cap fire behind a green step; it is not itself evidence that 40:00 is too
tight. That case rests on the arithmetic, which is arithmetic -- no job has
been observed hitting 40:00.
* backlog: correct #344's own figures, and file the job cap as instance 3
#344 is the item about bounds stated independently of the work they bound. Its
instance 1 still carried the retracted measurement -- 24:35 over "11 runs",
1.06x, raised to "1.46x" -- every figure of which was superseded, and the edit
had been outstanding since it was filed.
Instance 1 now reads 25:51 / 1.006x / 1.393x, and carries its pool (70 ci.yml
runs created 2026-08-01 UTC; per-leg n = 42 / 39 / 36) so the next reader can
recompute it rather than trust it.
Adds two things the re-measurement turned up:
* INSTANCE 3 -- the CI job cap. Two steps in that job carry step_timeout, so
job_timeout must cover their sum, and the +4 convention that sized it was
never summed against what it had to hold. Recomputed from measured maxima,
ubuntu was -0:20 and windows-2025 -0:37: both already underwater. It presents
as a GREEN first step followed by an unattributed job-level kill, which is a
signature instance 1's own proposed margin check would not catch, because the
step it measures passed.
* THE CENSORING TRAP. A max-passing figure is a LOWER BOUND: the pool is
censored by whatever cap was in force when it was collected, so the runs that
would have exceeded it were killed and are missing from exactly the tail being
measured. This is why 1.006x looked survivable until #119 died.
Proposal 5 records the structural fix instance 3 does not make: give the
web-console step its own cap, because until then ci.yml's nesting invariant is
unenforceable for the second gated step on every leg.
Banner moves from "not started" to PARTIAL -- instances 1 and 3 are fixed,
instance 2 is not. One banner, still OPEN.
Also records, once, that instance 1's figures have now been published wrong
twice; the maxima survived both passes and the pools did not.
* ci: fix what the verification pass found in my own correction
Nine agents re-derived this block; two re-derived the table from scratch under
instructions to refute it. They confirmed every figure in the step table and
refuted six things written around it. Fixing my own text, since the whole point
of this change is not to ship a third unchecked table.
* 26:07 EXISTS, and I said it did not. It is in this very pool -- run
30717229521 attempt 1, sha 8c407fb, step conclusion FAILURE, killed at the
26:00 cap -- hidden because the jobs endpoint defaults to `filter=latest`,
which returns only the passing attempt-2 re-run. Same filter hid seven
same-commit pairs, so the "no identical-code spread is computable" claim was
also wrong. `?filter=all` shows both.
* THE SPREAD RULE IS NOT MET, and I claimed it was. The first day after the
raise produced 26:23 TWICE, both concluding SUCCESS -- uncensored evidence
that the population exceeds the old 26:00 cap. Against 26:23 the headroom is
9:37 and the spread 10:27, so "headroom must exceed observed spread" FAILS at
36:00; it would need ~37:00. 36:00 is kept and the reason is now stated
plainly -- this cap catches a deadlock, not slowness, and 1.365x over the
worst observed run is ample for that -- rather than the rule being asserted as
satisfied. Re-derive if a windows-2025 step is ever seen above 28:00.
* WINDOWS setup(max) IS 1:20, NOT 1:04. 1:04 came from restricting to rows where
BOTH gated steps succeeded, which drops the exhibit run printed 20 lines above
(its web-console step was cancelled) -- the same censoring mistake as filtering
the step table by job conclusion, made again. W25 is 40:53, so the old cap was
-0:53, not -0:37. windows-2022 now gets its own row with its own addends
instead of an unrecheckable 39:42.
* "the +4 convention" was Windows-only. ubuntu went 15/13 -> 22/19, so +2 then
+3, never +4.
* "2 x step_timeout ... which job_timeout must cover" asserted a requirement the
shipped caps do not meet (38 > 26, 72 > 46). Now says what they are actually
sized against.
* The nesting invariant at the top of the block asserted a guarantee it does not
provide for the SECOND gated step on any leg. Amended there, where a reader
meets it, not only in a caveat 100 lines below.
Also: pytest_timeout / fault_timeout were quoted as flat 60s / 90s in three
places; they are matrix values (60/120 and 90/150) passed explicitly on the
command line, so each figure was false on two of three legs. And records that
`test` is the only one of this file's ten jobs with any cap at all -- the other
nine run on GitHub's 6h default.
* backlog: #344 instance 3 carried the superseded -0:37, and the censoring now has evidence
The windows-2025 job-cap shortfall is -0:53, not -0:37: the 1:04 setup addend it
was computed from excluded the exhibit run itself, because that run's
web-console step was cancelled. Same censoring mistake, one layer down.
Instance 1 now cites the uncensored observation rather than only arguing the
maximum must be a lower bound: the day after the raise, windows-2025 produced
26:23 twice, both passing -- runs the old 26:00 cap would have killed. Records
that the jobs endpoint hides a killed attempt behind its passing re-run unless
asked for ?filter=all, which is why nobody had seen them.
* ci: #119 merged — stop saying it "died"
Reported by the announce-hook session, verified here: gh pr view 119 gives
MERGED, mergedAt 2026-08-02T01:45:00Z. What the 26:00 cap killed was a RUN, not
the PR.
"#119 died" reads as never-landed, and that reading had already propagated --
docs/WORKTREES.md asserted #119 "never merged (it died on an unrelated CI
timeout)", which that session corrected against the API. This block was one of
the places the phrasing came from, so it is fixed at the source rather than
only downstream.
* ci: 36:00/26:23 is 1.364x, not 1.365x
Caught by running an exact-arithmetic assertion over every figure in the block
rather than re-reading it: 2160/1583 = 1.3644978, which rounds to 1.364. I had
rounded it up by hand in both places.
Trivial in size and not in kind -- this is a change whose entire subject is
numbers published without being recomputed, so it does not get to ship one.
Every ratio, sum and delta in the block is now covered by that assertion and all
fifteen are exact.
* backlog: #344's own proposal 3 was harmful, and instance 2 was mis-diagnosed
Found by investigating a sqlserver failure on this very PR, which turned out to
be instance 2 recurring on a different test.
PROPOSAL 3 IS WITHDRAWN. It said a poll deadline over a virtual-clock system
should follow that clock rather than loop.time(). Implementing that would have
HUNG the suite: _wait_until waits on real store I/O, never on virtual time, and
ManualClock.now advances only inside advance(), which nothing calls from the
poll loop (tests/test_stage_dispatcher.py:182-204). A mc.now-based deadline is
never reached, so a bounded `assert False` becomes an unbounded hang stopped
only by pytest_timeout or the job cap -- manufacturing the exact signature
instances 1 and 3 are about. A virtual clock can only bound work it drives.
INSTANCE 2 IS RE-DIAGNOSED, and the original reading -- "the 8.0s bound is too
small" -- is refuted by the recurrence's own timings. The failing test took
8.185s, so _wait_until burned its full 8.000s and setup+teardown cost 0.185s:
the store was FAST when it failed. In the same process against the same
container the sibling retry_forever[sqlserver] drove seven identical fault
cycles in 0.364s, and the [sqlite] variant of the failing test passed in 0.144s.
A cycle costs ~30-45ms against an 8000ms bound. The lane is not slow to
transition; it never transitions. Raising the number would not fix it and would
bury it -- which is precisely the mislabelling this item's own Why warns about.
The leading mechanism is recorded as evidenced-but-unconfirmed rather than
asserted: a sanctioned EMPTY claim drops the lane to IDLE, and these tests
deliberately disable the sweep that recovers it in production. What is settled
is the negative: not latency, and not a bigger number.
PROPOSAL 1 now carries the evidence for preferring a computed gate to a written
instruction. Seven claims were retracted across this triage cluster and none was
caught by re-reading; every one fell to a mechanism that could return "no". The
one an author caught themselves was caught by running exact arithmetic over all
fifteen ratios in the block. As a method, re-reading is 0-for-7 here.
* backlog: #344 instance 2 inverts the item's own remedy, and needs observability first
A second, larger pass measured what instance 2 actually costs, and the numbers
change what should be done about it.
RATE AND MARGIN. The two affected tests fail 2 times in ~479 observations
(~0.4%), zero on postgres (119) and zero across 1,105 sqlite executions. Over a
sample of green sqlserver jobs the failing test passes in min 0.185s / median
0.196s / max 0.204s -- the 8.0s bound is ~39x its worst passing run, ~14x over a
wider 21-day pool. Both failures sit ~7x beyond the whole passing distribution:
a gap, not a tail.
SO THIS INSTANCE INVERTS THE ITEM'S OWN GENERIC REMEDY. "Size the bound against
the work" would derive ~1-2s here -- TIGHTER than the 8.0s already in place.
There is no larger number to justify, and raising it would only convert a 0.4%
visible failure into a 0.4% invisible 30-60s pause. An item about bounds that
have drifted too LOOSE has to be able to say when the answer is not a bigger
number, and this is that case.
MECHANISM IS EXPLICITLY UNRESOLVED. Two independent passes disagreed -- one
proposes a sanctioned EMPTY claim dropping the lane to a terminal IDLE (these
tests disable the sweep that recovers it in production), the other returned NOT
PROVEN and is right that the evidence cannot separate that from a genuine stall.
Recorded as unresolved rather than picking the more satisfying story.
NEW PROPOSAL 6: make the expiry diagnostic before tuning it. `assert await
_wait_until(...)` prints `assert False` and nothing else -- no phase, no park
deadline, no streak, no task state -- which is why this was read as latency for
a day. That is the prerequisite for judging any other proposal here, and unlike
them it cannot itself be wrong about the cause.
NOT changed: the note that a killed attempt hides behind its passing re-run
unless you pass ?filter=all. A reviewing pass claimed filter=all does not return
prior attempts; checked directly against both cited runs and it does
(attempts [1,2] on each), so the existing text stands.
* backlog: #344 proposal 6 — the instrument that settles instance 2 already ships
Both adversarial passes converged on the same verdict (raising the bound would
mask, not fix) but neither proposed the cheap discriminator, and it turns out
not to need building.
StageDispatcher.empty_claims (stage_dispatcher.py:1230) already returns
(total, wake_fanout, idle_poll) and is fed by _record_empty, whose ONLY call
site is the EMPTY branch of _claim_and_dispatch (:686). Under these tests'
topology -- lane_provider=set(), sweep_interval=3600, one seeded row -- a clean
run must read (0,0,0). So at the moment of failure `empty_claims[0] > 0` proves
a spurious EMPTY dropped the lane to a terminal IDLE (T12 sets phase=IDLE and
arms no timer), and `== 0` proves the claim never returned at all. One assertion
separates the two hypotheses this item currently records as unresolved.
A second signature costs nothing and is already in the captured log: a healthy
run emits FOUR `re-pending head with backoff` records (1001.000 / 1003.500 /
1008.000 / 1016.500, the ManualClock base plus the infra backoff ladder); the
failing run emitted ONE. The lane never took a second fault.
Verified against the source before citing it -- accessor, call site and the T12
branch all read directly, not taken from the analysis.
* backlog: two of my own #344 claims were wrong — postgres power, and a signature that does not generalise
Both reported by the session that settled instance 2 on a live SQL Server, and
both are defects in text I had already committed.
POSTGRES'S ZERO EXONERATES NOTHING. I wrote "zero on postgres (119
observations)" alongside sqlite's zero, which reads as two backends clearing the
mechanism. It is not: at ~0.4% a 119-observation sample expects ~0.5 events, so
zero is the expected outcome whether or not Postgres is affected -- and Postgres
claims via FOR UPDATE SKIP LOCKED, the SAME head-of-line skip. Only SQLite's 0
in 1,105 is structural, because its global lock totally orders producers and
claimers. Citing an underpowered sample as evidence of absence is the same error
as the censored maximum three paragraphs above it.
THE LOG SIGNATURE HOLDS FOR ONE TEST, NOT BOTH. I wrote that "a healthy run"
emits four `re-pending head with backoff` records against the failing run's one.
True of test_adr0070_1_* only. test_adr0070_9_* takes the content path, which
uses mark_failed and never emits that line at all, so zero there is EXPECTED and
is not evidence of a second mechanism. Scoped, with the reason, and pointed at
the counter rather than the log.
Proposal 6 itself is vindicated: empty_claims settled it in one assertion, read
(1,0,1) forced deterministically against a live SQL Server. The mechanism write-
up belongs to that session; I have corrected only my own two claims and left
instance 2's resolution to them.1 parent 41a8c49 commit ffec094
2 files changed
Lines changed: 168 additions & 34 deletions
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
54 | 54 | | |
55 | 55 | | |
56 | 56 | | |
57 | | - | |
58 | | - | |
59 | | - | |
60 | | - | |
| 57 | + | |
| 58 | + | |
| 59 | + | |
| 60 | + | |
| 61 | + | |
61 | 62 | | |
62 | 63 | | |
63 | 64 | | |
| |||
200 | 201 | | |
201 | 202 | | |
202 | 203 | | |
203 | | - | |
| 204 | + | |
204 | 205 | | |
205 | 206 | | |
206 | 207 | | |
207 | 208 | | |
208 | | - | |
209 | | - | |
| 209 | + | |
| 210 | + | |
| 211 | + | |
210 | 212 | | |
211 | 213 | | |
212 | | - | |
| 214 | + | |
| 215 | + | |
213 | 216 | | |
214 | 217 | | |
215 | 218 | | |
| |||
218 | 221 | | |
219 | 222 | | |
220 | 223 | | |
| 224 | + | |
| 225 | + | |
| 226 | + | |
| 227 | + | |
| 228 | + | |
| 229 | + | |
| 230 | + | |
221 | 231 | | |
222 | 232 | | |
223 | 233 | | |
| |||
230 | 240 | | |
231 | 241 | | |
232 | 242 | | |
233 | | - | |
234 | | - | |
235 | | - | |
236 | | - | |
| 243 | + | |
| 244 | + | |
| 245 | + | |
| 246 | + | |
| 247 | + | |
| 248 | + | |
| 249 | + | |
| 250 | + | |
| 251 | + | |
| 252 | + | |
| 253 | + | |
| 254 | + | |
| 255 | + | |
| 256 | + | |
| 257 | + | |
| 258 | + | |
| 259 | + | |
| 260 | + | |
| 261 | + | |
| 262 | + | |
| 263 | + | |
| 264 | + | |
| 265 | + | |
| 266 | + | |
| 267 | + | |
| 268 | + | |
| 269 | + | |
| 270 | + | |
| 271 | + | |
| 272 | + | |
| 273 | + | |
| 274 | + | |
237 | 275 | | |
238 | | - | |
239 | | - | |
240 | | - | |
241 | | - | |
| 276 | + | |
| 277 | + | |
| 278 | + | |
| 279 | + | |
242 | 280 | | |
243 | | - | |
244 | | - | |
245 | | - | |
| 281 | + | |
| 282 | + | |
| 283 | + | |
| 284 | + | |
| 285 | + | |
| 286 | + | |
| 287 | + | |
| 288 | + | |
| 289 | + | |
| 290 | + | |
| 291 | + | |
| 292 | + | |
| 293 | + | |
| 294 | + | |
| 295 | + | |
| 296 | + | |
| 297 | + | |
| 298 | + | |
246 | 299 | | |
247 | 300 | | |
248 | 301 | | |
| |||
251 | 304 | | |
252 | 305 | | |
253 | 306 | | |
254 | | - | |
255 | | - | |
256 | | - | |
257 | | - | |
| 307 | + | |
| 308 | + | |
| 309 | + | |
| 310 | + | |
| 311 | + | |
| 312 | + | |
| 313 | + | |
| 314 | + | |
| 315 | + | |
| 316 | + | |
| 317 | + | |
| 318 | + | |
| 319 | + | |
| 320 | + | |
| 321 | + | |
| 322 | + | |
| 323 | + | |
| 324 | + | |
| 325 | + | |
| 326 | + | |
| 327 | + | |
| 328 | + | |
| 329 | + | |
| 330 | + | |
| 331 | + | |
| 332 | + | |
| 333 | + | |
| 334 | + | |
| 335 | + | |
| 336 | + | |
| 337 | + | |
| 338 | + | |
| 339 | + | |
| 340 | + | |
| 341 | + | |
| 342 | + | |
| 343 | + | |
| 344 | + | |
| 345 | + | |
| 346 | + | |
| 347 | + | |
| 348 | + | |
| 349 | + | |
| 350 | + | |
| 351 | + | |
| 352 | + | |
| 353 | + | |
| 354 | + | |
| 355 | + | |
| 356 | + | |
| 357 | + | |
| 358 | + | |
| 359 | + | |
| 360 | + | |
| 361 | + | |
| 362 | + | |
| 363 | + | |
| 364 | + | |
| 365 | + | |
| 366 | + | |
| 367 | + | |
| 368 | + | |
| 369 | + | |
| 370 | + | |
| 371 | + | |
| 372 | + | |
| 373 | + | |
| 374 | + | |
| 375 | + | |
| 376 | + | |
| 377 | + | |
| 378 | + | |
| 379 | + | |
258 | 380 | | |
259 | 381 | | |
260 | 382 | | |
261 | 383 | | |
262 | 384 | | |
263 | 385 | | |
264 | 386 | | |
265 | | - | |
266 | | - | |
| 387 | + | |
| 388 | + | |
267 | 389 | | |
268 | 390 | | |
269 | 391 | | |
| |||
421 | 543 | | |
422 | 544 | | |
423 | 545 | | |
424 | | - | |
425 | | - | |
426 | | - | |
| 546 | + | |
| 547 | + | |
| 548 | + | |
427 | 549 | | |
428 | 550 | | |
429 | 551 | | |
| |||
0 commit comments