make test is past the org 20s target and arguably past the 60s hard cap, driven almost entirely by internal/handlers #198
No Assignees
Notifications
Due Date
No due date set.
Dependencies
No dependencies set.
Reference: sneak/webhooker#198
Reference in New Issue
Block a user
Filed because
REPO_POLICIES.mdrequires 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:RUN make testlayer, cold-racecompile of the whole treemake teston the host, warm cacheThe ambiguity
The policy says "
make testmust complete in under 60 seconds. That is the hard cap, and a suite that exceeds it fails."The reviewer's view, which I share: the layer duration is not a clean proxy, because it bundles a cold
-racecompile 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/handlerswas the slowest in all 16 measured runs, at 4-5x the next: 16.7 s ambient, 41.3 s atGOMAXPROCS=4, 49.0 s under deliberate host load. Second place is unstable —internal/ciscriptat 7.1-7.2 s with cores to spare,internal/deliveryat 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/handlerscarries the bulk of the log-bounding suite added across #146, #176 and #178, each of which sweeps seven or more fills across twosloghandlers. That is real coverage, not waste.It also has a second cost, noted on #195: because
go testapplies-timeoutuniformly 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:
t.Parallel(). Likely the largest win for the least risk.internal/handlers. Shrinks the spread and lets the uniform-timeoutcome back down.Whichever is chosen:
make test, forinternal/handlers, and for the slowest remaining package, each measured on the tree being shipped.-timeoutinscript/testcan come back down as a result, do that in the same change and say what the new margin is.Implementation requirements
next, PR based onnext, single commit, title ending(closes #N).TODO.md(see #112).make bootstrapin a fresh clone before gating. Gate onmake checkplus the cache-defeated Docker lint path; all linting in Docker, never the host. Clean up every container and image; never run any prune.Fresh measurement from the review of #237, in a cache-defeated container build at host load average ~55 on 48 cores:
make test— 72.1s, 17 packages, zero(cached)lines.That is over the 60s hard cap in
REPO_POLICIES.md, not merely over the 20s target. The reviewer waived it rather than failing that PR, which was the right call: it is pre-existing onnext, load-dependent, and that branch added roughly 1.7s of it. Recording the number here so the overage is tracked rather than re-waived per PR.Related, and probably the actual lever: #225 measured the root cause of the
internal/handlersshare of this — everynewTestAppseeds an admin user and pays an Argon2id hash at 64 MB, so the package's runtime scales with how many fx applications the tests stand up rather than with what they assert. Cutting that is what would bring the whole invocation back under the cap; raising the timeout again would not.Plan. The figures on this issue predate cheaper test password hashing (#404):
script/test's header now recordsinternal/handlersat 8.5s and the slowest package,internal/database, at 15.8s, at host load 44 to 109.make testin a cache-defeated image build under the host's real load (no synthetic load on this shared host): the whole run, the test execution, and the three slowest packages.Model: opus-5-5
Opened #441. The three retention tests that made
internal/databasethe slowest package spent most of their time seeding rows 500 per insert, which this SQLite driver binds in time growing with the square of the parameter count; they now seed the same rows 50 per insert. No test case or assertion changes. The header ofscript/testrecords the new figures, which are in the PR.script/teststays, as the plan above says, although the issue body asked for it to come down where possible.internal/handlers, now the slowest package, has no single cause left to fix, andinternal/ciscript's fixed wait is the retry behaviour its test checks, so neither changes.Model: opus-5-5