internal/handlers runs at 22s against script/test's 30s per-package timeout, and has already reded a build under load #194

Closed
opened 2026-08-18 06:48:33 +02:00 by clawbot · 1 comment
Collaborator

Milestoned 1.0.0, on the same reasoning #186 was milestoned: a test budget that can red a package when nothing is wrong makes the gate untrustworthy from the other direction, and next is required to stay green and mergeable to main without notice. This repo has spent the entire cycle making the gate mean what it says — #119, #152, #109, #186 — and tagging 1.0 with a known, already-breached margin contradicts all of it.

This has been observed, not theorised. During the rebase of #182 a cache-defeated docker build --no-cache-filter=lint --no-cache-filter=builder . failed: internal/handlers hit script/test's -timeout 30s per-package budget, with TestFailedLogin_LogLineDoesNotTrackUsernameSize/{json,text}/astral taking 16s each, at host load average 46 on 48 cores. A re-run of the same head passed at 21.940s.

Measured, by the round-3 review of #182

Cache-defeated builder stage at ambient load 12-18/48: 17.415 s, 17.948 s, 16.488 s against the 30 s budget.

GOMAXPROCS sweep, plain next (563e834) versus that PR's head (65148ab), as a proxy for effective cores:

GOMAXPROCS next with 182 delta
48 12.128 17.207 +5.08
16 15.208 19.315 +4.11
8 21.529 25.837 +4.31
6 26.272 30.956 (marginal pass) +4.68
5 28.996 pass TIMEOUT
4 TIMEOUT TIMEOUT

The key finding: next alone already times out at GOMAXPROCS=4, before 182 landed. This is not a problem that any one PR introduced. 182 moves the cliff from 4 effective cores to 5, at a flat +4-5 s attributable to its non-parallel TestFlood_NoWriterGrowsWithTheInput (5.06 s / 5.67 s measured), taking budget consumption from 40 % to 57 %. #189 will consume more.

Spurious red is unlikely at ambient load and likely below roughly 6 effective cores. Since the box is shared and routinely loaded, "unlikely" is not the same as "won't happen" — and it already did once.

Preferred fix, and why

Raise the per-package timeout in script/test. One file, conflicts with nothing in flight, and 30 s was never a considered figure — it is a default the suite outgrew. The 182 reviewer suggests 120 s; that is a reasonable starting point but justify whatever you pick against the measurements above rather than adopting it because it was suggested.

Do not move tests between packages in this issue. Splitting internal/handlers would collide with work that touches it. If you conclude a split is genuinely right, say so here and stop rather than doing it.

Also state a view on whether a single per-package -timeout is the right instrument at all, given go test applies it per package and this suite's packages are very unevenly sized.

Definition of done

  • script/test's per-package timeout is raised, with the chosen value justified in a comment against measured durations rather than asserted.
  • A GOMAXPROCS=4 cache-defeated builder run of internal/handlers passes, since that is where next currently fails. Report the duration.
  • Evidence under load, not one clean run — repeated runs at high host load, with the resulting margin stated.
  • The slowest package under the new budget is named with its measured time, so the next person to consume the margin can see what is left.
  • No test is weakened, skipped, shortened or made to sample less to fit the budget. The problem is the budget, not the tests — "de-flaking" by removing coverage was caught and rejected once already in #188.

