make test goes over 60 seconds when the kept Go build cache has been removed #109

Closed
opened 2026-10-15 18:35:06 +02:00 by clawbot · 6 comments
Collaborator

REPO_POLICIES.md caps make test at 60 seconds, sets 20 seconds as the target, and says time between 20 and 60 seconds is filed against the repository. Since #97 the test phase keeps Go's build cache between builds, as sneak ruled on sneak/prompts#113.

Timed on this host as script/cibuild runs it, on fresh clones, make test took between 19 and 77 seconds in five runs. None met the 20-second target, and two went over 60 seconds, the last one on next after the merge.

Where the time goes:

  • Compiling. With the kept build cache it takes about 2 seconds; without it, 30 to 36 seconds, mostly modernc.org/sqlite and modernc.org/libc under the race detector. Both runs over 60 seconds compiled everything from scratch. Every cache mount on this host, in every repository, had been created in the five minutes before it was looked at, so something removes them between builds. Docker's own cleanup limit for them is about 106 GiB, far above what they use, so Docker's automatic cleanup is not what removes them. This is not specific to sfdupes.
  • go mod download runs on every build and fetches the modules over the network: usually 7 to 30 seconds, once 64. The policy does not allow keeping the module cache.
  • The tests themselves take 13 to 18 seconds.

Definition of done

  1. make test, run as script/cibuild runs it on this host, finishes in under 60 seconds every time.
  2. Any time over 20 seconds that the policy makes unavoidable (such as the module download) is stated on this issue, with what it would take to remove it.
  3. Nothing the policy rules out is built (keeping the module cache, dropping -race or -count=1); if under 60 seconds needs one of those, it goes to sneak as one question with a recommendation.

Model: opus-5-5

`REPO_POLICIES.md` caps `make test` at 60 seconds, sets 20 seconds as the target, and says time between 20 and 60 seconds is filed against the repository. Since https://git.eeqj.de/sneak/sfdupes/pulls/97 the test phase keeps Go's build cache between builds, as sneak ruled on https://git.eeqj.de/sneak/prompts/issues/113. Timed on this host as `script/cibuild` runs it, on fresh clones, `make test` took between 19 and 77 seconds in five runs. None met the 20-second target, and two went over 60 seconds, the last one on `next` after the merge. Where the time goes: - Compiling. With the kept build cache it takes about 2 seconds; without it, 30 to 36 seconds, mostly `modernc.org/sqlite` and `modernc.org/libc` under the race detector. Both runs over 60 seconds compiled everything from scratch. Every cache mount on this host, in every repository, had been created in the five minutes before it was looked at, so something removes them between builds. Docker's own cleanup limit for them is about 106 GiB, far above what they use, so Docker's automatic cleanup is not what removes them. This is not specific to sfdupes. - `go mod download` runs on every build and fetches the modules over the network: usually 7 to 30 seconds, once 64. The policy does not allow keeping the module cache. - The tests themselves take 13 to 18 seconds. ## Definition of done 1. `make test`, run as `script/cibuild` runs it on this host, finishes in under 60 seconds every time. 2. Any time over 20 seconds that the policy makes unavoidable (such as the module download) is stated on this issue, with what it would take to remove it. 3. Nothing the policy rules out is built (keeping the module cache, dropping `-race` or `-count=1`); if under 60 seconds needs one of those, it goes to sneak as one question with a recommendation. Model: opus-5-5
clawbot self-assigned this 2026-10-15 18:35:06 +02:00
Author
Collaborator

Cause found, on the host: both build-cache purges ran an unfiltered docker builder prune -a -f — the system cron every 3 hours (/etc/cron.d/docker-builder-prune, 15:23 and 18:23 UTC slots) and the top manager's 12-hourly reclaim (16:3x UTC today) — and that removes the BuildKit cache mounts holding Go's compile cache along with the layer cache. Both now run docker builder prune -a -f --filter 'type!=exec.cachemount', which keeps the cache mounts and still purges the layer cache (project-management crons/cron.d/docker-builder-prune and crons/docker-reclaim.txt, installed at 16:45 UTC). Closing; reopen if make test stays over 60 seconds with the cache present.

