perf(build): investigate warm-pass compilation stall — 30s where cache says <1s

[zackees]

Problem

In the FastLED repo, fbuild's warm-pass (incremental, nothing changed) compilation takes ~30 s per sketch. The build pipeline is designed around a re-hydratable cache; in the best case the no-op rebuild should be sub-second. Somewhere between "nothing to do" and "done" there is ~30 s of wall-clock time that is not explained by actual compilation.

Acceptance criteria

• Identify the dominant stall(s) with concrete numbers (e.g., "7 s in X", "12 s in Y").
• Produce a prioritized fix list with expected savings per item.
• Drive warm-pass wall-clock down to <3 s for a representative FastLED example and document the new baseline.

Investigation checklist

1. Reproduce & baseline

• Pick a representative FastLED sketch that builds through fbuild (e.g., examples/Blink, examples/DemoReel100).
• Run cold build twice to populate cache; time each phase.
• Run warm build; record total wall-clock (expect ~30 s).
• Repeat on Linux/macOS/Windows — stall may be platform-specific.

2. Macro profiling

• Instrument BuildOrchestrator phase boundaries with Instant::now() checkpoints; log per-phase elapsed on warm run.
• Classify time into buckets: daemon handshake, config parse, fingerprint hashing, compile scheduling, per-file staleness check, linker invocation, objcopy/size, disk cache lease acquisition, framework validation, response-file regeneration.

3. Fingerprint / staleness checks

• Measure build_fingerprint hashing cost — does it mtime-scan every source & header?
• Check whether header dep-files (.d) are being re-read serially for each compile unit even when no source changed.
• Verify compile_database::write_and_copy_identical_content actually short-circuits identical-content writes (tests exist — prove runtime behavior matches).
• Look for redundant filesystem stats across framework/core/sketch trees (especially ESP-IDF which has tens of thousands of files).

4. Toolchain / package resolution

• Cold-path code that resolves toolchain binary paths — does it re-validate on every warm build via filesystem probes?
• Check whether ensure_toolchain() and ensure_framework() short-circuit fully on hot cache, or re-touch manifest / re-hash archives.
• Inspect library_manager — does it re-scan every lib dir on each build?

5. Daemon / IPC overhead

• Measure HTTP request round-trip from CLI → daemon → response for build op.
• Check WebSocket log streaming startup latency; is there a race where the CLI blocks waiting for the first log line?
• Verify daemon isn't re-initializing state (device manager, serial manager, context) between requests.

6. Process spawn cost

• Count subprocess spawns on a warm build (strace/Procmon). Each compiler probe, each file invocation, each size/objcopy call adds up.
• Check whether tool-version probes (gcc --version, ar --version, etc.) are cached across builds.

7. Build graph execution

• Is there a serial bottleneck (e.g., single-threaded pre-flight before the parallel compile pool starts)?
• Does the pipeline wait on cargo check-style early rejection before spawning parallel workers?
• Measure gap between "build request accepted" and "first worker starts" vs "last worker finishes" and "response sent".

8. ESP-IDF / framework-specific

• ESP-IDF sdkconfig hashing — is the full tree walked?
• SDK lib scan (libxxx.a files) — cached or re-globbed?
• Include path validation — does it stat each directory on every build?

9. Disk cache

• disk_cache::lease acquisition time on warm build.
• disk_cache::gc::reconcile_on_open — does it run on every build or only at daemon start?
• Archive/extract paths — confirm nothing is being re-extracted on warm run.

10. Cross-reference FastLED CI badges

• Pull recent CI build durations from the FastLED repo badges/actions.
• Compare warm-rebuild time per platform across the badge matrix; outliers point at platform-specific stalls.
• If any badge shows a regression trend, correlate to recent fbuild commits.

Deliverables

• A docs/PERF_WARM_BUILD.md (or issue comment) summarizing the findings with concrete timing tables.
• One or more follow-up issues/PRs per identified stall, with the fix scope and expected savings.
• Updated warm-build baseline captured in a benchmark under tests/ or a crates/fbuild-build/benches/ entry so regressions are caught early.

Context

• Reference: CLAUDE.md "Key Constraints" — cache re-hydration is a core design goal.
• Related: perf(deploy): replace esptool subprocess with espflash native crate #66 (esptool subprocess overhead in deploy path — same class of problem, different phase).
• Related: Outstanding work: ledger removal, send_op errors, async API, B5a hardening, espflash native, sector-selective flashing #18 historical tracker for pipeline perf work.

[zackees]

Issue #91 — Macro-profiling results (warm ESP32 build)

TL;DR: The 30-second warm-build stall is almost entirely post-response process-teardown, not compile/link/IPC. The actual build work is 34-71 ms (fingerprint cache hit); the daemon HTTP round-trip is 50-70 ms; the rest (up to 120-180 s in PowerShell) is the CLI process waiting for its detached grandchild daemon to release a shell-pipe handle that leaks via bInheritHandles=TRUE on CreateProcess.

Test setup