Implementation requirements

  • Branch from next, PR based on next, single commit, title ending (closes #N).
  • Do not modify TODO.md (see #112).
  • Run make bootstrap in a fresh clone before gating. Gate on make check plus the cache-defeated Docker lint path; all linting in Docker, never the host. Clean up every container and image; never run any prune.
  • Re-measure rather than restating the numbers above: #189 lands before this and adds to the same package, so every figure here is out of date by the time you start.
Milestoned **1.0.0**, on the same reasoning https://git.eeqj.de/sneak/webhooker/issues/186 was milestoned: a test budget that can red a package when nothing is wrong makes the gate untrustworthy from the other direction, and `next` is required to stay green and mergeable to `main` without notice. This repo has spent the entire cycle making the gate mean what it says — https://git.eeqj.de/sneak/webhooker/issues/119, https://git.eeqj.de/sneak/webhooker/issues/152, https://git.eeqj.de/sneak/webhooker/issues/109, https://git.eeqj.de/sneak/webhooker/issues/186 — and tagging 1.0 with a known, already-breached margin contradicts all of it. **This has been observed, not theorised.** During the rebase of https://git.eeqj.de/sneak/webhooker/pulls/182 a cache-defeated `docker build --no-cache-filter=lint --no-cache-filter=builder .` **failed**: `internal/handlers` hit `script/test`'s `-timeout 30s` per-package budget, with `TestFailedLogin_LogLineDoesNotTrackUsernameSize/{json,text}/astral` taking 16s each, at host load average 46 on 48 cores. A re-run of the same head passed at 21.940s. ## Measured, by the round-3 review of https://git.eeqj.de/sneak/webhooker/pulls/182 Cache-defeated builder stage at ambient load 12-18/48: **17.415 s, 17.948 s, 16.488 s** against the 30 s budget. `GOMAXPROCS` sweep, plain `next` (`563e834`) versus that PR's head (`65148ab`), as a proxy for effective cores: | `GOMAXPROCS` | `next` | with 182 | delta | | --- | --- | --- | --- | | 48 | 12.128 | 17.207 | +5.08 | | 16 | 15.208 | 19.315 | +4.11 | | 8 | 21.529 | 25.837 | +4.31 | | 6 | 26.272 | 30.956 (marginal pass) | +4.68 | | 5 | 28.996 pass | **TIMEOUT** | — | | 4 | **TIMEOUT** | **TIMEOUT** | — | **The key finding: `next` alone already times out at `GOMAXPROCS=4`, before 182 landed.** This is not a problem that any one PR introduced. 182 moves the cliff from 4 effective cores to 5, at a flat +4-5 s attributable to its non-parallel `TestFlood_NoWriterGrowsWithTheInput` (5.06 s / 5.67 s measured), taking budget consumption from 40 % to 57 %. https://git.eeqj.de/sneak/webhooker/pulls/189 will consume more. Spurious red is unlikely at ambient load and likely below roughly 6 effective cores. Since the box is shared and routinely loaded, "unlikely" is not the same as "won't happen" — and it already did once. ## Preferred fix, and why **Raise the per-package timeout in `script/test`.** One file, conflicts with nothing in flight, and 30 s was never a considered figure — it is a default the suite outgrew. The 182 reviewer suggests **120 s**; that is a reasonable starting point but justify whatever you pick against the measurements above rather than adopting it because it was suggested. **Do not move tests between packages in this issue.** Splitting `internal/handlers` would collide with work that touches it. If you conclude a split is genuinely right, say so here and stop rather than doing it. Also state a view on whether a single per-package `-timeout` is the right instrument at all, given `go test` applies it per package and this suite's packages are very unevenly sized. ## Definition of done - `script/test`'s per-package timeout is raised, with the chosen value justified in a comment against measured durations rather than asserted. - **A `GOMAXPROCS=4` cache-defeated builder run of `internal/handlers` passes**, since that is where `next` currently fails. Report the duration. - **Evidence under load, not one clean run** — repeated runs at high host load, with the resulting margin stated. - The slowest package under the new budget is named with its measured time, so the next person to consume the margin can see what is left. - No test is weakened, skipped, shortened or made to sample less to fit the budget. The problem is the budget, not the tests — "de-flaking" by removing coverage was caught and rejected once already in https://git.eeqj.de/sneak/webhooker/pulls/188. ## Implementation requirements - Branch from `next`, PR based on `next`, single commit, title ending ` (closes #N)`. - Do not modify `TODO.md` (see https://git.eeqj.de/sneak/webhooker/issues/112). - Run `make bootstrap` in a fresh clone before gating. Gate on `make check` plus the cache-defeated Docker lint path; all linting in Docker, never the host. Clean up every container and image; never run any prune. - Re-measure rather than restating the numbers above: https://git.eeqj.de/sneak/webhooker/pulls/189 lands before this and adds to the same package, so every figure here is out of date by the time you start.
clawbot self-assigned this 2026-08-18 06:48:39 +02:00
clawbot added this to the 1.0.0 milestone 2026-08-18 06:48:39 +02:00
Author
Collaborator

#195script/test's -timeout 30s becomes -timeout 180s, one line plus the justification as a comment in the script. No test touched, nothing moved between packages.

Chose 180 s, not the suggested 120 s. Re-measured on the final tree in a cache-defeated builder-equivalent stage; internal/handlers at GOMAXPROCS 48/16/8/6/5/4/3/2/1 was 16.961 / 20.107 / 27.660 / 30.575 / 32.940 / 39.666 / 49.361 / 67.320 / 97.510 s. 120 s is only 1.23x that worst figure — a number the suite sits under, not a margin. 180 s is 1.85x it.

The old budget really fails: plain next at 33e4fa4, unmodified, GOMAXPROCS=4FAIL internal/handlers 30.165s, panic: test timed out after 30s. Same run on this branch: ok internal/handlers 41.262s.

Under real load (36 spinners, load 31-73/48), three cache-defeated runs: 45.881 / 47.274 / 49.000 s — all three would have breached 30 s. Compound GOMAXPROCS=4 plus load 52-68: 67.270 s. Spinners were killed and docker ps -a verified empty before the proof and gate runs.

No new cliff: 180 s is not breached anywhere in the sweep, down to the instrument's floor at GOMAXPROCS=1 (54 % of budget).

Slowest package: internal/handlers, in all 16 measured runs — 16.689 s in make check, 17.144 s in the gate build, 49.000 s at its worst under load. Second place is internal/ciscript (7.1-7.2 s) with cores to spare, internal/delivery (up to 18.306 s) without; the gap is 4-5x either way.

Verified with make check (GOFLAGS=-count=1, lint in Docker, 0 issues.) and docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain ., both rc=0 with the lint and builder stages shown executing rather than replaying. CI green on 7f27362.

Two things for you in the PR body: my view on whether a single per-package -timeout is the right instrument (it is the wrong shape but the right choice today), and a deliberate divergence from REPO_POLICIES.md, which still mandates 30 s.

https://git.eeqj.de/sneak/webhooker/pulls/195 — `script/test`'s `-timeout 30s` becomes `-timeout 180s`, one line plus the justification as a comment in the script. No test touched, nothing moved between packages. **Chose 180 s, not the suggested 120 s.** Re-measured on the final tree in a cache-defeated builder-equivalent stage; `internal/handlers` at `GOMAXPROCS` 48/16/8/6/5/4/3/2/1 was 16.961 / 20.107 / 27.660 / 30.575 / 32.940 / 39.666 / 49.361 / 67.320 / **97.510** s. 120 s is only 1.23x that worst figure — a number the suite sits under, not a margin. 180 s is 1.85x it. **The old budget really fails:** plain `next` at `33e4fa4`, unmodified, `GOMAXPROCS=4` → `FAIL internal/handlers 30.165s`, `panic: test timed out after 30s`. Same run on this branch: **`ok internal/handlers 41.262s`**. **Under real load** (36 spinners, load 31-73/48), three cache-defeated runs: 45.881 / 47.274 / 49.000 s — all three would have breached 30 s. Compound `GOMAXPROCS=4` plus load 52-68: 67.270 s. Spinners were killed and `docker ps -a` verified empty before the proof and gate runs. **No new cliff:** 180 s is not breached anywhere in the sweep, down to the instrument's floor at `GOMAXPROCS=1` (54 % of budget). **Slowest package: `internal/handlers`**, in all 16 measured runs — 16.689 s in `make check`, 17.144 s in the gate build, 49.000 s at its worst under load. Second place is `internal/ciscript` (7.1-7.2 s) with cores to spare, `internal/delivery` (up to 18.306 s) without; the gap is 4-5x either way. Verified with `make check` (`GOFLAGS=-count=1`, lint in Docker, `0 issues.`) and `docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .`, both rc=0 with the lint and builder stages shown executing rather than replaying. CI green on `7f27362`. Two things for you in the PR body: my view on whether a single per-package `-timeout` is the right instrument (it is the wrong shape but the right choice today), and a deliberate divergence from `REPO_POLICIES.md`, which still mandates 30 s.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#194