perf(esp32): fresh-project build is 7.1s for one file; only 25% is linking

[zackees]

Splitting this out of #1411. That issue was a 161s no-op caused by the ESP32-S3 SDK-libs completion check failing forever and reinstalling 298 MB on every build; fixed in #1413. This is what is left underneath it, profiled on the same machine and project.

Method

Bare blink sketch, no libraries, esp32-s3-devkitc-1 (opi PSRAM, 16MB), everything installed and the framework core cache warm. Each measurement is a brand-new project directory — the "second brand-new project directory" scenario from #1347 — built once with FBUILD_PERF_LOG=1. Linux, 32-core. fbuild at 87493b2.

Three independent fresh dirs: 14.1s, 7.2s, 7.0s. The 14.1s is a first-touch outlier (first build after the 298 MB SDK tree was re-extracted, so cold page cache). Steady state is ~7.1s to compile one file and link a blink.

Where the 7,175 ms goes

Phase	ms	Note
link-convert-size	1,801	link + elf2image + size
compile-sketch	1,306	one TU
core-cache-hydrate	1,169	copy 118 cached core objects into the new build dir
compile-core-variant	1,137	zero files compiled
unaccounted	~930	gap between BuildContext::new and the named phases
boot-artifacts	349
pioarduino-resolve	295
fw-libs	144
compile-db	30
core-cache-store	11
fingerprint-save	2

Raw line:

[perf-log esp32-orchestrator] config-parse=0 ms, board-load=6 ms, build-dirs=0 ms,
  flag-collect=0 ms, pioarduino-resolve=295 ms, fp-watches-collect=0 ms,
  fast-path-check=0 ms, fw-libs=144 ms, scan-sources=0 ms, core-cache-hydrate=1169 ms,
  compile-core-variant=1137 ms, core-cache-store=11 ms, compile-sketch=1306 ms,
  compile-local-libs=0 ms, compile-db=30 ms, link-convert-size=1801 ms,
  boot-artifacts=349 ms, fingerprint-save=2 ms, total=7175 ms

Linking is 25%. The other 75% is the interesting part.

Findings, most actionable first

1. The sketch TU is recompiled in every new project dir — zccache never serves it

The zccache journal shows exactly one real compiler execution per fresh-dir build: duration_ns=2022065630, 924681032, 890555906 for the three builds above. Same sketch bytes, same flags, different directory, and the object is never reused.

This is the same mechanism #1347 documents for the framework stage (persist_failed: "same cache key produced different staged output bytes", DWARF DW_AT_comp_dir embedding the per-build path) reaching the sketch stage. #1347's investigation note already worked out that -fdebug-prefix-map is the portable flag (avr-gcc 7.3.0 has it, -ffile-prefix-map is GCC 8+ and would break every AVR build) and that the map target must be chosen in BuildLayout where the layout is known.

Worth ~1.3s here and far more on the framework stage. It carries a one-time full cold rebuild on every platform when the flag lands, so it should go in on its own.

2. compile-core-variant costs 1.14s having compiled nothing

Compiled 0 files and 1,137 ms of wall clock. Whatever this is doing — re-deriving command lines, re-stat'ing 118 objects, rebuilding the include set — it is not compiling. Should be near zero on a fully hydrated core cache.

3. core-cache-hydrate byte-copies 118 objects, 1.17s

framework core cache hydrate key=... copied=0 skipped=118 costs 1.17s even when it copies nothing on the second pass; on a fresh dir it copies all 118. zccache logs reflink_count=0, copy_count=2 on this filesystem, so the copies are not reflinked. Reflink (FICLONE / copy_file_range, CopyFileEx COW on ReFS) or hardlinks into the build dir would make this near-free on any CoW filesystem, and hardlinks work everywhere for read-only inputs.

4. pioarduino-resolve 295 ms is mostly a subprocess spawned on every build

Esptool::ensure_installed runs esptool version on every build to prove a cached binary is launchable (verify_esptool_binary, added for #1213). The tasmota build is a PyInstaller onefile — it unpacks itself to a temp dir and starts Python every time. 295 ms here; on Windows with Defender scanning the unpack, materially worse, and that is where the users in #1411/#1347 are.

The check is worth keeping, but the result should be stamped next to the install (e.g. a .verified marker keyed on the binary's mtime+size) rather than re-proven per build.

5. ~930 ms is unattributed

total=7175 minus the named phases leaves ~930 ms with no phase covering it — BuildContext::new_with_perf returns before pioarduino-resolve starts and the include-path/library-discovery work between phases is not timed. Worth adding phases before optimizing blind: "include paths: 375 total" and "compiled 42 framework built-in libraries" both happen in there.

What good looks like

Items 1–4 are ~3.5s of the 7.1s. A ~3s fresh-project build looks reachable without touching the linker, and the no-op path is already 0.3s after #1413.

Reproduction

mkdir -p blink/src && cd blink
cat > platformio.ini <<'INI'
[env:esp32_esp32_esp32s3_opi]
platform = espressif32
board = esp32-s3-devkitc-1
framework = arduino
build_flags = -DCORE_DEBUG_LEVEL=0 -DBOARD_HAS_PSRAM
board_build.memory_type = dio_opi
board_upload.flash_size = 16MB
board_build.partitions = default_16MB.csv
INI
printf '#include <Arduino.h>\nvoid setup() { pinMode(2, OUTPUT); }\nvoid loop() { digitalWrite(2, HIGH); delay(500); digitalWrite(2, LOW); delay(500); }\n' > src/main.cpp
FBUILD_PERF_LOG=1 fbuild build      # phase summary lands in ~/.fbuild/prod/daemon/daemon.log

Found while verifying #1411 / #1347.