Model: opus-5-5

Cause found, on the host: both build-cache purges ran an unfiltered `docker builder prune -a -f` — the system cron every 3 hours (`/etc/cron.d/docker-builder-prune`, 15:23 and 18:23 UTC slots) and the top manager's 12-hourly reclaim (16:3x UTC today) — and that removes the BuildKit cache mounts holding Go's compile cache along with the layer cache. Both now run `docker builder prune -a -f --filter 'type!=exec.cachemount'`, which keeps the cache mounts and still purges the layer cache (project-management `crons/cron.d/docker-builder-prune` and `crons/docker-reclaim.txt`, installed at 16:45 UTC). Closing; reopen if `make test` stays over 60 seconds with the cache present. Model: opus-5-5
clawbot reopened this issue 2026-10-15 18:36:27 +02:00
Author
Collaborator

Reopened: closing was early. The definition of done above wants make test measured under 60 seconds every time with the cache now kept, and the remaining time over 20 seconds stated here; that measurement is still to be done.

Model: opus-5-5

Reopened: closing was early. The definition of done above wants `make test` measured under 60 seconds every time with the cache now kept, and the remaining time over 20 seconds stated here; that measurement is still to be done. Model: opus-5-5
Author
Collaborator

Waiting on sneak/prompts#130: sneak approved keeping Go's downloaded modules and golangci-lint's analysis cache between check builds, but the change is not merged in sneak/prompts yet. Once it is, it gets re-vendored here in one reviewed PR on next, make test is timed on a fresh clone with an empty build cache, and this issue closes if that is under 60 seconds.

Model: opus-5-5

Waiting on https://git.eeqj.de/sneak/prompts/issues/130: sneak approved keeping Go's downloaded modules and golangci-lint's analysis cache between check builds, but the change is not merged in `sneak/prompts` yet. Once it is, it gets re-vendored here in one reviewed PR on `next`, `make test` is timed on a fresh clone with an empty build cache, and this issue closes if that is under 60 seconds. Model: opus-5-5
Author
Collaborator

Plan, now that sneak/prompts#131 is merged in sneak/prompts next at 0653579: one PR on next, title ending (closes #109). No Go code changes.

  1. REPO_POLICIES.md, script/cibuild, script/docker, script/lint and script/test become the copies at 0653579 (prompts/REPO_POLICIES.md for the first). Today they are the e3f79c4 copies, with nothing local to keep.

  2. Dockerfile follows the canonical Go Dockerfile at 0653579, keeping what this repository adds:

    • Header comment: the canonical one, plus this file's note about the test phase's cache.
    • lint: WORKDIR /src, COPY go.mod go.sum ./ and RUN go mod download go above ARG CACHEBUST. The gofmt check, golangci-lint config verify and golangci-lint run stay below it. golangci-lint run also mounts /root/.cache/golangci-lint.
    • test: USER nobody, ENV HOME=/tmp, WORKDIR /src, COPY go.mod go.sum ./ and RUN go mod download go above ARG CACHEBUST. go test keeps -count=1 and -race.
    • builder: RUN apk add --no-cache git make, WORKDIR /src, COPY go.mod go.sum ./ and RUN go mod download go above ARG CACHEBUST. The two COPY --from lines, the safe.directory line, COPY . . and the build come after it.
    • The runtime stage is unchanged.
  3. README.md: the paragraph after the script/ list says what holds now. Today it says every stage declares ARG CACHEBUST first and that every run downloads the modules again. TODO.md gets a Completed Steps entry.

  4. Timing: make test on a fresh clone of the branch, run under flock /srv/code/tmp/.docker-build.lock:

    • once with an empty cache, on a BuildKit builder of its own that is removed afterwards;
    • then three times in a row with the cache kept.

    One comment on this issue gives the times, any time over 20 seconds the policy makes unavoidable, and what it would take to remove it.

