Repository navigation
Time five load-flaky tests by the product's own phases, not by start-up - #58
solvyxtech wants to merge 5 commits into
Conversation
"ends the job on time" failed on macOS CI for #54 (11055ms) and on the box for #51/#52 (11.3s) when suites ran in parallel. The product was not late: under 150 CPU burners on a 10-core Mac, job_end's durationMs was 7007ms on every run (5s budget + 500ms cancel grace + 1s salvage grace + 500ms cancel grace), while spawn-to-exit was 11.2-12.3s. The extra ~5s was CPU-starved start-up outside the turn's clock: ~3s of node module loading before the journal opened and ~1.7s of set-up before the turn began (120ms unloaded). The test measured the whole process lifetime against an 11s bound. It now checks the turn's own clock (durationMs) and the time from the agent taking the prompt to the process exiting, both against 5s + the documented graces (2 x CANCEL_GRACE_MS + deadlineGraceMs) + 2s slack. A 3s stall injected into the interrupt path still fails it (durationMs 13021). Under 150 CPU burners: 0/20 passes before, 20/20 after.
Solvyx
left a comment
Solvyx
left a comment
There was a problem hiding this comment.
Grok review of #58 (comment-only, no merge)
Verdict: looks good to merge once CI is green. No blocking issues. (This is posted as a comment because the PR and the review come from the same account, so GitHub won't take an approval. Read it as an approve.)
The diagnosis holds up. --for bounds the turn, and the old took < 11_000 timed Node start-up and pre-turn set-up too, which is exactly what grows under load. The durationMs bound is unchanged in value (5000 + 2×500 + 1000 + 2000 = 9000) but is now derived from the real constants. The 3s mutation in interrupt still failing is good evidence the turn check has teeth.
Pairing rules are fine: it's test-only, on a claude/ branch, uses only our own grok-build backend, adds no subscription backends, and has no competitor names or fine-tune data changes.
Blocking
None.
Non-blocking
1. test/acp-deadline.test.ts:138: resolving on exit can drop the job_end line under load. Confidence: medium.
Node can fire exit before the child's stdout pipe is drained. On a loaded runner, which is the exact condition this PR targets, the last chunk with job_end can arrive after resolve, and the test fails with no job_end in: instead. This was already true before this PR, but it's now the main load-sensitive part left in this test. Fix: keep exitAt = Date.now() on exit, but resolve on close.
2. test/acp-deadline.test.ts:160-161: sincePrompt is weaker than it looks at catching a process held open after the turn. Confidence: medium.
promptAt is set after the fake agent's own Node start-up and the ACP handshake, both of which happen inside the turn, and then it's seen by a 20ms poll in the test process. On a loaded machine that pushes promptAt later, which loosens the bound. So a hold after job_end of roughly 2s plus the agent's start-up time would still pass. The mutation you checked sits inside the turn, so durationMs caught it, not this assertion. A tighter check that doesn't depend on load: note Date.now() when out first contains a job_end line, then assert exitAt - jobEndSeenAt is under about 1000ms. That tests "nothing holds the process open past the turn" directly. Keeping sincePrompt as well is fine.
3. test/acp-deadline.test.ts:154: a bound built from constants moves when the constants move. Confidence: high that it can happen, low severity.
If someone raises CANCEL_GRACE_MS (say 500 to 5000), this test loosens silently instead of flagging it, and the old absolute 9000 would have caught that. deadlineGraceMs is already pinned at the bottom of the file. Adding assert.equal(CANCEL_GRACE_MS, 500) next to it would keep the derived bound honest.
CI (test-linux, typecheck-and-test, privsep-linux) was still running when I reviewed head 3534fc2.
"holds the first write until the checks are sealed" failed 15 of 20 runs under 150 CPU burners with "the wait was announced". Traced with a journal: the scripted ACP agent's first call came 500-860ms into the run, after the 600ms drafter timer had fired, so the checks were sealed before any write and the gate correctly had nothing to hold. The product was right; the stimulus was on a wall clock that ran during start-up. The drafter now finishes when the engine announces it is holding the write (a 10s fallback only bounds a gate that never holds). With the per-call gate switched off in the product the test still fails, in 100ms: "the drafter finished before the file was written".
"runs the sealed bar on the tree ... the model never said done" failed 14 of 20 runs under 150 CPU burners (passedAtEnd undefined). In every failing run the 400ms budget ran out before the scripted provider's first reply was read: "time budget reached (414ms of 400ms) - no more tool calls". Nothing was written, so the bar rightly failed the empty tree. The deadline itself was honoured (seen at 414ms, job_end 526-777ms with the bar). The three "a turn stopped by the clock" cases now arm the same 400ms budget when write_file is seen (the budget is read live), so the clock stops the turn after the work exists under any load. With the product's between-steps deadline stop removed, all three fail.
Under 150 CPU burners, "are not sealed empty" failed 12 of 20 runs and "drafts arriving at 200 s" 1 of 20. Both were the product on time and the test's clock in the wrong place: - The draft finished on a 300-400ms timer started before engine.run, against a 100ms cut. The journal showed the draft sealed 7-38ms into the turn: start-up had outrun the timer, the draft was ready at the cut, and sealing it there is right. The draft now finishes on the cut's own "none was ready" announcement, and the never-late case uses a draft that never arrives. - On the virtual clock (1 simulated second per 2ms real), the claim began 11 simulated seconds in under load, so it waited 189s for a draft that landed at 200s, which is correct, and a 19x-20x pattern failed. The test now checks that the draft joined after it landed and before the 510s margin, and that a draft that never arrives is given up at 510s from the turn's start (from job_end's durationMs), not a wait counted from wherever the claim began. With the late join switched off, the first two fail; with the claim held to the old 120s rule, both virtual-clock cases fail.
The three "late checks and the copy taken before the work" cases finished their draft on a 300ms timer started before engine.run, against a 100ms cut. Under 150 CPU burners the journals of 4 of 24 runs showed the draft sealed at the cut (62-102ms into the turn): start-up had outrun the timer, the checks were not late, no pre-work copy was tried, and "the change to the copy is journalled" / "task:abs untried" failed (1 of 20 runs each). Sealing a ready draft at the cut is right. The draft now lands on the cut's own "none was ready" announcement. With the product's late join switched off, all three cases fail.
solvyxtech
changed the title
|
Status: four more flaky timing tests were added after your review of 3534fc2 (commits up to fd056e7): acp-seal-gate, ended-with-verdict, late-criteria and discriminating-checks. Each is a test-clock problem; the journals show the product on time, as the description explains. Under 150 burners they went from 5/20, 6/20, 8/20 and 18/20 to 20/20. Strictness is checked two ways: an injected 1s stall, and breaking each behaviour the test guards. Please re-review the head; test-only, no product change. |
2 participants
Summary
Five tests flaked under load:
acp-deadline,acp-seal-gate,discriminating-checks,ended-with-verdictandlate-criteria. Every one was a test problem. In each, the product was on time and did the right thing for the order in which events actually happened. Each test either timed process start-up against a budget that doesn't cover it, or fired its stimulus on a clock that kept running while the product did CPU-bound start-up work. Under load the stimulus therefore landed in a different phase than the test assumed. No product code changes, so there's no CHANGELOG entry.Each file is a separate commit. Each fix makes the test follow the product's own clock or phase, and each is checked to still be strict.
How it was checked
yesCPU burners on a 10-core Mac, killed by a trap on exit.pgrep -x yesreturned 0 after every run.runSealedTurn, standing in for CPU-starved start-up. It makes the old tests fail deterministically (5 of 40, exactly the flaky cases) while the new ones pass 40/40.Per test
acp-deadline"ends the job on time"job_end.durationMswas 7007 ms on every loaded run (5s budget + 0.5s cancel grace + 1s salvage grace + 0.5s cancel grace). The extra ~5s was ~3s of node module loading plus ~1.7s of set-up, both before the turn's clock starts (--foris "wall-clock ceiling for one turn").durationMsand prompt→exit by 5s +2·CANCEL_GRACE_MS+deadlineGraceMs(5000)+ 2s slack.close()ininterrupt→durationMs 13021failsacp-seal-gate"holds the first write…"ended-with-verdict"a turn stopped by the clock" (3 cases)durationMs526–777 ms including the bar).write_fileis seen. The budget is read live, so the clock stops the turn after the work exists.late-criteria, real-timer casesengine.run, against a 100 ms cut. Journals showed it sealed 7–38 ms into the turn: ready at the cut, so sealing it there is correct.late-criteria, virtual-clock cases19x–20x spattern failed. "Never arrive" carried the same latent risk (500–512scounted from the claim).job_end.durationMs).discriminating-checks"late checks and the copy" (3 cases)Full check
npm run checkwith~/.local/binoff PATH: 2449 tests, 0 fail, 5 todo. e2e, self-drive and self-check pass.