bsp: fix compile-server self-deadlock, cut ECJ and footprint overhead, keep CI telemetry - #623
Merged
Conversation
The build job got ~50% slower (12-14 minutes on master before #622, 18-20 after) and the evidence needed to explain that is written by the server and then thrown away when the runner is destroyed. Two steps, both `if: always()` because a run that went wrong is the one whose telemetry is worth having: collect metrics.jsonl and the server logs into an artifact, and print a summary into the job log so the common questions need no download at all. The summary answers the question a wall clock cannot: did each compile get slower, or did fewer of them run at once? Per-project durations answer the first, machine occupancy the second, and they have different causes and different fixes. It also flags the case where cpu sits free while the queue is non-empty — admission refusing work it could take, which would be a scheduling bug rather than a slow compiler. CI is also the only environment with a realistic shape for this: 4 cores and 16GB, where the fork-memory budget actually binds. A developer machine cannot reproduce it, which is why the constrained case has gone unmeasured. Verified against a real local run, where it immediately showed 21.9% intern hit rate (sharing 1.28, well under the 2-3x that justified interning), 0% starvation, and a single compile allocating 145GB of churn.
ECJ keeps the JDK module image in statics -- JRTUtil.images, ctSymFiles,
JRT_FILE_SYSTEMS, and classCache (a SoftClassCache of already-parsed JDK
class files). Statics are per-classloader, and createEcjTools built a fresh
URLClassLoader for every compile, so each Java compile started with all four
caches empty: it re-opened ct.sym as a zip filesystem and re-read every JDK
class it touched. Reusing one loader per ECJ version is also how ECJ is meant
to be used -- the Eclipse IDE holds it for the life of the process.
Found by allocation profiling a loaded daemon: 26.6% of all sampled allocation
sat on ECJ's own thread in ClasspathJep247Jdk12.findClass -> ZipFileSystem.getPath,
churning ZipPath and byte[]. Note that this change does NOT recover that
allocation -- most of it is inherent to ECJ compiling. What it recovers is CPU
time, because a fresh loader also means ECJ's 807 classes are re-loaded per
compile and the JIT never stays warm on the compiler's own hot loops.
Measured two ways:
isolated A/B, only the classloader differs (800 files / 49.6k lines):
fresh loader ~8200 ms, 6265 MB
shared loader ~3300 ms, 6180 MB 2.5x faster, allocation ~unchanged
end-to-end, dlab dquery/ast (2265 Java files), n=1 per condition:
baseline 230.0 s
fixed 209.7 s -8.8%
The saving is per compile invocation, not per line, which is why one huge
project only nets ~9% while the synthetic case -- ten short compiles each
re-paying startup -- shows 2.5x. Builds with many Java projects pay it once
per project.
What this retains is bounded by the number of distinct ECJ versions the daemon
serves (normally one), not by compiles or workspaces: 807 classes of metaspace
plus a GC-reclaimable SoftClassCache. The previous code paid that class-loading
cost per compile instead.
Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
…ootprint
ourTreeFootprintMb sweeps the daemon's whole process tree every 5s, and on macOS
each pid meant spawning /usr/bin/footprint: ~35ms of address-space survey per
target (measured against a 6GB-heap JVM), plus parsing its output, which showed
up as 2% of the daemon's total heap allocation in a profile. proc_pid_rusage is
the syscall footprint itself reads. Measured on the same process: 11us/call
versus 27994us/call, ~2500x, and it allocates one 296-byte buffer.
RSS via a single batched `ps` was the tempting cheap fix and is wrong: on that
same 6GB-heap JVM phys_footprint reported 7190MB while RSS reported 2933MB,
because macOS compresses pages and RSS stops counting them. Subtracting a number
2.5x too small from the machine total is the class of error that produced a 63GB
fork budget on a 48GB machine, so the metric has to stay phys_footprint.
Verified proc_pid_rusage returns the same value footprint prints (7189 vs 7190MB,
the drift being live allocation between the two calls), and that offsets 72 and
240 in the 296-byte rusage_info_v4 are what offsetof reports.
Linker.downcallHandle is a restricted method: without --enable-native-access the
JVM prints four warning lines on first call and, per JEP 472, a future release
blocks the call outright. So the flag ships here rather than later:
- the daemon gets it in buildServerCommand, outside javaOpts so it stays out of
the daemon's identity key -- it is how bleep runs the server, not a tuning knob
- bleep-bsp-tests gets it in bleep.yaml, because ForkCostModelTest measures a
real process; scoped to this project rather than to every forked test JVM,
since it is this suite's need and not a general one
Also: say so when the daemon is killed from outside. Every shutdown the server
decides on sets shutdownRequested first, so finding it false in the shutdown hook
means a signal or a dead parent. This is not cosmetic -- the client reports
"BSP server crashed twice (no OutOfMemoryError recorded)", indistinguishable from
a crash, and a session diagnosed a thread dump taken by that very hook as an
idle-watchdog bug and filed a report for what was actually a `kill`.
Tested: ForkCostModelTest 8/8, including a dead pid declining rather than
returning a bogus zero, and peak >= current as a guard on the struct offsets.
The full bleep-bsp-tests run is NOT yet green -- it deadlocked twice against a
daemon built from another branch, which is being investigated separately.
Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
…he server A TestSuiteTask is charged Cost(TestFork, cpu = 1) by the DAG interpreter at admission. JvmPool.acquire then reserved cpu = 1 from the same machine governor AGAIN, from inside the already-admitted task -- asking a finite pool for a second permit while holding the first. That is fine until admission saturates. Once every permit is held by a test task, each of those tasks queues for a permit that cannot exist, and nothing can release because releasing requires finishing: machine: cpu 18/18, mem 0/24259MB, compiles 0, running 18, waiting 18 with zero fork processes, no worker thread doing anything, and the compute pool idle. It is a self-deadlock, not contention. Because machine CPU is daemon-wide while the pool is per test run, it also starved unrelated workspaces: compiles in another worktree sat behind parked test forks for 20+ minutes, and one grant was logged only after 1466599ms, when something elsewhere happened to free a permit. The two reservations were distinguishable in the queue dump only by label -- the interpreter's `test:proj:Suite` versus this one's `test Suite` -- which is why the dump reads as 18 running and 18 waiting for what looks like the same work. Fix: the interpreter is the single authority on machine-wide capacity, so the duplicate reservation goes. What stays in the pool is the local semaphore bounding one run's parallelism, which is not machine-wide and cannot deadlock against admission, and the spawn-time memory reservation, which belongs to the process rather than the suite and outlives this scope. Reproduced on this build before the change (not only on the branch where it was first seen), and diagnosed from the daemon's own queue dump plus a thread dump showing no OS thread involved -- the parked fibers are invisible to jstack, which is what made three earlier theories (leaked reservations, memory starvation, hold-and-wait behind startLimiter) plausible and wrong. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
oyvindberg
changed the title
The new peak-vs-current assertion falls back to identifying the platform when it gets no reading, and I wrote that fallback as `shouldBe ProcessMemory.Linux` -- thinking only of the two platforms that implement a reader. Windows implements neither and is `Unavailable`, so the test failed there while passing on macOS and Linux. CI caught it on windows-latest. Assert what the test actually means: only macOS answers both current and peak. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
… permit HeapPressureGate was the last scheduling decision made BELOW admission. The compile was admitted by the interpreter, took a machine-wide CPU permit, and only then slept on the gate -- up to MaxWaitMs, 60s. For that whole time it withheld capacity from every other kind of work: a test or a link that could have run waited behind a permit held by something deliberately doing nothing. That is the same shape as the test-fork double-charge fixed in e3ad7bf, and it is the reason the resource story had three authorities instead of one. It cannot deadlock the way that one did -- the wait is capped and GC resolves the condition externally -- but under sustained pressure N compiles each sit on a permit. So the gate becomes a decision the interpreter consults at admission: HeapPressureGate.decide(usage, othersCompiling, threshold, retryMs, firstRefusedAt, now): Decision a total function of what it observes, testable without a heap, a clock or a scheduler. `TaskDag.Handlers` gains `mayAdmitCompile`, which admission calls before spending a reservation on a compile; false means "not now", the task stays ready, and its permit goes to whatever else can use it. It is reconsidered on the next wakeup -- which fires when a task completes, precisely when heap is most likely to have been freed, so the 2s polling loop is not replaced by anything. Two details the sleep loop got for free and now need saying explicitly: - MaxWaitMs is enforced via a per-run map of when each project was first deferred, because there is no longer a single sleep to measure against. - othersCompiling is `> 0`, not `> 1`: this runs BEFORE the reservation, so the compile being considered is not yet in the count. `idle` bypasses the gate exactly as it bypasses tryReserve -- with nothing running, nothing will complete to reconsider the decision, so deferring would stall the build rather than delay a start. A sole compile is never deferred. Handlers is where this belongs per its own doc: new inputs go in the bundle rather than as positional parameters cascading through callsites, and every field is required, so test callsites pass `_ => IO.pure(true)` explicitly. waitForHeapPressure is deleted rather than left beside decide(), so there is only one copy of the policy. makeCompileHandler loses heapPressureThreshold with it. Tested: bleep-bsp-tests 649 passed / 0 failed (10.2x parallelism), bleep-tests 283 passed / 0 failed. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
…le machine The cancellation tests each start a job that would take 30s or 60s, cancel it, and assert both that the kill was honoured and that the call returned in under 5s (10s in one case). The first assertion is the point of the test. The second was a proxy for "it did not sit through the workload" -- but a tight wall-clock number does not measure the cancellation path, it measures how loaded the machine is, and these run alongside the rest of the suite. That proxy held only because the suite was effectively serialised: a double- charged CPU reservation capped test parallelism at ~1.4x (fixed in e3ad7bf). At the ~11x the suite now genuinely runs at, windows-latest took 6074ms here. The behaviour was correct -- terminationReason was Killed, and only the clock assertion failed: 6074 was not less than 5000 (TimeoutAndResourceTest.scala:86) So the bound moves to a named 20s, still a small fraction of the 30s/60s work it exists to rule out. Applied to all four sites, not just the one that failed: they share the pattern and the flaw, and the other three would fail the next time a runner is busy. This is loosening a test, so to be explicit about what is and is not being given up: the invariant that cancellation short-circuits the work is kept, and the accidental assertion that nothing else is running is dropped. No production code changed. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
20s was headroom picked by feel. Against the actual numbers — sub-second healthy (all eight tests in ~1.6s together), 6074ms worst on a loaded runner, 30s for the shortest workload being ruled out — 15s clears the worst observation by ~2.5x and still fails long before a cancellation that never happened. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Four changes to the compile server. They were developed together while chasing a stall, but they are independent — say the word and I will split the deadlock fix out to land on its own, since it is the only one that fixes a hang.
The deadlock (e3ad7bf)
TaskDagcharges aTestSuiteTaskCost(TestFork, cpu = 1)at admission.JvmPool.acquirethen reservedcpu = 1from the same daemon-wide governor again, from inside the already-admitted task — asking a finite pool for a second permit while holding the first.Harmless until admission saturates. Once every permit is held by a test task, each queues for a permit that cannot exist, and nothing can release because releasing requires finishing:
with zero fork processes and an idle compute pool. Because machine CPU is daemon-wide while the pool is per test run, it also starved unrelated workspaces — compiles in another worktree sat behind parked test forks for 20+ minutes, and one grant was logged only after 1466599ms, when something elsewhere happened to free a permit.
The two reservations were distinguishable in the queue dump only by label: the interpreter's
test:proj:Suiteversus the pool'stest Suite. That is why the dump reads as 18 running and 18 waiting for what looks like the same work.Fix: the interpreter is the single authority on machine-wide capacity, so the duplicate reservation goes. The pool keeps its local semaphore (bounding one run's parallelism, not machine-wide, cannot deadlock against admission) and its spawn-time memory reservation (which belongs to the process and outlives the suite).
This was not only a hang. It halved effective test parallelism whenever it did not deadlock outright.
ECJ classloader reuse (e4227d9)
ECJ keeps the JDK module image in statics —
JRTUtil.images,ctSymFiles,JRT_FILE_SYSTEMS,classCache. Statics are per-classloader, andcreateEcjToolsbuilt a freshURLClassLoaderper compile, so every Java compile re-openedct.symand re-read every JDK class it touched. Reusing one loader per ECJ version is how ECJ is meant to be used; the Eclipse IDE holds it for the process lifetime.Found by allocation profiling: 26.6% of sampled allocation sat in
ClasspathJep247Jdk12.findClass->ZipFileSystem.getPath. Note the fix does not recover that allocation — most is inherent to ECJ compiling. What it recovers is CPU, because a fresh loader also means ECJ's 807 classes are re-loaded per compile and the JIT never stays warm.dquery/ast(2265 Java files), n=1: 230.0s -> 209.7s, -8.8%The saving is per compile invocation, not per line, so one huge project nets ~9% while many Java projects each get closer to the 2.5x.
macOS footprint via syscall (2526635)
ourTreeFootprintMbsweeps the daemon's process tree every 5s, and on macOS each pid meant spawning/usr/bin/footprint: ~35ms of address-space survey per target plus output parsing, which showed as 2% of daemon heap allocation.proc_pid_rusageis the syscallfootprintitself reads: 11us/call versus 27994us/call.RSS via a batched
pswas the tempting cheap fix and is wrong: on a 6GB-heap JVMphys_footprintreported 7190MB while RSS reported 2933MB, because macOS compresses pages and RSS stops counting them. Subtracting a number 2.5x too small is the error class that produced a 63GB budget on a 48GB machine.Linker.downcallHandleis restricted, so--enable-native-accessships here too — without it the JVM warns now and, per JEP 472, blocks the call in a future release. The daemon gets it inbuildServerCommand(outsidejavaOpts, so it stays out of the daemon identity key);bleep-bsp-testsgets it inbleep.yaml, scoped to the one suite that measures a real process.Also: the shutdown hook now says when the daemon was killed from outside. Clients report
BSP server crashed twice (no OutOfMemoryError recorded), indistinguishable from a crash — a session diagnosed a thread dump taken by that very hook as an idle-watchdog bug and filed a report for what was actually akill.CI telemetry (410ed42)
Keep the compile server's
metrics.jsonlfrom every run and summarise it, so "did each compile get slower, or did fewer run at once?" does not require downloading an artifact.Testing
bleep-bsp-tests: 649 passed, 0 failed, 2 skipped — 46.8s at 11.1x parallelism (this suite previously deadlocked; the last time it completed it took 313.6s at 1.4x)bleep-tests: 283 passed, 0 failed — 57.7s at 9.7x parallelism🤖 Generated with Claude Code