meta: profiling-driven build performance burndown (Docker Linux, NightDriverStrip, cold vs hot cache)

[zackees]

Context

fbuild's end-to-end wall clock on a real project has never been measured systematically under a controlled, reproducible environment. We have anecdotal slow spots (toolchain download/extract, library resolution, sequential install steps) but no profile data separating on-CPU work from off-CPU waiting (network, disk, subprocess, lock contention).

Existing pieces this effort builds on:

• FBUILD_PERF_LOG=1 env-gated phase timing in crates/fbuild-build/src/perf_log.rs (from perf(build): investigate warm-pass compilation stall — 30s where cache says <1s #91) — coarse per-phase wall clock, emitted via tracing + stderr.
• fbuild-packages already has a parallel download pipeline; unknown how well it overlaps download → extract → install → compile in practice.
• Embedded zccache service (perf(zccache): migrate from managed wrapper binary to embedded ZccacheService in fbuild-daemon #789) covers compiler-invocation caching; this effort targets everything around the compiler.
• The NightDriverStrip benchmark fixture is referenced by the ignored test build_nightdriverstrip_demo in crates/fbuild-build/tests/esp32_build.rs (expects tests/NightDriverStrip/); the checkout is not committed, so the Docker harness must clone it.
• zackees/soldr has the Docker + script reference infrastructure (docker/cook-shared-cache/Dockerfile, perf/, PERF.md) to model the fast-rebuild container on.

Proposal

Stand up a reproducible Linux Docker profiling harness, measure cold-cache and hot-cache builds of NightDriverStrip, and use the data to drive a burndown of optimization sub-issues until fbuild's non-compiler overhead is as close to fully overlapped/concurrent as possible.

Phase 0 — Docker profiling harness

• Dockerfile optimized for fast image rebuilds (layer-cached toolchain/deps, source COPY last, or bind-mount + named volumes per the soldr pattern), based on zackees/soldr's docker + script infrastructure.
• fbuild's own cache (~/.fbuild/cache) is not persisted between container runs — cold cache means genuinely cold (fresh downloads).
• Clones NightDriverStrip as the benchmark workload (ESP32 demo env; optionally demo_c6 for a RISC-V data point).
• Orchestration script runs: (a) cold-cache build, (b) hot-cache rebuild (same container, cache intact), each N≥3 times, and archives all profiles/logs as artifacts.

Phase 1 — Instrumentation + profiling

• Event logging on: FBUILD_PERF_LOG=1 plus extending perf_log.rs/tracing spans wherever coverage is missing (download start/end per package, extract, install, per-TU compile dispatch, archive, link, daemon RPC round-trips).
• On-CPU profiling: perf record -g (or samply/cargo flamegraph) over daemon + CLI → flamegraphs.
• Off-CPU (async) profiling: off-CPU flamegraphs (perf sched / eBPF offcputime) and/or tokio-console-style async task instrumentation to expose where the pipeline waits — network, disk, subprocess, serialized stages, lock contention.

Phase 2 — Analysis → sub-issues

• Produce a cold-vs-hot phase breakdown table (wall clock per stage, % of total).
• For every stage that is (a) not cached when it should be, (b) serialized when it could overlap with download/install/compile/link, or (c) hot on-CPU in fbuild's own code: file a child sub-issue with the profile evidence attached.

Phase 3 — Optimization burndown

• Expected themes (to be confirmed by data, not assumed): overlap download ⇄ extract ⇄ install ⇄ first compiles; start compiling TUs whose deps are ready before the full install finishes; overlap archive/link prep with trailing compiles; cache anything recomputed on hot builds (config parse, library selection, header scan); remove sync-in-async stalls (continuing audit: sync code that could be async in fbuild-cli + fbuild-python (sub-issue of #813) #817).
• Out of scope: compile settings. No changes to compiler/linker flags, optimization levels, or codegen — stock settings stay stock. Everything around the compiler is fair game.
• Each optimization ships as its own PR against its sub-issue, with before/after numbers from the Phase 0 harness in the PR description.

Phase 4 — Verification + close-out

• Re-run the harness after each merged PR; final report of cold and hot wall-clock deltas vs the Phase 1 baseline on this issue.

Acceptance criteria

• Docker harness merged (Dockerfile + run script) that produces cold-cache and hot-cache builds of NightDriverStrip with fbuild cache not persisted between docker runs.
• On-CPU and off-CPU profiles + FBUILD_PERF_LOG event timelines captured for both cold and hot runs and attached to this issue.
• Baseline numbers posted: cold and hot wall clock with per-phase breakdown (median of ≥3 runs).
• Every identified slow/uncached/serialized path has a child sub-issue linked from a task list on this issue.
• All child sub-issues resolved via merged PRs, each PR showing before/after harness numbers.
• Final cold + hot wall-clock comparison vs baseline posted; all sub-issues closed; this issue closed.

Decisions

• Benchmark workload: NightDriverStrip demo env (ESP32/Xtensa) — it's the fixture the existing ignored integration test already targets and the heaviest real-world project we've built.
• Fixture provisioning: Docker harness clones NightDriverStrip at a pinned commit rather than committing the tree to this repo — keeps the repo lean, keeps runs reproducible.
• Profiler choice: perf + flamegraphs for on-CPU, off-CPU flamegraphs (perf sched/eBPF) for waits — standard Linux tooling that works in a container; exact tool swap is fine if the harness PR finds something better.
• Harness location: ci/docker-profile/ alongside the existing ci/docker-* dirs; scripts in Python via uv run per the language policy (CI scripting is the sanctioned Python use).
• Sub-issue granularity: one issue per independently-mergeable optimization, all linked from a task list here — matches the meta-issue pattern used by meta: broker-safe global artifact repository feature burndown #603.
• Priority: P2 — significant DX win, nothing shipping is blocked on it.
• Compile settings frozen: stock flags only; performance must come from caching, concurrency, and pipeline overlap.

Related issues

• perf(build): investigate warm-pass compilation stall — 30s where cache says <1s #91 — warm-build phase timing (FBUILD_PERF_LOG) — this effort extends that instrumentation.
• audit: sync code that could be async in fbuild-cli + fbuild-python (sub-issue of #813) #817 — sync-code-that-could-be-async audit — Phase 3 continues that thread with profile evidence.
• perf(zccache): migrate from managed wrapper binary to embedded ZccacheService in fbuild-daemon #789 — embedded zccache service — covers compiler caching; explicitly out of scope here.

Burndown (Phase 2 task list)

Correctness blockers found by the harness (done):

• fix(build): lite-scons harness JSON protocol is corrupted by user-script print() #945 — extra_scripts stdout corrupts lite-SCons JSON protocol (merged: fix(build): seal lite-scons harness JSON channel against user-script stdout #946)
• fix(build): escaped quotes in build_flags defines are mangled before reaching gcc (ESP32 sketch compile) #947 — escaped-quote defines mangled before gcc (merged: fix(config): consume INI shell-quoting layer in parse_flags #949)
• CI unbreak: BoardConfig: Default + rustdoc link from fix(release): restore macOS + arm64-windows lanes on soldr 0.7.98 + setup-soldr v0.9.64 #941 (merged: fix(config): derive Default for BoardConfig (unbreaks workspace check) #948)

Harness:

• feat(ci): Docker Linux profiling harness for NightDriverStrip builds #950 — Docker profiling harness (ci/docker-profile/)

Optimization sub-issues (from the Phase-1 baseline):

• perf(build): no-change rebuild recompiles the entire sketch + core variant (~103s; should be seconds) #951 — no-change rebuild recompiles sketch + core variant (fixed: 108 s → 2.1 s steady-state, PR fix(build): stop no-change rebuilds from recompiling every TU #956)
• perf(build): framework libs (~150s) recompiled per project; core cache never hydrates #952 — fw-libs recompiled per project (~150 s); core cache never hydrates
• perf(packages): overlap download/extract/install in cold pioarduino-resolve (~185-237s serialized) #953 — overlap download/extract/install in cold resolve (~185–237 s serialized)
• feat(deploy): manage esptool as a provisioned package instead of requiring pip install #954 — manage esptool as a provisioned package (P3)
• fix(build): project-relative board_build.partitions CSV not found (resolved against framework tools dir) #955 — project-relative board_build.partitions CSV ignored (correctness + blocks perf(build): no-change rebuild recompiles the entire sketch + core variant (~103s; should be seconds) #951 fingerprint persistence)
• perf(build): first rebuild after a cold build recompiles once (signature drift between cold and steady state) #957 — first rebuild after cold recompiles once (signature drift; follow-up to perf(build): no-change rebuild recompiles the entire sketch + core variant (~103s; should be seconds) #951)

[zackees]

Phase 1 baseline (harness: PR #950, fbuild @ main with #946 + #948 + #949)

Environment: Docker Desktop Linux container (WSL2 kernel 6.18), 4 vCPU / 8 GB, NightDriverStrip @ 5911331 env:demo, FBUILD_PERF_LOG=1, on-CPU perf (cpu-clock, −F 99, fp stacks) + off-CPU bpftrace/sched running during every build. fbuild cache wiped per cold run; 3 iterations per scenario.

Wall clock (median of 3)

scenario	median	min	max
cold (empty ~/.fbuild + ~/.platformio, fresh project)	774.2 s	700.8	808.4
warm (warm global cache, fresh project copy)	435.3 s	429.9	447.8
hot (no-change rebuild)	107.8 s	103.7	121.2

Per-phase medians (FBUILD_PERF_LOG, esp32-orchestrator)

phase	cold	warm	hot
pioarduino-resolve	236.7 s	0.02 s	0.01 s
fw-libs	162.6 s	150.7 s	0.001 s
compile-core-variant	11.0 s	11.0 s	10.7 s
compile-sketch	85.7 s	101.0 s	92.0 s
link-convert-size	5.1 s	4.7 s	4.4 s
config-parse	0.4 s	0.4 s	0.5 s

On-CPU profile (cold): cc1plus dominates as expected (real compiler work — out of scope per the stock-compile-settings constraint); fbuild's own tokio-rt-worker CPU is ~9% of compiler CPU. The wall-clock gaps above are therefore cache/pipelining problems, not fbuild CPU problems.

Findings → sub-issues

1. A no-change rebuild takes ~108 s — compile-sketch (92 s) and compile-core-variant (10.7 s) re-run every build; only fw-libs short-circuits. The embedded zccache also doesn't convert these recompiles into hits. Target: ≤ a few seconds.
2. fw-libs (~150 s) is recompiled for every fresh project with an identical platform/flags, and core-cache-hydrate never hits (0 ms in all 9 runs while compile-core-variant always runs ~11 s). Framework/core caching should be global, like the disk cache for packages.
3. Cold pioarduino-resolve is 185–237 s of mostly serialized download → extract → install (stderr shows repeated sequential downloading esp32-xtensa-gcc lines). Downloads, extraction, and installs should overlap with each other and with early compile phases.
4. esptool is not a managed package — a cold build on a clean machine fails at elf2image with "Install with: pip install esptool" (the harness now bundles it; fbuild should provision it like other tools).

Bugs already found and fixed by the harness on the way here: #945 (extra_scripts stdout corrupted the lite-SCons JSON protocol) and #947 (escaped-quote defines mangled before gcc) — both merged, NightDriverStrip demo now builds end-to-end (firmware.bin 753 KB, flash 18.4 %).

Artifacts (timings.jsonl, per-run flamegraphs, folded stacks, daemon perf-log lines) are archived locally under ci/docker-profile/out/baseline1/; regeneration is one command once #950 lands: uv run python ci/docker-profile/run_profile.py.