Done when: the PR passes an independent review and is merged to next, and make test is under 60 seconds in each run, the empty-cache one included. If the empty-cache run is over 60 seconds, that goes to sneak as one question with a recommendation. Nothing the policy rules out gets built.

Model: opus-5-5

**Plan**, now that https://git.eeqj.de/sneak/prompts/pulls/131 is merged in `sneak/prompts` `next` at `0653579`: one PR on `next`, title ending ` (closes #109)`. No Go code changes. 1. `REPO_POLICIES.md`, `script/cibuild`, `script/docker`, `script/lint` and `script/test` become the copies at `0653579` (`prompts/REPO_POLICIES.md` for the first). Today they are the `e3f79c4` copies, with nothing local to keep. 2. `Dockerfile` follows the canonical Go `Dockerfile` at `0653579`, keeping what this repository adds: - Header comment: the canonical one, plus this file's note about the test phase's cache. - `lint`: `WORKDIR /src`, `COPY go.mod go.sum ./` and `RUN go mod download` go above `ARG CACHEBUST`. The gofmt check, `golangci-lint config verify` and `golangci-lint run` stay below it. `golangci-lint run` also mounts `/root/.cache/golangci-lint`. - `test`: `USER nobody`, `ENV HOME=/tmp`, `WORKDIR /src`, `COPY go.mod go.sum ./` and `RUN go mod download` go above `ARG CACHEBUST`. `go test` keeps `-count=1` and `-race`. - `builder`: `RUN apk add --no-cache git make`, `WORKDIR /src`, `COPY go.mod go.sum ./` and `RUN go mod download` go above `ARG CACHEBUST`. The two `COPY --from` lines, the `safe.directory` line, `COPY . .` and the build come after it. - The runtime stage is unchanged. 3. `README.md`: the paragraph after the `script/` list says what holds now. Today it says every stage declares `ARG CACHEBUST` first and that every run downloads the modules again. `TODO.md` gets a Completed Steps entry. 4. Timing: `make test` on a fresh clone of the branch, run under `flock /srv/code/tmp/.docker-build.lock`: - once with an empty cache, on a BuildKit builder of its own that is removed afterwards; - then three times in a row with the cache kept. One comment on this issue gives the times, any time over 20 seconds the policy makes unavoidable, and what it would take to remove it. **Done when:** the PR passes an independent review and is merged to `next`, and `make test` is under 60 seconds in each run, the empty-cache one included. If the empty-cache run is over 60 seconds, that goes to sneak as one question with a recommendation. Nothing the policy rules out gets built. Model: opus-5-5
Author
Collaborator

Timed make test on a fresh clone of the branch of #131, each run under the shared build lock:

  • empty cache, on a BuildKit builder of its own that was removed afterwards: 58.4 s
  • default builder, cache kept, three runs in a row: 11.9 s, 11.8 s, 11.7 s

With the cache kept, no part is over 20 seconds; about 11 of the 12 are the tests.

The empty-cache run is under 60 seconds by 1.6. Compiling everything under the race detector took about 29 seconds of it, pulling the golang image about 10, the module download 6 and the tests 11. The policy lets all of these be kept, so a build pays for them only when the caches are gone, as on a new builder.

The one time the policy makes unavoidable is the module download after the host's cleanup. Every three hours, /etc/cron.d/docker-builder-prune removes the layers older than six hours and keeps cache mounts, so Go's build cache survives it and the module layer does not; the policy rules out keeping the modules in a cache mount. Today the download took between 4 and 7 seconds, which keeps make test just under 20. At the 7 to 30 seconds this issue measured earlier it goes over 20, and at the 64 seen once, make test would go over 60. What would remove it is a Go module proxy on this host, reached through GOPROXY, so the download never leaves the host. The canonical Dockerfile in sneak/prompts names no proxy, so adding one is sneak's call.

Model: opus-5-5

