Repository navigation
e11: the restore path does not serialize — 90% of a restore is a fixed 20ms poll, and the c>=16 knee is downstream #303
Description
Measured on srv-r16b14s16 (bare metal, SH_SUBSTRATE=metal, 2026-09-21) with an
instrumented worker, while following up issue #259's result. The premise that the restore
path serializes is false, and the knee is somewhere else.
The reasoning being corrected
#259 and #260 both start from this inference (quoting #259's runbook):
Restores are not serialized by the pool mutex —
replenishOnecallsp.mu.Unlock()
beforep.warm(...)— so they already can overlap. Yet 62 Exec/s against E10's 23.06 ms
restore implies only about 1.4-way effective restore concurrency. Something in the
restore path serializes and it is notpool.mu.
The arithmetic is right; the premise it rests on is not. E10's 23 ms restore is mostly a
sleep, and a sleep consumes no resource, so there is no concurrency to account for and
nothing in the restore path to find.
Phase breakdown, 3249 restores at c=8
Per-phase timing added around firecrackerLauncher.Restore (diagnostic only):
| phase | mean | share |
|---|---|---|
prep — jail mkdir + 5 os.Link + os.Chown |
220 us | 0.8% |
wsimg — ensureWorkspaceImage check |
44 us | 0.2% |
jailer — exec.Command + cmd.Start() |
359 us | 1.3% |
sockwait — waitForUnixSocket |
24,956 us | 90.1% |
loadsnap — PUT /snapshot/load |
2,125 us | 7.7% |
| total | 27,706 us |
Real work is 2.7 ms. The rest is sleeping. Filed separately as the actionable fix: #304.
sockwait is perfectly quantized, which is what identifies the cause beyond doubt:
| sockwait | restores |
|---|---|
| ~20-22 ms | 2,535 (78%) |
| ~40-42 ms | 714 (22%) |
| < 20 ms | 0 |
Restore is FLAT in concurrency — so the knee is downstream
Same instrument at c=16:
| phase (mean us) | c=8 | c=16 | change |
|---|---|---|---|
sockwait |
24,956 | 25,984 | +4.1% |
loadsnap |
2,125 | 2,128 | +0.1% |
jailer |
359 | 406 | +13% (of 0.4ms) |
prep |
220 | 221 | — |
| total restore | 27,706 | 28,787 | +3.9% |
Meanwhile per-Exec-per-pool latency roughly doubles over the same range
(c/throughput: 8/67.76 = 118 ms -> 16/62.99 = 254 ms). With restore flat at ~28 ms, that
puts ~90 ms -> ~226 ms of growth in resume + run + destroy, not in restore.
So the c>=16 knee (issue #291) and whatever limits aggregate per-process throughput are
downstream of Restore. Instrumenting Resume / the guest Run / Destroy the same way is
the obvious next step.
What was ruled out, with evidence
Recorded so nobody re-runs these:
| candidate | verdict | evidence |
|---|---|---|
Go syscall.ForkLock serializing jailer spawns |
no | Linux builds forkpipe2.go, which refcounts concurrent forks rather than serializing them |
| fork page-table copy inflated by the 256 MiB mlocked memfile | no | microbenchmark: 10,988 spawns/s pinned vs 10,364 unpinned |
jail-directory inode (i_rwsem) contention |
no | 13,961 ops/s for the full 12-op jail lifecycle in one parent dir; 20,770 sharded. ~250x faster than needed |
| single-threaded Node relay | no | 0.04-0.09 cores mid-rung (delta-based /proc/<pid>/stat) |
| one gRPC/HTTP2 connection worker<->relay | no | the container arm reaches 75-256 Exec/s over the same path |
cgroup_mutex, /dev/kvm, snapshot page cache, /srv device |
no | all shared between the two workers in #259's treatment, which still got 2x |
| a worker-side Go mutex | no | under-load SIGQUIT dump (15 live VMMs): no goroutine in warm/Restore/acquire, no semacquire anywhere. Block profile top sites are selectgo, http.roundTrip, sync.Pool.pin |
Method notes
Instrumentation lived on a local diag/259-serializer-probe branch (never pushed): per-phase
timing in Restore, plus net/http/pprof with SetBlockProfileRate/SetMutexProfileFraction
behind SH_DIAG_PPROF. Overhead was negligible — 61.00 Exec/s instrumented vs 58.26
uninstrumented at the same coldAcquireRate ~0.998.
microvm-worker has no pprof endpoint. Adding one behind an env var would have saved
most of a day here; worth considering on its own merits.
Activity
pdettori commentedon Sep 21, 2026
Correction to this issue's own conclusion. The measurements above stand; the inference about
where the knee lives was wrong, and #305 has the answer.
What stays correct and is worth keeping:
ExecPhased,Acquireis 158 us at c=16 and >99% of acquires are warm, so the restoreis not on the Exec hot path at all. The "at c>=16 every Exec pays a restore" reading was a
coldAcquireRateartifact (#306).waitForUnixSocket's fixed 20 ms sleep, perfectly quantized (vmpool: waitForUnixSocket's fixed 20ms retry is 90% of every restore (TDD) #304).the single gRPC connection, every host-shared resource, worker-side mutexes).
What was wrong: this issue concluded that because per-Exec-per-pool latency doubled from c=8
to c=16 while restore stayed flat, "~90 ms -> ~226 ms of growth" must be in
resume + run + destroy. It is not. Measuring those phases directly shows them identical at c=8 and c=16:AcquireResumeRunDestroyNothing in
vmpooldegrades with concurrency. The apparent latency growth was queueing outsidethe pool:
session.DefaultConcurrency = 4caps a worker at 4 concurrent Execs, so at c=16 theother 12 wait. Raising
WORKER_MAX_CONCURRENTto 16 took one worker from 62.99 to 172.88Exec/s — see #305.
So the reasoning error here was mine and of the same kind this issue was written to correct:
deriving a location from a latency subtraction instead of measuring the terms. The subtraction
was sound, but it assumed the missing time was inside the pool, and it was in a queue in front of
it.
Destroyat 55% of an Exec is tracked on its own merits in #307 — as a flat cost, not as theknee.
Refs #305, rossoctl/moca-experiments#8, #307
feat(vmpool): surface Exec/restore phases and add opt-in pprof
pdettori commentedon Sep 22, 2026
Ready to close once #327 merges — with one correction to this issue's own conclusion
Both actionable children now exist, which was the condition for closing this:
waitForUnixSocketretry) — closed, fixed in PR perf(vmpool): poll finely for the API socket instead of a fixed 20ms sleep (#304) #315. Worthrecording that the predicted 5x did not materialise: it was ~18%. The 5x came from reading a ratio
off 20 ms-quantized samples, where "appears at 2 ms" and "appears at 19 ms" are the same reading.
session.DefaultConcurrency = 4) — open, and it turned out to be the larger finding.The correction: this issue's title says the
c >= 16knee is "downstream" of restore. It is notdownstream of anything — it is
session.DefaultConcurrency = 4, a fixed pool of 4 goroutinesdraining the Exec queue in each worker, which
e11-density.shnever overrode. With slots raised tomatch
c, the same host reaches 577.55 Exec/s at 64 slots against ~62 here. The two headlinefindings — the restore path does not serialize and 90% of a restore is a fixed 20 ms poll — both
hold exactly as written.
The seven ruled-out candidates are preserved in
docs/notes/e11-restore-path-dead-ends.md(PR #327), with their evidence, so they are not re-derived.
One thing that note records deliberately, because it is instructive rather than embarrassing: the
under-load SIGQUIT dump used here to rule out a worker-side mutex also showed exactly 4 goroutines
in
session.(*Session).Serve.func5. That was the answer to the whole investigation, present inthe evidence, and it was dismissed as a sampling artifact. The dump ruled out a mutex correctly —
what it was also saying is that nothing was waiting because only four things were ever running.
Leaving this open until #327 merges, so the table has a home before the thread closes.
docs: publish the Exec/s campaign results and preserve #303's dead ends
Merge pull request #327 from pdettori/docs/phase2-record-corrections
pdettori commentedon Sep 22, 2026
Follow-up filed as #328: with fine-grained polling in place (#315),
sockwaitstill measures 38.07 ms at 64 slots and 869.43 ms at 256 — so this issue's "90% of a restore is a fixed 20 ms poll" described the instrument, and the true wait is larger than the quantum it was measured in, not smaller.Both findings here survive: the restore path does not serialize, and the poll was misreporting. What changes is that the residual after fixing the poll is real work rather than sleep, and it is now the largest term in a restore.
pdettori commentedon Sep 22, 2026
Closing — the ruled-out table is now durable on
mainindocs/notes/e11-restore-path-dead-ends.md(PR #327, merged), which was the condition for closing this.Both of this issue's headline findings stand as written: the restore path does not serialize, and the poll was misreporting. What changed is everything downstream of that:
c>=16knee was not "downstream of restore" — it wassession.DefaultConcurrency = 4(session: DefaultConcurrency=4 is the per-process throughput cap — raising it beats adding workers (2.74x) #305, now closed; the correction to §E11 merged in docs(e11): the c=8 knee reproduces — and it is the 4-slot cap (#305), not density #300).So this issue's instinct that the time was not real work was half right: the 20 ms quantum was an instrument artifact, but what it was hiding is our own per-VM setup cost rather than sleep.
The seven ruled-out candidates are preserved with their evidence, including the SIGQUIT dump that correctly ruled out a worker-side mutex and, in the same output, showed exactly 4 goroutines draining the Exec queue — the answer to the whole investigation, present in the evidence and dismissed as a sampling artifact.