test(ci): split phase timing for the four #4997 budget overruns - #5081

Summary

The four cases in #4997 exceed their own budgets only when the suite runs unsharded, and pass in the sharded lanes that run the same files. Three control dispatches produced three disjoint failing sets, so the shared factor is elapsed time in a process holding 1367 files rather than any one subsystem. A per-test duration cannot say where that time went: cold fixture setup, a wait the assertion genuinely needs, slow contended execution, and a teardown still reaping a child all arrive as one number.

This PR adds no fix. It makes the phases readable so each of the four can get a disposition argued from a measurement instead of from a plausible story. The fix is stacked on top of this branch.

tests/helpers/phase-timing.ts emits one grep-able record per instrumented case:

• prepare / execute / teardown boundaries from performance.now(), which is monotonic and is already the timing convention across this suite (78 uses in 27 files).
• at= is milliseconds since process start, so it doubles as position-in-run. Sorting every emitted line by at recovers the order the runner selected these cases in, rather than any file restating an ordering it would then have to keep correct.
• Runtime and host only: Bun version, platform, OS release, arch, CPU count, pid. No environment dump and no file reads.
• Progress ticks on an exponential schedule while a phase is open. This is the part that matters: a budget overrun kills the test, so the closing line of the phase that overran is exactly the line that never prints. Each tick reports whether the case's own progress counter moved since the previous one, so a record truncated at moving=yes is slow execution under contention and one truncated at moving=no is a stall with no work happening. Those are different defects and the per-test duration cannot tell them apart.

A tick fires from the event loop while the case is parked on an await, so the case cannot push a count at that moment. The two image cases therefore pass a probe reading the normalizer's own encodeCalls counter, which a tick can read from outside.

Where the four cases actually are

The issue asked for the other two to be located precisely. They are:

This corrects the triage comment on the issue, which mapped "image non-droppable" to tests/adapters/anthropic/anthropic-image-normalize.test.ts N1 and imageTierBias to tests/adapters/anthropic/anthropic-image-retry.test.ts. That comment says it is matching names approximately, and the completed control run at 56a99d3848 later named imageTierBias verbatim as openai-chat inline image normalization > imageTierBias from incoming meta reaches the normalizer, which is the openai file. "Image non-droppable" reads the same way: the openai file has a case literally titled "an image this wire cannot drop", the anthropic N1 title is "resized under the tier-0 edge and 2MiB cap, not dropped", and the two openai cases sit in one file, which fits an observation about pressure inside one process better than two cases in two unrelated files. The anthropic N1 case does build a 12-megapixel PNG and is worth watching, but it is not what the table row names.

Why the heartbeat case moved files

tests/web-search/web-search.test.ts sits at exactly its recorded 2823-line cap in tests/fixtures/file-size-baseline.json, and caps only move downward, so instrumenting in place was not available. Moving the case to a sibling file is the remedy AGENTS.md names for this situation. The case body is unchanged apart from the two phase boundaries; the preamble it needs (runWithWebSearch, forwardProvider, collectSse, the globalThis.fetch restore hook) is reproduced in the new file. The new file is registered in both scripts/test-layout/layout.json and tests/fixtures/test-layout-expected.json.

The enclosing describe name changes from "web-search sidecar native web_search_call emission" to "web-search same-target 429 retry", so a future control log matches on the test name rather than the full path. The test name itself is untouched. web-search.test.ts goes from 2823 to 2781 lines, which the ratchet reads as SHRANK; the recorded cap is left where it is rather than tightened, since lowering it is a maintainer --update action and not this PR's business.

Two things this instrumentation already contradicts

Recorded here because they change what the fix should be, and both are addressed in the stacked PR rather than here.

The heartbeat case does not exercise the watchdog its name claims. runWithWebSearch drains the first iteration through prepareIterationDrained (src/web-search/loop.ts:613), awaits it eagerly (src/web-search/loop.ts:820), and only then constructs bridgeToResponsesSSE with the stall watchdog (src/web-search/loop.ts:947). The case returns its 429 on the first send, so its 1.5s heartbeat-fed wait completes before any watchdog exists and the heartbeats are discarded by the drain loop. Ablating the heartbeat yields would not turn this case red, which is the second condition tests/helpers/test-budget.ts requires.

The spine's inner and outer deadlines are the same number. Every WebSocket turn uses watchdogMs(2_000), which tests/helpers/ci-watchdog.ts:21 raises to 30000ms on macOS CI, and the case's own bound is 30000ms. A stalled turn therefore cannot produce its own diagnostic before the enclosing case times out, which is consistent with the 30029ms observation being a stalled turn rather than accumulated work.

What this measurement cannot tell you

Two caveats, both real, neither avoidable within this PR.