• Platform: Windows 10, fbuild commit f86d17a, release binary target/x86_64-pc-windows-msvc/release/fbuild.exe.
• Project: tests/platform/esp32dev (ESP32 + Arduino 3.x, 57-file Arduino core archive, firmware.elf 4.99 MB, .bin 288 KB). Behavior indistinguishable from FastLED/Blink.ino on the same board since both hit the same fingerprint fast-path.
• Methodology: three-run warm sequence — two cold runs populated packages and compile cache; measurements taken on the third run with .fbuild/build/esp32dev/release/* artifacts intact and the fingerprint sidecar valid.
• Instrumentation: temporary timers via file sink (%TEMP%/fbuild-diag.log) at each major CLI/daemon checkpoint — run_build entry/exit, ensure_daemon_running sub-phases, build_streaming (POST, headers, first byte, result-event parse, stream end).

Summary table — warm run, hot daemon (idle + running)

Bucket	Measured	% of total	Expected	Gap
CLI startup (main entry -> run_build)	3 ms	3%	<10 ms	OK
ensure_daemon_running health check	1 ms	1%	1-2 ms	OK
HTTP POST /api/build + headers	2 ms	2%	1-2 ms	OK
Daemon: config parse + platform resolve	~5 ms	5%	<10 ms	OK
Daemon: fingerprint load + hash	~25 ms	27%	~10 ms	slight (file I/O)
Daemon: fast-path artifact existence checks	~5 ms	5%	<5 ms	OK
Stream end / response drain	1 ms	1%	<5 ms	OK
CLI teardown (main returning -> exit)	~55 ms	57%	<5 ms	LARGE
Total wall-clock (bash)	92-133 ms	100%	~50 ms	modest

Summary table — warm run, cold daemon (must spawn)

Bucket	Measured	% of total	Expected	Gap
Initial health() probe (timeout)	2007 ms	47%	10 ms	HIGH — 2s timeout on instant connection refusal
spawn_daemon_process -> first healthy poll	110 ms	3%	50-100 ms	OK
HTTP build round-trip	53 ms	1%	50 ms	OK
Rust CLI main() end-to-end	2175 ms
CLI process teardown (main returns -> shell unblocks)	0-125 s	varies	<100 ms	CRITICAL when pipe-inherited
Total wall-clock, PowerShell	125-187 s			97-99% stall
Total wall-clock, bash + 2>/dev/null	4.2 s			fine

Subprocess-spawn count on warm run

• Daemon already running: 0 subprocesses spawned. No gcc/ld/esptool/ar. Fingerprint cache hits cleanly and the orchestrator returns cached artifacts at orchestrator.rs:392-412. Verified via Get-WmiObject Win32_Process during the build window.
• Daemon not running: 1 subprocess spawned (fbuild-daemon.exe).

Top 3 stalls (ranked by user-visible impact)

1. Grandchild daemon inherits parent shell's stderr pipe -> 120-180 s process-exit stall on Windows

• Location: crates/fbuild-cli/src/daemon_client.rs:851-900 (spawn_daemon_process).
• Root cause: Rust's Command::spawn on Windows sets bInheritHandles=TRUE in CreateProcess whenever any custom stdio is provided (we provide all three: Stdio::null/null/from(log_file)). The daemon is spawned with CREATE_NO_WINDOW | DETACHED_PROCESS, but those flags govern console attachment, not handle inheritance. Every handle in the CLI marked HANDLE_FLAG_INHERIT — including the shell's stderr pipe that PowerShell/MinTTY gives the CLI on startup — flows through into the daemon. When the CLI exits, the shell still holds a read handle to that pipe and blocks until all writers close. The daemon lives 120 s (SELF_EVICTION_TIMEOUT in context.rs:53), so the shell reliably hangs ~120 s on PowerShell and sometimes on mintty-bash.
• Repro: stop daemon, then powershell -c "& fbuild.exe build tests/platform/esp32dev -e esp32dev" -> 125 s. Add 2>$null (PS) or 2>/dev/null (bash) -> 4.2 s. Confirmed by timing: main() enters at T+0 and returns at T+2.2 s; the shell only unblocks at T+125-187 s. The stall duration matches SELF_EVICTION_TIMEOUT exactly.
• Suggested fix: use raw CreateProcessW via windows-sys with bInheritHandles=FALSE and only the three explicit STD handles in STARTUPINFO. Alternatively, before cmd.spawn(), call SetHandleInformation(GetStdHandle(STD_ERROR_HANDLE), HANDLE_FLAG_INHERIT, 0) (and same for stdout/stdin) to strip inheritability from the CLI's stdio handles; restore after spawn. Effort: 1-2 hours.

2. 2-second socket-connect timeout when the daemon isn't running

• Location: crates/fbuild-cli/src/daemon_client.rs:390-398 (DaemonClient::health), called twice per CLI invocation (display_daemon_stats_compact + ensure_daemon_running). The Windows TCP stack returns WSAECONNREFUSED nearly instantly on a dead port (verified: Test-NetConnection RTT <1 ms), but reqwest's .timeout(2s) applies to the whole send-await and waits the full timeout before surfacing failure.
• Root cause: every CLI invocation against a stopped daemon incurs 2-4 s of pure timeout wall before the spawn path begins.
• Suggested fix: short-circuit with a raw std::net::TcpStream::connect_timeout(_, 100ms) probe before the reqwest call, or add reqwest::ClientBuilder::connect_timeout(Duration::from_millis(100)) to the shared client. Effort: 15 minutes.

3. display_daemon_stats_compact duplicates the health probe on every command

• Location: crates/fbuild-cli/src/main.rs:445. The compact status banner is printed before every command — including build, which then calls ensure_daemon_running() and repeats the same health check. On a cold daemon that's 2+2=4 s of pure health-probe timeout before any work starts.
• Suggested fix: skip the banner for commands that will spawn the daemon themselves, or pass the probe result through. Effort: 30 minutes.

Unexpected findings

• Short-circuits verified working. Esp32Orchestrator::build (crates/fbuild-build/src/esp32/orchestrator.rs:315-415) correctly short-circuits on warm builds: fingerprint match returns in ~34 ms with zero compiler invocations. compile_database_path is preserved and reused. fbuild-packages::ensure_installed is never reached on the cache-hit path.
• No toolchain/framework re-validation on warm hot-daemon runs. The warm-path guard at orchestrator.rs:315 happens before ensure_installed for toolchain and framework.
• Library manager not rescanned. lib_deps is empty for this sketch, but the code path shows the manager is never called on fingerprint-match.
• Compile-DB identical-content writer works. compile_db_is_current + expected_output_path avoid rewriting the JSON when unchanged.
• Daemon self-eviction timeout = 120 s (crates/fbuild-daemon/src/context.rs:53). The exact duration of the observed PowerShell stall — smoking gun that the shell waits for the daemon itself to die.
• The stall is shell-dependent. PowerShell hangs every time. Bash in some harnesses hangs, in others (stderr already piped somewhere else) does not. The issue is fully real for interactive Windows users.
• The 2 s health() timeout is 2x the Python reference daemon's 1 s — worth parity-checking.

Top follow-up fixes (not done here — deferred)

• F1 (CRITICAL): strip HANDLE_FLAG_INHERIT from CLI stdio before spawning daemon on Windows; or switch to raw CreateProcessW with bInheritHandles=FALSE.
• F2 (HIGH): add 100 ms connect_timeout before the 2 s request timeout on health()/daemon_info().
• F3 (MEDIUM): skip or defer display_daemon_stats_compact on commands that will call ensure_daemon_running.
• F4 (LOW): reduce SELF_EVICTION_TIMEOUT to 30 s so that even if F1 is deferred, the worst-case stall shrinks.

Reproduction commands

# Build fbuild (msvc target is where artifacts actually land on Windows):
uv run cargo build --release -p fbuild-cli -p fbuild-daemon
BIN=C:/Users/niteris/dev/fbuild/target/x86_64-pc-windows-msvc/release

# Warm up (run twice):
$BIN/fbuild.exe build C:/Users/niteris/dev/fbuild/tests/platform/esp32dev -e esp32dev
$BIN/fbuild.exe build C:/Users/niteris/dev/fbuild/tests/platform/esp32dev -e esp32dev

# Stop daemon so the spawn path is exercised:
$BIN/fbuild.exe daemon stop && sleep 3

# PowerShell: reproduces the 125-s stall (stderr attached):
powershell -NoProfile -Command "Measure-Command { & '$BIN/fbuild.exe' build C:/Users/niteris/dev/fbuild/tests/platform/esp32dev -e esp32dev 2>&1 | Out-Host } | Select TotalSeconds"

# Fix verification (redirect stderr to /dev/null -> stall gone, 4.2 s total):
$BIN/fbuild.exe daemon stop && sleep 3
time $BIN/fbuild.exe build C:/Users/niteris/dev/fbuild/tests/platform/esp32dev -e esp32dev 2>/dev/null

# Hot-daemon warm run baseline (92-133 ms):
time $BIN/fbuild.exe build C:/Users/niteris/dev/fbuild/tests/platform/esp32dev -e esp32dev

Key files referenced

• crates/fbuild-cli/src/daemon_client.rs:851-900 — spawn_daemon_process (root cause)
• crates/fbuild-cli/src/daemon_client.rs:390-411 — health/health_full (2 s timeout)
• crates/fbuild-cli/src/daemon_client.rs:769-848 — ensure_daemon_running
• crates/fbuild-cli/src/main.rs:445 — display_daemon_stats_compact (redundant probe)
• crates/fbuild-daemon/src/context.rs:53 — SELF_EVICTION_TIMEOUT = 120s (the value the shell ends up waiting for)
• crates/fbuild-build/src/esp32/orchestrator.rs:315-415 — the warm-path guard (works correctly)
• crates/fbuild-build/src/esp32/orchestrator.rs:395-411 — the 0-compile fast return

Instrumentation was added locally for measurements and then removed; no PR filed.