Timed `make test` on a fresh clone of the branch of https://git.eeqj.de/sneak/sfdupes/pulls/131, each run under the shared build lock: - empty cache, on a BuildKit builder of its own that was removed afterwards: 58.4 s - default builder, cache kept, three runs in a row: 11.9 s, 11.8 s, 11.7 s With the cache kept, no part is over 20 seconds; about 11 of the 12 are the tests. The empty-cache run is under 60 seconds by 1.6. Compiling everything under the race detector took about 29 seconds of it, pulling the `golang` image about 10, the module download 6 and the tests 11. The policy lets all of these be kept, so a build pays for them only when the caches are gone, as on a new builder. The one time the policy makes unavoidable is the module download after the host's cleanup. Every three hours, `/etc/cron.d/docker-builder-prune` removes the layers older than six hours and keeps cache mounts, so Go's build cache survives it and the module layer does not; the policy rules out keeping the modules in a cache mount. Today the download took between 4 and 7 seconds, which keeps `make test` just under 20. At the 7 to 30 seconds this issue measured earlier it goes over 20, and at the 64 seen once, `make test` would go over 60. What would remove it is a Go module proxy on this host, reached through `GOPROXY`, so the download never leaves the host. The canonical `Dockerfile` in `sneak/prompts` names no proxy, so adding one is sneak's call. Model: opus-5-5
Author
Collaborator

This corrects #109 (comment), which said no part of make test with the cache kept goes over 20 seconds. Some runs do: the reviewer of #131 measured about 22 seconds in four runs of six.

The extra time comes after the tests. The test command ends, and the build step then waits before Docker reports it done. In my runs that wait was anywhere from under a tenth of a second up to 9.8 seconds, while the tests took 11 to 16.

The wait is on the host. Docker's data in /var/lib/docker and the working trees in /srv/code are on one ZFS dataset, pool.fsn1app1.2025.07/docker. At its end a build step waits for the same thing a sync of that dataset waits for: its pending writes reaching the disk. I timed a sync of that dataset every half second while builds ran, and every slow step ended within a hundredth of a second of one of those syncs finishing, steps that only ran echo included. A sync there took up to about 5 seconds, and a step sometimes waits for two in a row. At the same moments a sync of another dataset in the same pool never took more than 0.02 seconds, so the delay belongs to that one dataset.

Nothing in this repository or in sneak/prompts causes it; every build step on this host pays it, whatever it runs. The policy makes it unavoidable only by putting the tests in a build step. Removing it is a host change and sneak's call. Setting sync=disabled on the dataset that holds Docker's data should end the wait at once, at the cost of losing that dataset's last few seconds of writes if the host crashes. Moving Docker's data to a dataset of its own, apart from the working trees, might shorten it. I tried neither.

Model: opus-5-5

This corrects https://git.eeqj.de/sneak/sfdupes/issues/109#issuecomment-145498, which said no part of `make test` with the cache kept goes over 20 seconds. Some runs do: the reviewer of https://git.eeqj.de/sneak/sfdupes/pulls/131 measured about 22 seconds in four runs of six. The extra time comes after the tests. The test command ends, and the build step then waits before Docker reports it done. In my runs that wait was anywhere from under a tenth of a second up to 9.8 seconds, while the tests took 11 to 16. The wait is on the host. Docker's data in `/var/lib/docker` and the working trees in `/srv/code` are on one ZFS dataset, `pool.fsn1app1.2025.07/docker`. At its end a build step waits for the same thing a sync of that dataset waits for: its pending writes reaching the disk. I timed a sync of that dataset every half second while builds ran, and every slow step ended within a hundredth of a second of one of those syncs finishing, steps that only ran `echo` included. A sync there took up to about 5 seconds, and a step sometimes waits for two in a row. At the same moments a sync of another dataset in the same pool never took more than 0.02 seconds, so the delay belongs to that one dataset. Nothing in this repository or in `sneak/prompts` causes it; every build step on this host pays it, whatever it runs. The policy makes it unavoidable only by putting the tests in a build step. Removing it is a host change and sneak's call. Setting `sync=disabled` on the dataset that holds Docker's data should end the wait at once, at the cost of losing that dataset's last few seconds of writes if the host crashes. Moving Docker's data to a dataset of its own, apart from the working trees, might shorten it. I tried neither. Model: opus-5-5
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/sfdupes#109