CI's Linux test job takes 46–72 minutes a run, because its Python tests and the shell suite run one after the other #77
Description
tests/test_lane_helpers.sh now takes 45 minutes on the macOS job and crossed its wrapper's 2400 s bound on feat/lane-the-word at b9018c1:
tests-macos 03:18:03 -> 04:03:37 1 failed, 654 passed in 2722.13s (0:45:22)
subprocess.TimeoutExpired: Command '['bash', '…/tests/test_lane_helpers.sh']'
timed out after 2400 seconds
tests 03:17:59 -> 03:34:46 green, the same 655 cases
Every other case in that macOS job passed. #45 raised the bound to 3600 s so the cap is not the thing failing — that is not the fix, it is the cap moving out of the fix's way.
What is actually slow. The suite is ONE bash file, run serially, that does real work per case: a bare repository and two clones seeded in a mktemp -d, several thousand real git invocations, a sleep process per liveness fixture, and a growing seed register rewritten and pushed by dozens of sections. It is 2345 assertions today and every amendment adds a section — 1500 at 92eab6c, 1678 after #41, 2102 after #52 and #47, 2345 with #45's own. macOS is roughly 2.7× the Linux time for the same file, which is where the cap bit first.
Directions worth measuring before choosing one:
- Where the time actually goes. Nobody has profiled it. A
PS4-stamped run, or a section-by-section timer printed beside each== … ==heading, would say whether the cost isgitprocess spawns, thesleep-backed liveness fixtures, the register pushes, or the per-case sandbox churn — and that answer decides everything below it. - One sandbox per SECTION rather than one per file. Sections are already fenced by their
== heading ==lines; if the seeding is the cost, sections that seed nothing could share. - Splitting the file so pytest can run sections in parallel (
pytest -nis not in this repository's dependencies today, and adding one is its own decision) — the wrapper is deliberately ONE test, and that choice is documented intests/test_lane_helpers_suite.py; splitting it means keeping the bash suite's ownok/FAILvocabulary while giving pytest more than one bit, which the file's own comment explains the cost of. gititself:commit.gpgsign=false,gc.auto=0,core.fsmonitor=false,protocol.version=2and a shared template directory in the sandbox's$HOME/.gitconfigare cheap to try and easy to measure.
Wants: a measurement first, a direction second. Filed from the lane running #45, whose merge of Amendment 17's and Amendment 18's sections is what crossed the line.
Activity
brettheap commentedon Sep 15, 2026
CLAIMED — lane openRepoTools-3, session 4135b2c9-34a6-47e3-a156-5adebb632fae@Eagle, 2026-09-15T04:06:34Z, for #77
Logged in
lanes/log/openRepoTools-3.mdat846bb5b9eda35e5bf4bfe38a4049b1b2f1b5e890.The three reads (lane-collision-protocol Rule 1):
The suite's own wrapper is what failed on macOS, not a case in it: 23…
`lane`: one word lists the lanes and binds the one you pick — availab…
brettheap commentedon Sep 16, 2026
RELEASED — lane openRepoTools-3, session 4135b2c9-34a6-47e3-a156-5adebb632fae@Eagle, 2026-09-16T00:36:27Z, for #77
brettheap commentedon Sep 16, 2026
CLAIMED — lane openRepoTools-1, session df82f553-7803-49c4-8ddf-3f9acdcb8ee0@Eagle, 2026-09-16T01:07:10Z, for #77
Logged in
lanes/log/openRepoTools-1.mdat2346a217e3c871082141313c73c8c88bd8359579.The three reads (lane-collision-protocol Rule 1):
brettheap commentedon Sep 16, 2026
Lane: openRepoTools-1 — measurement only, no edits; the suite is another lane's in flight.
How this was measured
One instrumented run of
tests/test_lane_helpers.sh, reproducing exactly whattests/test_lane_helpers_suite.pydoes (same env-var pop list —LANES_FILE/EDIT/REPO/PATH/LANE/WORKSPACE_ROOT/REPOS_TSV*,AGENT_PROTOCOL_ROOT,OPENREPOTOOLS_BIN_DIR,PROJECTS_ROOT— plus the sameGIT_AUTHOR_*/GIT_COMMITTER_*defaults; also unset two moreLANES_*vars this interactive shell happened to carry ambiently, which the suite re-pins itself anyway),cwdat the repo root, run directly withbash(neverpython3 -m pytest).Shim: a
gitand asleepscript placed first on PATH (real binaries resolved viacommand -vbefore prepending the shim dir, so no recursion). Each shim reads$EPOCHREALTIME(bash 5.2, no process spawn needed to time), invokes the real binary as a child (not a literalexec, since anexeccan't log an end time — noted as a deliberate, negligible-cost deviation from the letter of the brief), appends<start> <end> <cwd> <argv>to a log, and exits with the real exit code. Verified correct on a smoke-test repo before the real run. STDOUT was piped throughwhile IFS= read -r line; do printf '%s %s\n' "$EPOCHREALTIME" "$line"; donefor arrival timestamps. Guard + lock exactly per AGENTS.md (pgrep -f '^python3 -m pyt''est'host-wide, thenflock ${TMPDIR:-/tmp}/openrepotools-pytest.lock).One run only (no second run: the biggest cost turned out to need no
bash -xto find — see below). Section boundaries come from the suite's own== … ==echo lines (20 of them) as they actually arrived in stdout, not from source line numbers.Overhead/contention caveats, stated plainly:
git rev-parse HEADin a scratch repo): direct = 0.546s (1.82ms/call), shimmed = 1.225s (4.08ms/call) → ≈2.3ms/call shim overhead. Over 50,419 real calls that's ≈116s of the totals below that is my instrumentation, not the suite — small next to the numbers that matter but not zero.python3 -m pytestruns to clear, then blocked a further 33m53s insideflock(01:56:40Z→02:30:33Z) for another lane's holder — that wait is excluded from every number below (the suite's own start/end markers bracket only thebash tests/test_lane_helpers.shinvocation itself). Separately, at least three long-livedbash tests/test_lane_helpers.shprocesses from other lanes (two later confirmed orphaned,ppid=1) were observed running on this workstation around the guard/lock window; I could not confirm whether they were still alive during my actual measurement window (02:30:33Z–03:26:16Z is the ~4-hour gap in which my own agent process was killed by a usage-limit reset and could not observe the host). Read the wall-clock figures as a plausible upper bound on isolated cost; git-spawn counts, per-call git seconds and the subcommand mix are far less sensitive to contention (they're sums of this run's own measured intervals), and relative proportions across sections/subcommands should still be informative.suite_end; an unguarded "clamp to last bucket" fallback in the analysis script silently misattributed them to the post-footer row. Fixed by dropping any shim-log row outside[suite_start, suite_end]before bucketing (0 such rows remained in-range afterward). Flagged here because it's exactly the kind of silent error this kind of report should not hide.Suite totals
Exit code was 1:
2541 passed, 1 failed, 0 skipped, 0 pending. The one failure —— is
tests/test_lane_helpers.sh:2985, inside the== Amendment 11 hotfix …==section. It is a clean exit-code mismatch (not a timeout/race shape), everything else in a 2542-assertion run passed, and correctness is out of scope for this profiling task — flagging it for the owning lane rather than diagnosing it further.Per-section table
lane <name>laneslane, numbered pick, three branchesrm -rf "$SANDBOX")Two content sections are wildly disproportionate to their own git-call count — Amendment 18 Addendum 1 (657s wall for 5509 calls / 15.4 gitS — 10x the per-call overhead of, say, Amendment 7's 7081 calls / 83.9s) and Amendment 11 decision 6
lanes(182s wall for 2985 calls / 9.0 gitS). Together they're 57% of all content wall from 2 of 20 sections. Could be genuinely heavier per-call work (numbered-pick/branch resolution across real worktrees is plausible for the first one), could be where workstation contention happened to concentrate — this run can't distinguish the two; worth an isolated re-measurement of just these two sections if the owning lane wants a firm answer.Top git subcommands
show+rev-parsealone are 71.4% of every git spawn in the suite (36,015 of 50,419) and 50.3% of git time — almost certainly the assertion helpers (is/has/hasnt) reading committed content and resolving refs to compare against expected strings. Per-call cost is telling:show/rev-parseaverage ≈2.5ms;fetch/pull/pushaverage 12–34ms (10–15x more per call) — the network-shaped plumbing is intrinsically heavier even against local bare repos, but there are two orders of magnitude fewer of them.What the numbers say
1. By far the biggest lever, and not one of the four listed: the post-footer
rm -rf "$SANDBOX"teardown, ≈31m14s, 56% of total wall. All 2542 assertions finish and the full pass/fail footer prints at content-end; the process itself doesn't exit for another 31 minutes with zero further stdout, zero further git calls, zero further sleep — only theEXITtrap's 4 (near-instant) kills and onerm -rfof a sandbox that accumulated files across 50,419 git calls remain. This host's/tmpis a deeply-layered container overlayfs (100+lowerdirentries,overlayon/and/tmpalike) on top of WSL2 — exactly the shape of filesystem where bulk unlink of many small files is disproportionately slow, andload average: 4.15at time of writing confirms real concurrent host load too. Estimated saving: most of that ~31 minutes, by backing the sandbox with tmpfs instead of the default disk-backedmktemp -dlocation. A tmpfs exists here (/dev/shm, but only 64MB — too small to size this without measuring the sandbox itself, which was already deleted by the time this was investigated); a CI image could mount one sized to the sandbox's actual footprint. This isn't literally issue #77's "one sandbox per section" idea, but it's the same diagnosis from a different angle: it's not the number of sandboxes, it's what medium the one (or many) live on and get torn down from. Splitting into per-section sandboxes without addressing the storage medium would just spread the same total unlink cost around rather than cut it.2. Second lever: the bash/sed/awk/jq churn around the git calls, not the git calls themselves — ≈1286s, 87.6% of content wall. Git execution is only 12.3% of content time even before subtracting shim overhead. This is what direction 2 ("splitting for parallel pytest") would actually attack, since it's CPU-bound per-assertion scripting that should parallelize across sections about as well as the sections turn out to be independent of each other's state (not measured here — a code-structure question, not a timing one). Estimated saving: proportional to parallelism achieved (e.g., 4-way parallel content sections ≈ content wall/4 plus fixed overhead, if state independence holds) — the more promising of the two real levers to chase after the sandbox fix.
3. Git config tweaks (direction 3): checked and not worth it. The sandbox sets no
gpgsign/gc.auto/fsmonitor/protocol.version/template-dir — nor does this operator's global config (git config --global --geton all four returns "not set").commitalready averages ≈10ms (500 calls, 4.98s total) confirming gpgsign is already off in practice;protocol.version=2has been git's default since 2.26 (this box runs 2.43.0), so setting it explicitly is a no-op;gc.auto's default 6700-loose-object threshold is never plausibly reached by these tiny per-test repos (500 commits total across the whole suite, spread over many repos); a shared template dir would save, at absolute most, the 0.53s spent across all 38git initcalls. Even zeroing out ALL git time entirely saves only 5.4% of total wall. Do not spend effort here.Not worth bothering with at all: the sleep fixtures (direction 4). 5 real
sleepcalls, 2.63s total. Thesleep 3000 &liveness fixtures (4 of them) are backgrounded and killed at cleanup before they ever complete naturally — they cost the suite nothing (confirmed: 0 appear in the completed-calls log). The only two non-trivial ones arelanes-edit.sh:762(sleep 1) and:1434(sleep 3, cut short at ~0.53s — consistent with a deliberate SIGTERM-interrupt test in the hung-push/mutex code, not a bug). This whole direction is a non-issue.macOS-vs-Linux scaling, since the issue asks specifically: process-spawn-bound cost (the ≈50K git forks and the surrounding bash/sed/awk/jq forks, together ≈94.6% of the wall time excluding the teardown gap) is exactly the class that plausibly scales with macOS's documented ~2.7x fork/exec penalty — consistent with the issue's 45–50min macOS vs ~17min Linux baselines.
sleepdoes not scale that way (it's already ~0 cost, backgrounded, everywhere). The post-footer bulk-teardown cost is a third, distinct class that this run puts front and center: it scales with the filesystem's bulk-unlink performance (APFS on macOS vs. whatever backs$TMPDIRon the Linux runner), which is a different axis than fork/exec and not necessarily the same 2.7x — worth its own measurement on macOS specifically, since if APFS handles bulk unlink of many small files poorly too, it could be an even larger fraction of the 45–50 minute macOS figure than the 56% measured here.Measured on one Linux workstation run under real contention (see caveats above); raw shim logs (50,419 git-call rows, per-section boundaries) available on request from lane openRepoTools-1's scratch if useful for a follow-up.
Give the shell suite 5400 s and its liveness fixture 6000, because da…
Amendment 19: a closed or dormant lane leaves the listing, one sweep …
brettheap commentedon Oct 6, 2026
RELEASED — lane openRepoTools-1, session df82f553-7803-49c4-8ddf-3f9acdcb8ee0@Eagle, 2026-10-06T17:40:59Z, for #77 — Brett Heap's word of 2026-10-06 (release 77 to lane 3): the measurement this lane owed is on the issue (issuecomment-5692549523: 56% of Linux wall is the exit-trap sandbox rm -rf; git spawns 5%; sleeps nil; teardown first; then parallel sections); the fix is the suite owner's; lane openRepoTools-3 claims it
brettheap commentedon Oct 6, 2026
CLAIMED — lane openRepoTools-3, session 83619980-06bb-4469-ae73-2a8c5e61981a@Eagle, 2026-10-06T17:42:32Z, for #77
Logged in
lanes/log/openRepoTools-3.mdat1396e6ed8f2b5c37b049f42450d11a4ec41dff98.The three reads (lane-collision-protocol Rule 1):
brettheap commentedon Oct 6, 2026
Deferred under Brett Heap's close-out direction of 2026-10-06 (no new scope until the existing PRs land). The writer that was about to start found, before writing anything:
/dev/shmis 64 MB and mountednoexec, and the suite runs scripts from its sandbox, so a tmpfs-backed TMPDIR is not a lever here; faster (deferred) teardown and parallel sections are. Any tmpfs check must prove it can execute a script there, not only look at free space..claude/worktrees/suite-speed(branchfeat/shell-suite-wall-time, no commits of its own, upstream unset) is left in place for whoever resumes this.Lane: openRepoTools-3
brettheap commentedon Oct 13, 2026
RELEASED — lane openRepoTools-3, session 83619980-06bb-4469-ae73-2a8c5e61981a@Eagle, 2026-10-13T18:24:13Z, for #77 — Brett Heap 2026-10-11 gave #28-#89 to lane openRepoTools-5 (its RULED line of 16:19:19Z); lane 3 holds no live work on this number
brettheap commentedon Oct 18, 2026
CLAIMED — lane openRepoTools-5, session 0d83dca2-c18c-4bb0-99ce-896e6cafea02@Eagle, 2026-10-18T20:16:18Z, for #77
Logged in
lanes/log/openRepoTools-5.mdat47eaf6e99a713a2f6e374696c8a72e17a3e388ae.The three reads (lane-collision-protocol Rule 1):
The shell suite's teardown line is said once by a flag and a failed r…
The shell suite times each of its sections and its exit-trap teardown…
The wrapper's failing-suite test no longer counts how often pytest re…
brettheap commentedon Oct 19, 2026
Lane openRepoTools-5, 2026-10-19T16:31Z: step 1a's first numbers, from a green Linux CI log (#261 landed as
b707bd7; #265, step 1b, makes the wrapper print them on a pass).This is draft PR #265's
testsjob: run 39276800512, job 118143094255, at head458f831over main55aae16. The job reported1958 passed, 51 skipped in 2695.34soverall, and the shell suite is one of those tests.What the numbers say, measurement only:
d14e482) it took 1466 s.rm -rfof the sandbox took 1 s, and 0 s in the first run. The 56% that lane 1 measured in the exit trap was on WSL's filesystem, so that finding is WSL-only.pytest -ndependency, or sharding the sections into separate jobs. That is the direction question this issue left for Brett Heap after the measurement. Lane 5 starts nothing on it without his word.Lane: openRepoTools-5
The wrapper's child pytest no longer inherits colour or CI settings, …
The wrapper's timing block is tested against a stdout that raises OSE…
The shell suite's wrapper prints the suite's timing table and teardow…
[-]The shell suite takes 45 minutes on macOS — the cap it just crossed is not the fix, its duration is[/-][+]CI's Linux test job takes 46–72 minutes a run, because its Python tests and the shell suite run one after the other[/+]brettheap commentedon Oct 23, 2026
Retitled on Brett Heap's word of 2026-10-23T15:16:44Z, given by multiple choice: "pytest-xdist -n 3 (Recommended)" for the first step, and "Later, after measuring (Recommended)" for splitting the shell suite. The macOS cap this issue was filed about is solved. What is left is the Linux job's wall. CI on 2026-10-19 and 2026-10-20 measured 46–72 min a run, with the Python tests about 55% of it and the shell suite about 45%, run one after the other.
The steps, in order:
fix/ci-python-tests-three-wide-77.Dropped: the git-config levers. All git time was 5.4% of the suite's wall (180 of 3343 s), and their saving is about zero. Local
tests/run.shstays serial.Lane: openRepoTools-5
brettheap commentedon Oct 23, 2026
Three wide, measured. The commit is
a79e05don lane openRepoTools-5's branchfix/ci-python-tests-three-wide-77: pytest-xdist 3.8.0,-n 3 --dist loadfile --no-loadscope-reorder, with the shell suite's module handed out first. It ran three times on the branch, and all four jobs were green each time.teststests-no-submoduletestsFor comparison, two serial
testsruns the same day took 50m23s (run 40001227949) and 72m13s (run 40008392449, which overlapped runs 2 and 3).What the runs show:
forkpty()intests/test_run_wrapper.py: "This process is multi-threaded, use of forkpty() may lead to deadlocks". An xdist worker runs execnet threads. No run hung.The next step is Brett Heap's, per his ruling of 2026-10-23T15:16:44Z ("Later, after measuring"). The question is whether to shard the shell suite into section groups inside its one test. That is the only lever left on the critical path.
Lane: openRepoTools-5
The test jobs' comments say that execnet floats and that the shell su…