compile-many stage-2 workers serialize at ~200ms intervals — what's the shared lock?

[zackees]

Follow-up to #337. The framework-share seed lands the big perf win (3.7s/sketch → ~200ms/sketch on uno cold), but the stage-2 workers themselves finish in a strictly serial pattern despite `sketch_jobs=4` and 16 cores available locally.

Three consecutive cold-cache uno runs all show the same pattern:

Run	s1 firmware mtime	s2 +Δ	s3 +Δ	s4 +Δ
11:54	.588	+207ms	+194ms	+200ms
12:02	.806	+196ms	+195ms	+190ms
12:36	.216	+211ms	+158ms	+164ms

If all four workers actually ran in parallel for the same duration, their firmware.elf mtimes would land within a few ms of each other. Instead they consistently spread out at near-uniform 160–210ms intervals — workers are running in parallel for SOME of the time but blocking on something shared near the end.

Candidates I'd start poking at:

• The shared zccache daemon (single sqlite WAL writer, even with WAL it serializes on commit)
• avr-ld link step — single linker process per worker, possibly contending on a temp file or framework lib path
• The fbuild perf-log mutex (probably not — even if it served all stage-2 workers, it's just a Mutex append)
• NTFS filesystem-level locks on the shared framework cache dir (`~/.fbuild/prod/cache/platforms/arduino-ArduinoCore-avr/`)

The PERF_LOG isn't useful here because each stage-2 worker emits its own perf-log frame and they don't share a timeline. A quick way to triangulate would be to emit `tracing::info!` at known phase boundaries inside each worker (seed-start, seed-end, orchestrator-start, link-start, link-end) with a worker ID, then sort the resulting log lines on wall-clock to see which span is the long one. If link-end is what's spreading out across workers and link-start is bunched, it's contention in the linker phase; if seed-end is spread out, the seed is the bottleneck (unlikely given how small the hardlink set is).

Pragmatically, the current 200ms-per-sketch baseline is already 19× better than pre-#337, so this isn't urgent. But the same contention will scale linearly: 100 sketches × 200ms ≈ 20s of serialization that should be ~5s if the workers actually fanned out.

[zackees]

Update: zccache isn't the lock.

Repro with the same 4-uno setup but FBUILD_NO_ZCCACHE=1:

compile-many: board=uno sketches=4 framework_jobs=8 sketch_jobs=4
compile-many results:
  [stage1] OK (0.09s) ...s1  AVR (atmega328p) build for uno reused cached artifacts
  [stage2] OK (0.07s) ...s2  AVR (atmega328p) build for uno reused cached artifacts
  [stage2] OK (0.05s) ...s3  AVR (atmega328p) build for uno reused cached artifacts
  [stage2] OK (0.06s) ...s4  AVR (atmega328p) build for uno reused cached artifacts
compile-many summary: stage1=1/0.10s stage2=3/0.08s total=0.18s

Per-result build_time_secs are 0.05–0.07s — fast-path warm-cache hit, no compile work. Yet firmware mtimes still spread sequentially:

	firmware mtime	delta
s1	15:32:20.944	—
s2	15:32:21.105	+161ms
s3	15:32:21.269	+164ms
s4	15:32:21.431	+162ms

So every worker takes ~160ms of wall time even when the orchestrator reports it did almost nothing (build_time_secs = 0.05–0.07s). The gap is in the orchestrator startup path, not in compile/link or zccache.

Candidate locks now look more like:

• The fbuild-packages disk_cache lease (rusqlite, single Cache connection per process). Lease::acquire does index.pin(entry_id, pid, nonce) which is a sqlite write — multiple workers will contend on the WAL writer.
• fbuild_packages::Toolchain::ensure_installed / Package::ensure_installed — does it hit the lease path? If yes, the toolchain pin is the per-worker contention point.
• framework-ensure (same shape — pin the framework cache entry).

Next step: add a tracing::info! at Lease::acquire start + finish with the entry_id, then run with FBUILD_PERF_LOG and grep for the 150ms span. If the spans line up serially across workers we have our culprit and can swap the lease to a try-pin with retry loop instead of a blocking write.

[zackees]

Localized the lock. crates/fbuild-packages/src/disk_cache/index/queries.rs:134-167 — CacheIndex::pin and unpin both do:

let conn = self.conn.lock().unwrap();

CacheIndex holds a single Mutex<rusqlite::Connection> shared across the whole process. Every stage-2 worker that calls ensure_installed on the AVR toolchain, the Arduino-AVR framework, or any other package ends up serializing through this mutex for its lease acquire+release.

Each stage-2 worker realistically takes 2–3 leases (toolchain, framework, variant). With ~50ms per pin/unpin observed-on-Windows that lines up with the 160ms-per-worker gap measured even with FBUILD_NO_ZCCACHE=1.

This is a double-lock by accident: SQLite WAL mode already serializes writers among connections without an in-process mutex. Two cleaner approaches:

1. Per-thread connection: thread_local! or pooled rusqlite::Connection (each call opens or reuses a thread-bound connection). WAL handles the actual serialization. Trade-off: connection open is ~1–5ms, but it's a one-time per thread.

2. Drop the mutex, retry on SQLITE_BUSY: replace the Mutex<Connection> with a Connection that's safe to &self — rusqlite::Connection is Sync only via internal mutex, but you can wrap each call in a while busy { backoff } loop. SQLite WAL writers serialize anyway, just at the WAL level instead of the process mutex level.

#1 is the straightforward path. I can take a swing if it's not already on someone's plate.

[zackees]

Quick follow-up before I take a swing — the analysis from yesterday isn't quite right and the fix is probably different from what I sketched.

CacheIndex already opens the SQLite db in WAL with synchronous=NORMAL. pin/unpin are writes, so even with a thread_local connection or no mutex at all they'd still serialize at the WAL writer level — that's SQLite's design, not the Rust mutex. So removing/sidestepping the Mutex<Connection> wouldn't actually help.

What's making each pin slow is almost certainly the WAL fsync. On Windows NTFS plus Defender, a single fsync runs ~30–60ms; three pins per worker (toolchain + framework + variant) lines up with the 160ms-per-worker gap I observe and the fact that each per-worker build_time_secs only accounts for 50–70ms.

Two avenues that should actually help:

1. Batch pins per worker. A worker today does three sequential UPDATE leases statements (toolchain, framework, variant). Wrapping them in a single transaction → one fsync instead of three. Drops per-worker overhead from ~150ms to ~50ms.

2. Hoist the lease to the batch level. Stage-1 acquires (toolchain, framework, variant) and stage-2 workers receive an Arc<Lease> instead of re-pinning. The same lease entry-id is shared; workers only bump a refcount in-memory. Drops per-worker overhead to ~0 on this path. Cleaner conceptually since stage-2 sketches in the same compile-many invocation are all using the exact same toolchain/framework/variant by construction.

(2) is what I'd actually like to do — it makes the data shape match the design intent (one toolchain for the whole batch). (1) is the smaller change if (2) is more disruptive than the win is worth. Happy to take (2) on if you want.

The original "swap the mutex" line is wrong, sorry — the mutex is fine, the fsyncs are the problem.