Order matters between this PR and its child. The stacked fix removes workload that this PR is trying to measure. A control dispatch has to run at this branch's head, not at the child's, or the numbers describe a workload that no longer exists.

The heartbeat case has changed neighbourhoods. It was moved into its own file because web-search.test.ts is at its cap, and bun test --isolate reclaims the realm at file boundaries, so the case no longer shares a module registry with 2800 lines of siblings. A figure measured after the move is therefore not strictly comparable to the 6233ms that was observed before it. That is a real loss and it was the cheapest option available: instrumenting in place would have breached the ratchet, and the alternative of not instrumenting it at all would have left one of the four with no evidence. What the move does preserve is the ability to see the split between setup and the measured wait, which is the question that matters for this case, and what it plausibly removes is exactly the cross-file pressure that is under suspicion — so a post-move figure near 1.5s is itself informative.

Progress probes, per case. sends for the heartbeat retry, captures.length for the ownership spine, and the normalizer's encodeCalls for the two image cases. Each is monotonic within its phase, which is what makes a frozen reading mean a stall rather than an unscheduled test. The image cases reset that counter between their two builds, so the reset is kept outside the measured segment; zeroing a probe mid-phase would report movement that did not happen.

Measured

Dispatched at this branch's head 765d43533a: run 35386429688, job 105734399306, started 19:44:25Z, cancelled at 20:59:58Z by timeout-minutes: 75. The lane did not complete, for the same reason the third dev dispatch did not. A second dispatch at the child branch's head ran 35386456242, job 105734706534, 19:40:21Z to 20:55:57Z, also cancelled at the budget.

The heartbeat case emitted a full record in both:

Against 6233.05ms when the issue was opened. Setup is not where the time goes — 1.2ms and 31.6ms — and the measured window is the 1.5s backoff plus roughly 440 to 640ms. The tick fired mid-backoff with the send count already advanced, so the case was progressing rather than parked. Read this with the neighbourhood caveat above: the case is in its own file now.

Neither run reached the two image cases or the spine. Bun's file order under bun test tests is not the sorted order the sharded runner imposes, and the cut landed before those files in one run and exactly at openai-chat-image-normalization.test.ts in the other. Three of the four still have no phase record, and getting one needs the lane to finish rather than more instrumentation.

What both runs did produce is a fourth and a fifth disjoint failing set, and not one entry belongs to the four this issue names:

Five dispatches, five disjoint sets. The first of these had already appeared once, at 10059.54ms in the third dispatch and 10854.12ms here; the other three are new. This is the strongest version yet of the argument the issue makes against raising any bound.

Both names in the issue table are ambiguous

Worth fixing before the next reading, because matching on a test name alone picks the wrong case.

retry wait longer than the stall budget still succeeds (heartbeats feed the watchdog) exists twice. The other one is tests/images/loop.test.ts:477, under describe("runWithImageBridge"), and it ran at 1529.91ms and 1538.47ms in these two runs. The issue calls its row "web-search heartbeat retry", so the web-search one is intended, but the name does not say that.

imageTierBias also exists twice. The other one is tests/adapters/anthropic/anthropic-image-retry.test.ts:71, describe("imageTierBias plumbing (030 R1 — bias activation through the real adapter)"), which ran at 1057.23ms. That is the file the triage comment picked. The completed control at 56a99d3848 settled it by naming the case in full — openai-chat inline image normalization > imageTierBias from incoming meta reaches the normalizer — which is the openai file, and that is the one instrumented here.

Verification

No local suite was run. No local test, focused test, typecheck, build, or install was executed, and the ocx binary was not invoked. Verification here is static reasoning plus hosted CI at the exact head.

• Branch is cut from the current origin/dev tip 6044a9ab38.
• File-size ratchet: tests/helpers/phase-timing.ts (206) and tests/web-search/web-search-retry-heartbeat.test.ts (113) are new and under the 2000-line NEW_OVERSIZED threshold, so neither needs a baseline entry. web-search.test.ts shrinks, which is not an offender. The three other touched test files are untracked by the baseline and remain far under 2000.
• Test layout: the new helper is not a *.test.ts and the guard skips it; the new test file is registered in both maps with the same basename-to-domain row.
• Hosted CI on this PR is the gate for typecheck and the suite. The evidence this PR exists to produce needs a macos control dispatch, which is dispatch-only.

Checklist

• Scope stays focused and avoids unrelated cleanup.
• Docs or release notes were updated when needed. No user-facing behaviour changes; the rationale lives in the helper's own header.
• Security-sensitive changes were reviewed for secrets, auth, and unsafe defaults. The helper reads runtime and host identity only and touches no file, credential, or environment dump.

Refs #4997