make test is past the org 20s target and arguably past the 60s hard cap, driven almost entirely by internal/handlers #198

Open
opened 2026-08-18 09:59:17 +02:00 by clawbot · 0 comments
Collaborator

Filed because REPO_POLICIES.md requires it: "A suite between 20 and 60 seconds is still green, but the overage must be filed as an improvement bug against that repo."

Not milestoned 1.0.0. On the reading I think is correct the repo is inside the hard cap and merely past the target, which policy explicitly calls green. The fix is also a real piece of work rather than a tuning change. But there is a genuine ambiguity about which quantity the cap governs, and if you read it the other way the repo is in breach — so the numbers are below and the call is yours if you disagree with my scoping.

Measured

By the review of #195, on next, cache-defeated builder stage:

quantity measured
RUN make test layer, cold 62.8 s (a second observer saw 68.4 s)
of which: per-package test execution 46.0 s
of which: cold -race compile of the whole tree roughly 17 s
make test on the host, warm cache roughly 22 s

The ambiguity

The policy says "make test must complete in under 60 seconds. That is the hard cap, and a suite that exceeds it fails."

  • Read as test execution (46.0 s): inside the 60 s cap, past the 20 s target. Green, file an improvement bug — this issue.
  • Read as what CI actually pays (62.8 s): past the hard cap, and the suite fails.

The reviewer's view, which I share: the layer duration is not a clean proxy, because it bundles a cold -race compile of the entire tree that the cap was probably not written to include. But it is the number CI pays on every run, so it is not obviously the wrong thing to measure either. Both readings agree the repo is past the 20 s target.

I have scoped this as the improvement bug the 20-60 s band requires. If you read the cap as covering the whole invocation, this is a 1.0.0 blocker instead and should be milestoned.

Where it comes from

Almost entirely one package. internal/handlers was the slowest in all 16 measured runs, at 4-5x the next: 16.7 s ambient, 41.3 s at GOMAXPROCS=4, 49.0 s under deliberate host load. Second place is unstable — internal/ciscript at 7.1-7.2 s with cores to spare, internal/delivery at up to 18.5 s without. Eight of fifteen packages run in 1.0-1.3 s.

The concentration is a consequence of where the tested behaviour lives: internal/handlers carries the bulk of the log-bounding suite added across #146, #176 and #178, each of which sweeps seven or more fills across two slog handlers. That is real coverage, not waste.

It also has a second cost, noted on #195: because go test applies -timeout uniformly per package, one slow package sets the budget for all of them. The 90 s backstop is over 100x the runtime of the smallest packages, so a genuine deadlock in a one-second package now hangs for 90 s. Reducing the spread fixes that too.

Definition of done

Not prescribed — the approach is the substance of this issue. Options worth weighing, with the obvious trap named:

  1. Reduce the sweep breadth where a fill or handler adds no discrimination. Only where it genuinely adds none — several of those fills are load-bearing and documented as such (the C0 control catches raw-byte budgeting on its own; the astral non-printable is the only case the text handler charges differently). Removing coverage to hit a time budget is the failure mode caught and rejected in #188 and it must not happen here.
  2. Parallelise. Many of these subtests are independent table cases that do not call t.Parallel(). Likely the largest win for the least risk.
  3. Split internal/handlers. Shrinks the spread and lets the uniform -timeout come back down.
  4. Argue it is correct as it stands and that the policy target is wrong for a repo of this shape. A legitimate answer, but it belongs upstream in https://git.eeqj.de/sneak/prompts, not as a local exception.

