mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-10-12 18:06:11 +02:00
42ecc96556
## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - Pull requests to this repository run a large CI matrix. The slowest check sets the time a contributor waits for a green run. > - After #15826 leveled the server shards and #15831 split `workspaces-b`, the `Build` lane is the slowest check: 634s in run 38107578322 (2026-10-11 03:11Z), ahead of the next server shard at 574s. It was 533s in run 38107430861 and 543s to 568s in earlier runs that night. > - `Build` is about 100s of setup, 148s to 195s of `pnpm build`, and 278s to 320s of `scripts/verify-grok-npm-install.mjs`. The verifier stages and packs the public packages first (84s to 100s of CPU work), and only then pulls the pinned `node:24-trixie` consumer image (8 layers, 440 MB compressed) and downloads the Grok binary (65 MB gzip, 166 MB verified). Both network waits sit after the staging work on the critical path. > - Neither download depends on the packed packages. The image is pinned by digest and the Grok binary is checked against its pinned sha256 by the provisioning script, so starting them early changes no verified property. > - This pull request starts both downloads as background children before staging and joins them where they are needed: the image before the first sandbox, the binary after the negative probe. It also prints one timing line per phase so the next slow part is visible in the CI log. > - The benefit is that the whole pull and the whole Grok download hide behind the staging phase. The verifier should shed the full pull time on a fresh runner, and the next cycle can read the phase split instead of inferring it from log gaps. ## Linked Issues or Issue Description **Describe the enhancement** The `Build` PR check is now the slowest check in the run. Its last step, the public npm install verifier, pulls the consumer Docker image and downloads the Grok binary only after it has finished staging and packing the eighteen public packages. Both downloads could run while the packages are staged. **Why is this needed** The slowest check decides the wall-clock time of every PR run. In the most recent fully green run (38107578322), `Build` took 634s: `pnpm build` 195s and the verifier 320s. The verifier's log shows the staging phase ends at +100s and the Grok result arrives at +267s. The image pull and the Grok download are inside that second window, in series with the consumer install and the probes. **Proposed solution** Start `docker pull --platform linux/amd64 <pinned image>` and `provision-grok.mjs` as background children at the top of the verifier, before the staging loop. Await the image right before the first sandbox call. Provision Grok into a prefetch directory and rename it into `native/grok` only after the "npm must not provision Grok" assertion and the negative probe, so that assertion keeps its meaning and only the positive probe sees the binary. Print a `paperclip.public-npm-install.timing.v1` line with wall time per phase and the time the main flow waited on each prefetch. **Alternatives considered** - Run the verifier as its own job in parallel with `Build`. It needs the full `pnpm build` output, so that job would be as long as `Build` is now. - Warm the consumer npm cache from an Actions cache. That changes the "clean public npm install" property the verifier reports. Not done here; the new timing line will show whether the consumer install is worth that discussion. - Pack the eighteen packages concurrently. The three bundled packages run their own npm installs in series inside `prepareBundledPackage`, which is synchronous. A larger restructure; left for a later cycle with timing data. - Overlap the Pi runtime setup with the Grok probes. Both use the same consumer directory from separate containers, and the probes after provisioning are short. Not worth the concurrency on shared state. ## What Changed - `scripts/prefetch-child.mjs` (new): `startPrefetch({ name, cmd, args, cwd, env, logPath })` spawns a background child with no inherited terminal and its stdout and stderr in a log file, and returns `{ name, child, done, durationMs }`. `done` resolves on exit 0 and otherwise rejects with the tail of the log; the rejection is observed inside the helper, so an unawaited failure never becomes an unhandled rejection. `durationMs` ends at the child's last write to its log (the exit event is observed late when the caller is blocked in synchronous work; both downloads print their final status line as they complete). `stopPrefetches(prefetches, { graceMs })` sends `SIGTERM` to every child still running, escalates to `SIGKILL` after the grace period, and resolves only once all of them have exited. - `scripts/verify-grok-npm-install.mjs`: the image pull and the Grok provisioning start through the helper inside the `try` block, before the staging loop. The main flow awaits the image before the first `npm install` sandbox and awaits Grok after the negative probe, then renames the staged binary into `native/grok` before the positive probe. The `finally` block awaits `stopPrefetches` and only then removes the scratch root, so cleanup never races a child's writes. The script prints one timing JSON line after the Pi probe, with the per-phase wall times, the two `*_wait_ms` values, and the corrected `*_prefetch_ms` values. - `scripts/__tests__/prefetch-child.test.mjs` (new): seven tests run small local Node children, with no Docker or network: a successful prefetch resolves and keeps its output; the duration ends at the download even when the parent is blocked for 1.5s; a nonzero exit rejects with the log tail; a command that cannot start rejects instead of hanging the join or the stop; stopping a running child waits for its exit; a child that ignores `SIGTERM` is killed after the grace period; an unawaited failure does not produce an unhandled rejection in a fresh process. - `scripts/__tests__/grok-public-install-sandbox.test.mjs`: the source test asserts that exactly the pinned image is pulled for `linux/amd64`, that Grok is provisioned into the prefetch directory and never straight into `native/grok`, that both prefetches start before staging, that the image is joined before the first sandbox, that the rename happens after the npm assertion and the negative probe and before the positive probe, that the verifier imports the helper, and that `stopPrefetches` is awaited before the single `rmSync(root, ...)`. - `package.json`: `test:release-registry` runs the new test file. ## Verification - `node --test scripts/__tests__/prefetch-child.test.mjs scripts/__tests__/grok-public-install-sandbox.test.mjs scripts/__tests__/cursor-public-install-sandbox.test.mjs scripts/__tests__/retain-runner-qualification-packages.test.mjs`: 22 pass (7 new in `prefetch-child.test.mjs`, 12 in the sandbox file). The new file passed on three consecutive runs. - `node --check scripts/verify-grok-npm-install.mjs` passes. - `node packages/paperclip-runner/scripts/provision-grok.mjs <scratch>/prefetch/grok` on this host: `Verified Grok 1.0.13 (linux-x64)` in 1.0s, `native/grok` absent before the move, 166079904 bytes in place after it. - Docker is not installed on the host that produced this PR, so the verifier was not run end to end locally. This PR's own `Build` job runs `node scripts/verify-grok-npm-install.mjs` from the branch checkout, so it exercises the change in full. **Measured on this PR's first CI run** ([38108964834](https://github.com/paperclipai/paperclip/actions/runs/38108964834), created 03:37Z), against two `master` runs created in the same twelve minutes: | | 38108878166 (`master`, 03:35Z) | 38108995800 (`master`, 03:37Z) | 38108964834 (this PR, 03:37Z) | | --- | --- | --- | --- | | Verifier step | 307s | 248s | 219s | | `Build` job | 555s | 484s | 459s | | Slowest check in the run | `Build` 555s | server (8/12) 535s | server (12/12) 547s | The PR run's timing line: `stage_packages_ms 84464`, `image_wait_ms 1`, `consumer_install_ms 97305`, `lifecycle_rebuild_ms 3545`, `codex_probe_ms 1211`, `grok_wait_ms 0`, `grok_probes_ms 626`, `pi_setup_ms 22194`, `pi_probe_ms 7753`. Both waits are at most 1ms, so the staging phase hid both downloads in full. The window from the end of staging to the Grok result went from 161s to 167s on the two runs that motivated this PR to 102s here, so the hidden downloads were about 60s on a fresh `runs-on` spot instance. Against the two same-window `master` runs, the verifier step is 29s to 88s shorter and `Build` is 25s to 96s shorter; the spread is runner variance in `pnpm build` and the consumer install. The `image_prefetch_ms` and `grok_prefetch_ms` values on that first run (84550 and 186696) were the parent's late observation of each exit, not download times; that is the first Greptile finding, fixed by the second commit, which measures from the download's last output instead. ## Risks - Low risk. The verifier proves the same properties in the same order. The only ordering change is that the downloads start earlier; every assertion, probe, and sandbox argument is unchanged. - The Grok binary is written under the scratch root in a `prefetch` directory during staging. That directory is never mounted into a container, and the `native/grok` assertion still runs against an absent path. - A prefetch that fails early now fails the step at its join point, where the old code would have failed at the same download a few seconds later. Same outcome, same message source. - `*_prefetch_ms` is a last-output time. A child that printed early and then kept working silently would be under-reported; neither `docker pull` nor `provision-grok.mjs` behaves that way (both print their final status as they finish), and a silent child falls back to the observed exit time. - Cleanup now waits up to 5s for a child that ignores `SIGTERM` before killing it, so a failing run can end up to 5s later than before. Both children exit promptly on `SIGTERM` in practice. - The timing line is one more stdout line. Nothing in the repository parses the verifier's stdout; the two workflows that run it write the output to the job log or to a file. ## Model Used - Claude (Anthropic), model ID `claude-fable-5-1`, running as a Paperclip agent through the Claude local adapter with tool use (shell, file edits, GitHub CLI). The agent collected the CI data, made the change, ran the tests, and wrote this description. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [ ] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [ ] All Paperclip CI gates are green - [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: devinfoley <139239+devinfoley@users.noreply.github.com> Co-authored-by: Claude Fable 5.1 <noreply@anthropic.com>