You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
Since July 7 the bench / benchmarks (serial|parallel) jobs (ci-gate → test-bench.yml) occasionally take 1.5–5.5 hours instead of the usual ~33 minutes, blocking the merge queue. Twelve events on July 7–9 at roughly 6–8% incidence per job; both matrix shards, Intel and AMD runners, two runner-image versions, twelve unrelated PR branches. Examples: 339 min (parallel, success), 201 min (serial, success), 303 min (serial, cancelled).
Duration distribution of benchmarks (serial) successes (job-level sweep of ci-gate runs):
window
n
median
p90
max
Jun 18–30
69
31 m
35 m
38 m
Jul 1–7
73
32 m
35 m
53 m
Jul 8–9
64
31 m
34 m
201 m
Where the time goes
Gap analysis of six affected job logs shows a single silent window every time, inside db/test, between the BenchmarkSharedDomains_ComputeCommitment result line and the BenchmarkPruneSmallBatches result line — i.e. in the latter's untimed setup (generation loop + 100 inline ComputeCommitment calls + Flush/Commit + BuildFiles). ok db/test self-reports 10,297–19,244 s vs ~733 s in a healthy run; the measured prune iteration stays at 0.4–1.7 s even in the worst case, and the benchmarks right after the window run at full speed.
Crucially, the VM is healthy during the stall: the other ~238 test packages — including MDBX-heavy ones — complete concurrently at normal speed, and a sweep of ~14,000 job durations shows no other CI job type moved between the windows. The stall is inside one process, in one phase.
Ruled out
Runner hardware pools / image rollout (outliers span both CPU vendors and two image versions), fleet-wide events (no other job type affected).
A poisoned queued PR (twelve unrelated branches), cache byte budgets (cachebudget caps the envelope at RAM/32), a plainly reproducible code regression (24 local runs on a 64 GB Mac at both main and a July 5 baseline: all clean, ~500–650 s each).
A/B experiment + watchdog
To separate code from environment, test-bench.yml was overlaid with a stall watchdog (SIGQUIT to the test binaries after 60 min → the Go runtime dumps all goroutine stacks into the job log; see #22358) on two adjacent-commit branches, 12 dispatches each (24 workload samples per arm):
with the benchmark goroutine at [chan receive, 47 minutes].
Root cause
BenchmarkPruneSmallBatches's setup accumulates ~2 GB in sd.mem (random contract-code blobs dominate). SharedDomains.Flush spills the code domain through an ETL collector into ~61 files and k-way-merges them back (etl.mergeSortFiles). The spill files are read zero-copy via mmap (fileDataProvider / mmapBytesReader in db/etl/dataprovider.go), so the merge-heap keys/values alias mmap pages — db/etl/collector.go even carries a comment that element.Value may point into read-only mmap.
On a 16 GB / 4-core hosted runner whose page cache is under pressure, each bytes.Compare/copy that touches a cold spill page takes a major page fault at (possibly throttled) disk latency. At ~10 ms per fault, the ~165k-entry merge takes tens of minutes to hours — matching the observed 0.8–5.3 h continuum and its variability. Because mmap faults do not park goroutines, the dump shows the goroutine [running] in cmpbody — an I/O stall disguised as CPU work, which is what let it evade CPU-vs-I/O triage: concurrent packages (tiny I/O) run normally, and the moment the merge completes the working set shrinks, so the job "recovers" instantly. On a 64 GB dev machine the spill set stays fully cached and the merge is pure CPU (seconds) — hence zero local repro in 24 attempts.
#22154's role is amplifier, not defect-in-stack: none of its code appears in the stall stack (its code-store/state-cache write-through hooks SharedDomains.Commit, not Flush), but its aggregator-lifetime resident caches add memory pressure during the setup's 100 inline commitments, evicting spill pages on marginal VMs — consistent with onset tracking its July 7 merge and with the A/B split. Two-of-24 vs zero-of-24 is under-powered on its own (Fisher p≈0.24); the conviction comes from the dumps plus the mechanism.
Why nothing bounds a stalled run today
go test -timeout does not apply to benchmarks — testing.M.Run stops the timeout alarm before the benchmark phase (verified in the Go 1.25 sources). The job had no timeout-minutes, so it inherited GitHub's 6-hour default; stalled runs held the merge queue until cancellation. One stalled runner received an external shutdown signal mid-stall.
Trim the db/test benchmark setups with testing.Short() guards per CI-GUIDELINES ("Checking benchmarks") — make test-bench already passes -short. The ~12-minute untimed setup is the exposure that turns page-cache pressure into a multi-hour queue stall.
Consider a durable db/etl fix so merges degrade gracefully under memory pressure: batched MADV_WILLNEED on the upcoming provider windows, or switching fileDataProvider to buffered pread with explicit readahead, so a cold page costs a scheduled read instead of a blocking fault per compare.
Delete the experiment branches yperbasis/bench-ab-with22154 / yperbasis/bench-ab-pre22154 once this is triaged.
Symptom
Since July 7 the
bench / benchmarks (serial|parallel)jobs (ci-gate →test-bench.yml) occasionally take 1.5–5.5 hours instead of the usual ~33 minutes, blocking the merge queue. Twelve events on July 7–9 at roughly 6–8% incidence per job; both matrix shards, Intel and AMD runners, two runner-image versions, twelve unrelated PR branches. Examples: 339 min (parallel, success), 201 min (serial, success), 303 min (serial, cancelled).Duration distribution of
benchmarks (serial)successes (job-level sweep of ci-gate runs):Where the time goes
Gap analysis of six affected job logs shows a single silent window every time, inside
db/test, between theBenchmarkSharedDomains_ComputeCommitmentresult line and theBenchmarkPruneSmallBatchesresult line — i.e. in the latter's untimed setup (generation loop + 100 inlineComputeCommitmentcalls +Flush/Commit+BuildFiles).ok db/testself-reports 10,297–19,244 s vs ~733 s in a healthy run; the measured prune iteration stays at 0.4–1.7 s even in the worst case, and the benchmarks right after the window run at full speed.Crucially, the VM is healthy during the stall: the other ~238 test packages — including MDBX-heavy ones — complete concurrently at normal speed, and a sweep of ~14,000 job durations shows no other CI job type moved between the windows. The stall is inside one process, in one phase.
Ruled out
ReadAheaditself is feature-flag-gated off.cachebudgetcaps the envelope at RAM/32), a plainly reproducible code regression (24 local runs on a 64 GB Mac at both main and a July 5 baseline: all clean, ~500–650 s each).A/B experiment + watchdog
To separate code from environment,
test-bench.ymlwas overlaid with a stall watchdog (SIGQUIT to the test binaries after 60 min → the Go runtime dumps all goroutine stacks into the job log; see #22358) on two adjacent-commit branches, 12 dispatches each (24 workload samples per arm):yperbasis/bench-ab-with22154@ b4ad655 (first commit with execution/cache, execution/commitment, db/state: consolidate cache stack (freelru + persistent code cache) #22154) — 2 stalls (one serial, one parallel; siblings clean): run 29013660440, run 29013679650yperbasis/bench-ab-pre22154@ b85a699 (its parent) — 0 stalls, 12/12 greenBoth stalled jobs produced goroutine dumps at exactly the 60-minute mark, with the identical stack on two independent VMs:
with the benchmark goroutine at
[chan receive, 47 minutes].Root cause
BenchmarkPruneSmallBatches's setup accumulates ~2 GB insd.mem(random contract-code blobs dominate).SharedDomains.Flushspills the code domain through an ETL collector into ~61 files and k-way-merges them back (etl.mergeSortFiles). The spill files are read zero-copy via mmap (fileDataProvider/mmapBytesReaderindb/etl/dataprovider.go), so the merge-heap keys/values alias mmap pages —db/etl/collector.goeven carries a comment thatelement.Value may point into read-only mmap.On a 16 GB / 4-core hosted runner whose page cache is under pressure, each
bytes.Compare/copy that touches a cold spill page takes a major page fault at (possibly throttled) disk latency. At ~10 ms per fault, the ~165k-entry merge takes tens of minutes to hours — matching the observed 0.8–5.3 h continuum and its variability. Because mmap faults do not park goroutines, the dump shows the goroutine[running]incmpbody— an I/O stall disguised as CPU work, which is what let it evade CPU-vs-I/O triage: concurrent packages (tiny I/O) run normally, and the moment the merge completes the working set shrinks, so the job "recovers" instantly. On a 64 GB dev machine the spill set stays fully cached and the merge is pure CPU (seconds) — hence zero local repro in 24 attempts.#22154's role is amplifier, not defect-in-stack: none of its code appears in the stall stack (its code-store/state-cache write-through hooks
SharedDomains.Commit, notFlush), but its aggregator-lifetime resident caches add memory pressure during the setup's 100 inline commitments, evicting spill pages on marginal VMs — consistent with onset tracking its July 7 merge and with the A/B split. Two-of-24 vs zero-of-24 is under-powered on its own (Fisher p≈0.24); the conviction comes from the dumps plus the mechanism.Why nothing bounds a stalled run today
go test -timeoutdoes not apply to benchmarks —testing.M.Runstops the timeout alarm before the benchmark phase (verified in the Go 1.25 sources). The job had notimeout-minutes, so it inherited GitHub's 6-hour default; stalled runs held the merge queue until cancellation. One stalled runner received an external shutdown signal mid-stall.Follow-ups
db/testbenchmark setups withtesting.Short()guards per CI-GUIDELINES ("Checking benchmarks") —make test-benchalready passes-short. The ~12-minute untimed setup is the exposure that turns page-cache pressure into a multi-hour queue stall.db/etlfix so merges degrade gracefully under memory pressure: batchedMADV_WILLNEEDon the upcoming provider windows, or switchingfileDataProviderto bufferedpreadwith explicit readahead, so a cold page costs a scheduled read instead of a blocking fault per compare.yperbasis/bench-ab-with22154/yperbasis/bench-ab-pre22154once this is triaged.