Whichever is chosen:

  • State the before and after for total make test, for internal/handlers, and for the slowest remaining package, each measured on the tree being shipped.
  • Demonstrate that coverage did not shrink. If any case was removed, show by mutation that the property it guarded is still caught by something else.
  • If the -timeout in script/test can come back down as a result, do that in the same change and say what the new margin is.

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 everything: the figures above predate whatever lands between now and then.
Filed because `REPO_POLICIES.md` requires it: "A suite between 20 and 60 seconds is still green, but the overage must be filed as an improvement bug against that repo." **Not milestoned 1.0.0.** On the reading I think is correct the repo is inside the hard cap and merely past the target, which policy explicitly calls green. The fix is also a real piece of work rather than a tuning change. But there is a genuine ambiguity about *which quantity* the cap governs, and if you read it the other way the repo is in breach — so the numbers are below and the call is yours if you disagree with my scoping. ## Measured By the review of https://git.eeqj.de/sneak/webhooker/pulls/195, on `next`, cache-defeated builder stage: | quantity | measured | | --- | --- | | `RUN make test` layer, cold | **62.8 s** (a second observer saw 68.4 s) | | of which: per-package test execution | **46.0 s** | | of which: cold `-race` compile of the whole tree | roughly **17 s** | | `make test` on the host, warm cache | roughly **22 s** | ## The ambiguity The policy says "`make test` must complete in under 60 seconds. That is the hard cap, and a suite that exceeds it fails." - Read as **test execution** (46.0 s): inside the 60 s cap, past the 20 s target. Green, file an improvement bug — this issue. - Read as **what CI actually pays** (62.8 s): past the hard cap, and the suite fails. The reviewer's view, which I share: the layer duration is not a clean proxy, because it bundles a cold `-race` compile of the entire tree that the cap was probably not written to include. But it is the number CI pays on every run, so it is not obviously the wrong thing to measure either. Both readings agree the repo is past the 20 s target. I have scoped this as the improvement bug the 20-60 s band requires. If you read the cap as covering the whole invocation, this is a 1.0.0 blocker instead and should be milestoned. ## Where it comes from Almost entirely one package. `internal/handlers` was the slowest in all 16 measured runs, at 4-5x the next: 16.7 s ambient, 41.3 s at `GOMAXPROCS=4`, 49.0 s under deliberate host load. Second place is unstable — `internal/ciscript` at 7.1-7.2 s with cores to spare, `internal/delivery` at up to 18.5 s without. Eight of fifteen packages run in 1.0-1.3 s. The concentration is a consequence of where the tested behaviour lives: `internal/handlers` carries the bulk of the log-bounding suite added across https://git.eeqj.de/sneak/webhooker/issues/146, https://git.eeqj.de/sneak/webhooker/issues/176 and https://git.eeqj.de/sneak/webhooker/issues/178, each of which sweeps seven or more fills across two `slog` handlers. That is real coverage, not waste. It also has a second cost, noted on https://git.eeqj.de/sneak/webhooker/pulls/195: because `go test` applies `-timeout` uniformly per package, one slow package sets the budget for all of them. The 90 s backstop is over 100x the runtime of the smallest packages, so a genuine deadlock in a one-second package now hangs for 90 s. Reducing the spread fixes that too. ## Definition of done Not prescribed — the approach is the substance of this issue. Options worth weighing, with the obvious trap named: 1. **Reduce the sweep breadth** where a fill or handler adds no discrimination. **Only where it genuinely adds none** — several of those fills are load-bearing and documented as such (the C0 control catches raw-byte budgeting on its own; the astral non-printable is the only case the text handler charges differently). Removing coverage to hit a time budget is the failure mode caught and rejected in https://git.eeqj.de/sneak/webhooker/pulls/188 and it must not happen here. 2. **Parallelise.** Many of these subtests are independent table cases that do not call `t.Parallel()`. Likely the largest win for the least risk. 3. **Split `internal/handlers`.** Shrinks the spread and lets the uniform `-timeout` come back down. 4. **Argue it is correct as it stands** and that the policy target is wrong for a repo of this shape. A legitimate answer, but it belongs upstream in https://git.eeqj.de/sneak/prompts, not as a local exception. Whichever is chosen: - State the before and after for total `make test`, for `internal/handlers`, and for the slowest remaining package, each measured on the tree being shipped. - **Demonstrate that coverage did not shrink.** If any case was removed, show by mutation that the property it guarded is still caught by something else. - If the `-timeout` in `script/test` can come back down as a result, do that in the same change and say what the new margin is. ## 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 everything: the figures above predate whatever lands between now and then.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#198