ci: the margin table was wrong twice — re-measure the pool, and size the job cap from maxima - #138
Open
wshallwshall wants to merge 23 commits into
Open
ci: the margin table was wrong twice — re-measure the pool, and size the job cap from maxima#138wshallwshall wants to merge 23 commits into
wshallwshall wants to merge 23 commits into
Conversation
…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.
wshallwshall
enabled auto-merge (squash)
August 2, 2026 03:40
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.
wshallwshall
disabled auto-merge
August 2, 2026 04:11
…om 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.
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.
wshallwshall
changed the title
#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.
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.
…ing 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.
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.
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.
…agnosed 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.
…ervability 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.
…eady 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.
wshallwshall
enabled auto-merge (squash)
August 2, 2026 14:13
… 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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
#131 replaced a "~2x headroom" claim with a measured table. That table was wrong in every row. The first correction on this branch fixed the maxima but repeated #131's own failure mode in a new place — it reported a pool and an
nthat its stated pool cannot produce. This revision fixes that, and sizesjob_timeoutfrom measured maxima instead of typical values.Two independent re-derivations agree on every figure below.
The measurement
Pool: every run of
ci.ymlcreated 2026-08-01 UTC — 70 runs, enumerated over a deliberately wider window and filtered locally oncreated_at, then cross-checked against the narrow?created=query (same 70 ids, symmetric difference 0). Rows are each leg'sTests (pytest)step, kept when that step concluded success.The maxima re-derive to the second. The pool size (
101) and everyn(57/52/49) do not reproduce under any pool definition tried.These maxima are lower bounds — the pool is right-censored
Every run in it predates #131 (
28d186b5, landed2026-08-02T00:35:28Z), so Windows ran under step 26:00 / job 30:00. A run that wanted longer was killed at the cap and then — correctly, by the filter above — dropped for not concluding success. 25:51 is the largest step that FIT in 26:00, not the largest the suite wants. Sizing a cap as a multiple of a censored maximum under-provisions by construction. That is exactly how "1.06x" read as survivable right up until #119 died.Three mechanisms, all cheap to repeat
gh run list --limit 20— a default page size, reported as though chosen.n" has to carry annthe next reader can recompute — that column is how they would tell it had rotted.The job cap
Both
Tests (pytest)andWeb console tests (pytest)carrystep_timeout, so a job can hold 2 ×step_timeoutof gated work thatstep_timeoutcannot bound. Run30724385719(main @8f01cef8), windows-2025 — all six timestamps confirmed:Read that exhibit for its mechanism, not as a verdict on the cap it replaces: it ran under the retired 26/30 pair and would have passed under #131's 40:00. What condemns 40:00 is the arithmetic below — and that is arithmetic; no job has been observed hitting 40:00.
Every addend is now that addend's measured maximum. The previous revision used
0:41for setup, which is the median, and web-console figures (1:58/3:27) that are each only the third-highest on their leg:ubuntu and windows-2025 were already negative — ubuntu as well, which an earlier revision had the wrong way round (it showed ubuntu at +21s). windows-2022 was the one row genuinely in the black.
The Windows setup addend was itself wrong twice:
0:41(a median), then1:04— which came from restricting to rows where both gated steps succeeded, silently dropping the exhibit run whose web-console step was cancelled. Same censoring mistake as filtering the step table by job conclusion, made a second time. The true figure,1:20, is visible in the exhibit printed directly above it.What this does not fix
The nesting invariant
ci.ymlasserts — "the step must expire BEFORE the job" — holds forTests (pytest)on every leg and forWeb console tests (pytest)on none of them: reaching that step already spends setup plusTests, so its own cap can never fire first. Satisfying it would needjob_timeoutpast 39:24 on ubuntu and 73:21 on Windows. A hang there still surfaces as an unattributed job-level kill. The file now says so instead of restating the claim — a compensating control must not rest on a false premise. The structural fix (stop the two steps sharing one budget) is BACKLOG #344.The spread rule is not met, and the file now says so
An earlier revision claimed 36:00 "comfortably clears" the observed spread. Against real values it does not. The first day after the raise produced windows-2025
Testssteps of 26:23 twice, both passing — uncensored evidence that the population exceeds the old 26:00 cap. Against 26:23: headroom 9:37 vs spread 10:27. The rule would need ~37:00.36:00 is kept, with the reason stated rather than dressed up: this cap exists to catch a whole-process deadlock, not slowness, so 1.365x over the worst observed run is ample for its actual job, and #131 already set this value. Re-derive if a windows-2025 step is ever seen above 28:00.
Also withdrawn — both were wrong: "
26:07does not exist" and "no identical-code spread is computable". Artifacts of the jobs endpoint defaulting tofilter=latest, which hides a step killed at the cap behind its passing re-run.26:07is in this very pool (run 30717229521 attempt 1, killed at the cap), and seven same-commit pairs exist under?filter=all.Also corrected
Three pre-existing claims in this same file that match no configuration — the very defect class this note is about:
timeout-minutes: 13(it ismatrix.step_timeout, 19 or 36)matrix.job_timeout, 26 or 46)main; it is #344 item 1Drops
HANDOFF-ci-margin-correction.md: session ephemera, and no HANDOFF file has ever been tracked at the repo root onmain.The 36:00 step / 46:00 job decision is unchanged and remains correct. Only its justification moves — for the second time, which is itself the finding.
Verification
Nine agents; 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 — all six fixed in
5be4d1fe.The sqlserver
HYT00isPRE_EXISTING_INTERMITTENT, not caused by this PR. Adversarially checked and upheld:adr0154-sync-reply@88f99b0c, ~10h before this PR was opened, carrying the pre-ci: the margin table was wrong twice — re-measure the pool, and size the job cap from maxima #138ci.ymlsqlserver-storedeclares notimeout-minutesand never readsneeds.changes.outputs.matrix(the only output this PR changes); and every leg runs on GitHub-hosted runners perci.yml:49("the self-hosted NucBox Windows runners are RETIRED"), so there is no shared pool for a longertestjob to starveNot claimed: that it is harmless.
HYT00is a query timeout — a fixed wall-clock bound, the same shape as #344.