diff --git a/docs/ci-build-slowness-findings.md b/docs/ci-build-slowness-findings.md new file mode 100644 index 0000000..17d74c1 --- /dev/null +++ b/docs/ci-build-slowness-findings.md @@ -0,0 +1,370 @@ +# CI build slowness β€” root-cause findings (handoff) + +> Why the Hetzner CI build takes ~2 h. The bottleneck is the host-side +> `wasm-opt -O2` pass (~76–88 min). **This doc was substantially revised** after +> pulling the per-pass `/usr/bin/time -v` counters out of the real CI runs and a +> multi-source deep-research pass: the earlier "irreducible 3.5 CPU-hours of +> work, environment only moves it Β±15%" conclusion was **wrong**. See +> "Correction log" at the bottom for what changed and why. + +## πŸ†• RUN #4 VERDICT (CI run 27226030304, 2026-06-09): v130 works; the remaining 4h is ORCHESTRATION +Run #4 built **all 6 tools** on v130 on the ccx53 in **4h05m** (18:10β†’22:15 UTC). +The v121 lock convoy is confirmed dead on-box: pcbnew's `-O2` ran with **system +time 81 s / 1,495 voluntary ctx-switches** (v121: 114,075 s / 180 M). The 4h has +three *new*, measured causes β€” all orchestration, none of them wasm-opt pathology: + +| Phase | Wall | Cause | +|---|---|---| +| setup | 4 min | fine | +| deps + wx + pcbnew compile | 50 min (18:12β†’19:02) | **docker-compose capped the container at `cpus: '10'`** (dev-Mac default) on the 32-core box, with `-j 32` oversubscribed on top | +| pcbnew asyncify 24 min + `-O2` 66 min | 90 min (19:02β†’20:32) | pcbnew is **338 MB** pre-O2 (eeschema: 188 MB). `-O2` = 13,993 s user @ **354% CPU** (BINARYEN_CORES=8) β€” *real* compute, Amdahl-capped at ~4 effective cores. This is the irreducible critical path. | +| 5 remaining tools, strictly sequential | 103 min (20:32β†’22:15) | each tool's host-side wasm-opt **blocked** the next tool's container compile; wasm-opt uses ~4 of 32 cores while the container idles | + +eeschema's `-O2` was 10:38 β€” exactly the bench prediction, so the bench fixture +generalizes. The Mac does pcbnew's asyncify+O2 in ~35 min @ 6 cores (arm64 +per-core advantage); the CI gap beyond that is orchestration, fixed by: +1. **Lift the compose caps in CI** β€” `KICAD_DOCKER_CPUS`/`KICAD_DOCKER_MEM` env + interpolation in docker-compose.yml; CI sets nproc/110G (was 10/32G). +2. **Pipeline host-side wasm-opt with the next tool's compile** β€” + `KICAD_PIPELINE=1` in docker/build.sh backgrounds dyncall+finalize+asyncify+O2 + (max `KICAD_PIPELINE_JOBS=2` concurrent; pcbnew `-O2` peaks 33.6 GB RSS). + CI-only: a 32 GB dev Mac can't stack two postprocesses. +3. **BINARYEN_CORES=16** in the validate workflow (bench: 32c=8:02 vs 8cβ‰ˆ10:00 + on the eeschema fixture β€” mild win, and two concurrent postprocesses share + the box with the compile). +4. **Binaryen default bumped 121β†’130** in get-wasm-opt.sh (validated: local + 31/31 e2e; CI run #4 Chromium fully green). + +Expected: ~2h–2h20m (floor = deps + pcbnew compile + pcbnew's 90-min wasm-opt +chain). Below that needs Lever E (shrink pcbnew's `-O2` work) and/or caching +deps across runs (the ephemeral runner rebuilds deps+wx every time, ~30–50 min). + +**Run #4 e2e: 16 passed / 14 failed β€” ALL 14 Firefox-only**, across every tool +("GL canvas has zero dimensions", wizard never appears), while Chromium passed +everything. Headless-Firefox/WebGL environment problem on the Hetzner VM, not a +v130 regression (locally Firefox passes; and `-O2` exists for V8's locals limit, +i.e. Chromium is the engine that matters for the corruption check). Open issue, +tracked separately from build time. + +Correction: the "all 6 tools rc=0 in ~1h04m" local claim below was wrong β€” the +actual log (`logs/build/20260609-191138.log`) spans 19:11β†’21:15 β‰ˆ **2h04m** +(`-j 3`, BINARYEN_CORES=6). The conclusion (v130 builds a working KiCad) stands. + +## βœ… FINAL VALIDATION (run 27280051992, 2026-06-10): all 6 tools in **1h14m41s** (was 4h05m, 3.3x) +Full cold `all` build on the ccx53 with everything adopted (compose caps lifted, +KICAD_PIPELINE=1, BINARYEN_CORES=16, self-built wasm-opt v130): +- pcbnew: asyncify **5:12** (was 24:07 β€” the self-built binary at pcbnew scale), + `-O2` **52:09** (was 1:06:13). Its 58-min postprocess fully overlapped ALL + five other tools' compiles + postprocesses (eeschema asyncify 1:00 β€” was 7:22). +- Critical path is now β‰ˆ deps + pcbnew compile + pcbnew asyncify+`-O2` β‰ˆ the + whole 1h15. Going below ~1h10 requires shrinking pcbnew's `-O2` input β€” + see the wasm-EH (-fwasm-exceptions / KICAD_WASM_EH) experiment. +- e2e: 16 passed / 14 failed β€” the failures are the SAME 14 Firefox-only + environmental tests as run #4 (Chromium 100% green). No regression; Firefox + headless-GL on the Hetzner VM remains a separate open issue. + +## πŸ†• 2026-06-10 EXPERIMENT DAY: orchestration verified on-box + the release-tarball discovery + +**Repro run 27273412419** (calculator,pl_editor, pipelined, no e2e, ccx53): all +orchestration fixes confirmed on the real runner β€” deps 14 min (was 28 at the +10-CPU cap), pipeline overlap engaged (calculator's wasm-opt ran during +pl_editor's -j32 compile), whole step **32 min**. + +**The official Linux Binaryen release tarballs are badly built.** Measured on +identical fixtures with sha256-identical outputs: +- x86_64 (ccx53, run 27276830256, BINARYEN_CORES=16): asyncify 3:50 β†’ **0:58 + (4x)** with a stock gcc -O3+LTO self-build; -O2 equal (4:22 vs 4:20). +- aarch64 (M-chip QEMU VM): asyncify **13x** faster self-built; clang -O3+LTO + also beats the tarball's -O2 by 3.5%. With a good binary, Linux β‰ˆ macOS on + the same silicon (2:59 vs 2:53) β€” the "Linux is slow" gap was binary quality. +- macOS arm64: the official tarball is *well*-built (self-build 12% slower) β€” + keep the tarball on dev Macs; self-build is a Linux-CI-only fix. +β†’ Adopted: `BINARYEN_BUILD_FROM_SOURCE=1` in get-wasm-opt.sh (one-time ~5-min +build per ephemeral runner, cached in build-wasm/tools, builds wasm-opt + +wasm-emscripten-finalize). Good upstream-issue material (WebAssembly/binaryen). + +**Allocator: dead lever on v130** (VM sweep, calculator fixture): glibc 5:37, +jemalloc 5:47, mimalloc 6:59. The jemalloc preload is harmless legacy now. + +**arm64 cloud runners: ruled out** (run 27273412432, ubicloud-standard-8-arm): +calculator asyncify 10:42 / -O2 8:40 β€” Ampere burns ~1.6x the EPYC cycles and +~2x the M-chip's on the Amdahl-bound wasm-opt. Per-core speed is what matters. + +**Projection for `all`** with everything adopted: setup 3 + deps 14 + pcbnew +compile ~10 + binaryen build 5 + pcbnew asyncify ~6 + pcbnew -O2 ~60, other 5 +tools fully overlapped β‰ˆ **~1h35-40m** (from 4h05m). Next levers beyond that: +Lever E on pcbnew's -O2 (user ruled out -O1; pass-subset/removelist remain) and +deps caching across runners. + +## βœ… THE FIX (bench run 27210317273): upgrade Binaryen 121 β†’ 130 +Measured on the cached 188 MB fixture, same `-O2`, identical output size: + +| Binaryen | cores | `-O2` wall | system time | ctx-switches | effective cores | +|---|---|---|---|---|---| +| **121** (current) | 32 | **1:12:52** | 89% | 180,000,000 | ~2.6 | +| **130** | 32 | **8:02** | **1%** | **3,599** | **~10** | +| 130 | 8 | ~10:00 | 1% | 848 | ~5.8 | + +**~9Γ— faster.** v130 eliminates the `wasm::Type` lock convoy: system time 89%β†’1%, +context-switches 180Mβ†’3,599, and the work that was capped at ~2.6 parallel cores now +scales to ~10. This is the whole story β€” the "more cores = slower" and "weak Mac beats +strong Linux" symptoms were all downstream of the v121 contention bug, fixed by v130. +Ruled out on-box: `-O1` (still 88% system β€” lock is pass-independent) and fewer threads +(still ~4 effective cores β€” lock caps it regardless). It is the **version**, full stop. + +**Remaining work = validation (run #3):** the speed win is solid, but it was measured +running v130's `-O2` on a *v121*-asyncified module. `get-wasm-opt.sh` warns that +Binaryen/emsdk skew can corrupt asyncify metadata, so the real change is to build the +**whole** asyncify+`-O2` step on v130 (now selectable via `BINARYEN_VERSION=130`) and +run the **Chrome e2e suite** to confirm the app still loads. If e2e passes, bump the +default in `get-wasm-opt.sh` (and check the emsdk-bundled Binaryen matches). If it hits +"func is not a function", the emsdk Binaryen also needs bumping. + +## βœ… VALIDATED (local cold build, 2026-06-09): v130 builds a WORKING KiCad +Full from-source cold build of **all 6 tools** with `BINARYEN_VERSION=130` (no +artifacts/fixture reuse), then the KiCad e2e suite in Firefox + Chromium: + +- **Build:** `BINARYEN_VERSION=130 ./docker/build.sh all --build-deps -j 3` β†’ all 6 + tools rc=0 in ~1h04m. Each used the standalone **binaryen-130** wasm-opt for the + asyncify+`-O2` step (confirmed in logs). pcbnew `-O2` shrank it 338 MB β†’ 187 MB, so + the optimizer ran correctly β€” **no asyncify-metadata corruption, no "func is not a + function".** Sizes: pcbnew 187M, eeschema 99M, symbol_editor 99M, pl_editor 53M, + gerbview 50M, calculator 38M. +- **kicad e2e (`npm run test:kicad`): 31 passed / 1 skipped / 0 failed** across + Firefox + Chromium. Every tool renders and passes in-browser on v130. +- `-j 3` (not the default `-j 10`) is required **locally only** β€” Docker Desktop's + 15.6 GB VM OOM-kills the OpenCASCADE compile at `-j 10` on a fresh `--build-deps`. + The 128 GB Hetzner CI box has no such limit and uses `-j $(nproc)`. + +CI cross-check (run #4, validate workflow, `build all`) is the on-box confirmation. +NB: run #3 (eeschema-only build) showed 26 e2e failures β€” those were the 5 **unbuilt** +tools' missing wasm + Firefox flake, **not** a v130 regression: the identical eeschema +Firefox tests that failed there (`eeschema-ui` Delete/Backspace, text-tool dialog) all +**pass** in this full-build run. β†’ Safe to bump the `get-wasm-opt.sh` default to 130. + +## ⚠️ VERDICT (measured on-box, bench run 27197360957) β€” supersedes the memory theory +**The `-O2` cost is ~90% FUTEX LOCK CONTENTION inside wasm-opt, not memory +management.** `perf` on the live ccx53 shows ~92% of CPU in +`do_futex β†’ _raw_spin_lock β†’ native_queued_spin_lock_slowpath` β€” threads spinning +in the kernel on a contended lock β€” **identical under glibc (92%) and mimalloc +(90%)**. The lock is Binaryen's own global type mutex (`wasm::Type`), hit by every +worker thread; more threads β†’ worse contention (a lock convoy). Hard evidence it is +**not** the allocator/THP/madvise theory below: +- `madvise` calls = **0** (perf syscall count). The "purge storm" does not exist here. +- THP `compact_stall` Ξ” = **0**, `thp_fault_alloc` Ξ” = **0**. No compaction. (THP=madvise mode.) +- `mimalloc-retain` (`MIMALLOC_PURGE_DELAY=-1`) vs baseline: **1:12:52 β†’ 1:06:51, + only 8% faster**, both ~88.7% system, both ~90% futex-spinlock. Allocator is irrelevant. + +So **jemalloc / mimalloc / retain-configs / THP=never are all DEAD ENDS** (now proven +on-box, not just argued). The levers that can actually move wall-clock: +1. **Newer Binaryen** β€” the devs cut this exact `wasm::Type` contention after our + pinned **v121** (latest is v130). Highest-value; coupled to the emsdk Binaryen, + needs Chrome e2e. **The #1 thing to test.** +2. **Fewer threads** (`BINARYEN_CORES=4–8`) β€” fewer threads on the one lock = far + less contention + far less wasted CPU. But `-O2` only does ~2.6 cores of *real* + work at any cores (true at 8 and 32), so this is mostly an **efficiency/cost win, + probably not a big wall-clock win** β€” the ~2.6Γ— parallelism is the wall floor. +3. **Less `-O2` work** β€” the fixture is **188 MB** of asyncify bloat and `-O2` runs + every pass over all of it (~11,500 CPU-s of real work = the wall floor). A lighter + pass set (`-O1`/targeted) or a bigger asyncify removelist cuts that floor; needed + to get toward ~30 min. Validate output in Chrome (it exists for V8's locals limit). + +Everything below this section about "madvise TLB-shootdowns" and "THP compaction" +was the pre-measurement hypothesis and is **WRONG for this workload** β€” kept only as +the reasoning trail. Trust this section. + +## (superseded hypothesis) The memory-storm theory +The `-O2` pass is **not** CPU-bound on optimization work. It is bound by a +**kernel page-management storm** on glibc Linux: the allocator constantly returns +freed pages to the OS (`madvise(MADV_DONTNEED)`/`munmap`), and each return forces +**cross-core TLB-shootdown work** (plus, on Ubuntu 24.04, very likely +Transparent-Huge-Page compaction). That work is **system (kernel) time**, it +**scales super-linearly with thread count**, and it is **largely allocator-choice +independent** β€” which is exactly why swapping in *default* jemalloc only helped +~15%. [SUPERSEDED: on-box perf shows the system time is futex spinlock, not +TLB-shootdowns; madvise=0, compaction=0. The "futex" the prior strace saw was +lock contention, not allocator arenas. See the VERDICT above.] + +## The measurements that settle it +Per-pass `/usr/bin/time -v`, pulled from the real CI runs +(`emergence-engineering/pcbjam`, workflow "CI"). The earlier table omitted the +**context-switch and page-fault counters β€” those are the diagnostic gold.** + +### `wasm-opt -O2` pass (the ~80-min bottleneck) +| metric | 8c glibc (run 27139529490) | 32c glibc (27144910231) | 32c jemalloc-default (27186569662) | +|---|---|---|---| +| BINARYEN_CORES | 8 | 32 | 32 | +| wall clock | **1:23:57** (5037 s) | **1:28:30** (5310 s) | 1:16:23 (4583 s) | +| user time | 12,807 s | 13,043 s | 12,177 s | +| **system time** | **18,030 s (58%)** | **114,075 s (90%)** | **95,525 s (89%)** | +| % CPU | 612% | 2393% | 2349% | +| peak RSS | 39.8 GB | 39.7 GB | 39.0 GB | +| minor page faults | 73.7 M | 67.2 M | 69.7 M | +| **voluntary ctx-switches** | **674,829,131** | **180,672,277** | **149,367,474** | +| involuntary ctx-switches | 31,675 | 1,235,328 | 1,429,770 | + +### `--asyncify` pass (same machine, only ~6 GB RSS β€” shows the storm too) +| metric | 8c glibc | 32c glibc | 32c jemalloc-default | +|---|---|---|---| +| wall | 9:26 (566 s) | **10:51 (651 s)** | 8:28 (508 s) | +| user / system | 1,317 / 2,715 s | 1,187 / **19,045 s** | 994 / 14,630 s | +| voluntary ctx-switches | 61.8 M | 10.4 M | 7.3 M | + +### What these numbers prove +1. **Cores anti-scale.** Under the *same* allocator, 32c is *slower* than 8c + (-O2: 5310 vs 5037 s; asyncify: 651 vs 566 s). System time scales **~6.3Γ— + for a 4Γ— core bump** (18kβ†’114k) while user time stays flat. That super-linear- + in-cores, flat-in-user-work shape is the fingerprint of **cross-core kernel + coordination (TLB shootdowns / compaction)**, not of the optimization work. +2. **Only ~2.5 cores of real work ever happen.** user Γ· wall β‰ˆ 12,800 Γ· 5,000 β‰ˆ + **2.5** at both 8c and 32c. `wasm-opt -O2` barely parallelizes on this module + (a few asyncify-created monster functions dominate β€” Amdahl). The other ~20 + "busy" cores at 32c are burning **kernel** time, not optimizing. +3. **The contention is allocator-independent.** glibc and jemalloc both sit at + **150–680 M voluntary context-switches** and ~70 M page faults; jemalloc- + default shaved only ~16% of system time and ~14% of wall. A real arena-lock + problem would have collapsed under jemalloc. It didn't β†’ the cost is **not** + in the allocator's arenas. +4. **The ctx-switch *inversion* (8c=675 M vs 32c=181 M, yet 32c has 6Γ— the system + time)** means at 32c threads stop *sleeping* on locks and instead *spin in the + kernel* (TLB-shootdown IPIs / page-table locks) β€” consistent with the + shootdown model, not userspace mutex spinning (which would be *user* time). + +## Root cause +**A kernel virtual-memory storm driven by allocator page-return traffic.** Both +glibc and (default) jemalloc periodically hand freed pages back to the OS via +`madvise(MADV_DONTNEED)`/`munmap`. On x86-64 each such return triggers a +**TLB shootdown** β€” the OS sends IPIs to the other cores running the process's +threads to flush their TLBs β€” which costs more the more cores exist (hence the +6.3Γ— system-time blow-up 8cβ†’32c). On Ubuntu 24.04 with THP active, faulting +threads can additionally stall in **direct compaction** (`__alloc_pages_slowpath` +β†’ `try_to_compact_pages`) plus background `khugepaged`. macOS doesn't hit this +(different VM/TLB + allocator, bare-metal, only 10 cores), which is why the +weaker Mac is faster. **Which term dominates β€” shootdowns vs compaction β€” was not +yet measured on this exact module; Phase 0 of the experiment plan measures it.** + +## Deep-research corroboration (primary sources) +A fan-out research pass (Linux kernel THP docs, jemalloc/mimalloc tuning docs, +glibc-maintainer write-up, Binaryen issues) independently reached the same +diagnosis and supplied the key precedent: +- **Binaryen #5561** β€” 48-core AMD EPYC, 128 GB, Ubuntu: `wasm-opt` went + **58m35s β†’ 3m43s** (system time 2,395 min β†’ 40 s) just by switching the + allocator to **mimalloc** (which by default purges far less aggressively). + Same anti-scaling signature as ours. This is the upside ceiling. +- **Binaryen #6338** β€” a 10Γ— `wasm-opt` slowdown "fixed by using Emscripten's + mimalloc port." Multiplicative, not marginal. +- jemalloc `TUNING.md`: decay time is "a trade-off between CPU and memory" β€” the + default *keeps* issuing `madvise`, which is precisely why a default jemalloc + swap didn't help. The fix is to **disable decay** (retain memory). +- Live alternative hypothesis (do not ignore): Binaryen's own `wasm::Type` global + mutex (mutrace: 41.8 M locks / 10.7 M contentions in #5561) can contribute + futex/system time **independent of malloc** β€” unfixed by any allocator/THP + change. If allocator-retain + THP-off underperform, this is the next suspect, + and it points at **upgrading Binaryen** (see below). + +### Corrections from adversarial verification (don't repeat these overclaims) +- ❌ "MADV_DONTNEED broadcasts IPIs to *all* CPUs and is KVM-amplified" β€” refuted. + Shootdowns go only to cores that ran the process's threads; no special VM + penalty was substantiated. (Still scales with thread count.) +- ❌ "`dirty_decay_ms:-1` is the documented official fix and fully stops madvise" + β€” failed verification; one report saw madvise persist anyway. **Every retain + config must be strace/perf-verified to confirm madvise actually drops to ~0.** +- ❌ "THP high-system-time symptom definitely matches ours" β€” the *mechanism* is + well-documented but attribution to THP for *this* module is an inference; + measure it (Phase 0), don't assume. + +## Levers, ranked (exact flags) +All are env/sysctl only (no pipeline change) except D/E. 128 GB RAM vs ~40 GB +peak makes "never return memory" safe. + +| # | Lever | Exact change | Confidence | Risk | +|---|---|---|---|---| +| **A** | Fewer threads | `BINARYEN_CORES=8` (sweep 4–16) | High β€” *already in our data* (8c ties/beats 32c) | none | +| **B** | Allocator retain (KILLS the purge) | jemalloc `MALLOC_CONF=dirty_decay_ms:-1,muzzy_decay_ms:-1,background_thread:true` Β· mimalloc `MIMALLOC_PURGE_DELAY=-1` Β· glibc `MALLOC_TRIM_THRESHOLD_=-1 MALLOC_MMAP_MAX_=0` | High mechanism; **must verify madviseβ†’0** | low (more RAM) | +| **C** | Disable THP | `echo never | sudo tee /sys/kernel/mm/transparent_hugepage/{enabled,defrag}` | High mechanism | low | +| **B+C** | Stack | retain allocator + THP=never | High | low | +| **D** | Newer Binaryen / bundled mimalloc | bump `BINARYEN_VERSION` past 121 (`scripts/common/get-wasm-opt.sh`) | Med (#5561/#6338) | **Med-High**: must match the emsdk Binaryen or asyncify metadata corrupts ("func is not a function"); needs e2e | +| **E** | Shrink the `-O2` input | bigger `asyncify-removelist` / `-O1`/targeted passes vs full `-O2` | Med | Med β€” needs Chrome e2e per change | +| β€” | Contention-only controls (expected to NOT fix it) | `MALLOC_ARENA_MAX=4`, `MIMALLOC_PURGE_DECOMMITS=0` | β€” | β€” | + +**Lever / merely-reduces-contention distinction:** retain configs (B) *kill* the +madvise/munmap traffic; `MALLOC_ARENA_MAX` only trims arena-lock cost (which +isn't our bottleneck) β€” included as a control to confirm the diagnosis. + +## Expected outcome / the 30-min question +At 8c, if `-O2` parallelized perfectly with zero system time it'd be ~27 min +(12,807 s Γ· 8 Γ· 60). The gap to 84 min is the storm **plus** parallelism capped +at ~2.5Γ— β€” and 32c tying 8c implies **contention is what caps the parallelism**. +So killing the storm should cut system time *and* unlock real core scaling β†’ +**~30 min is plausible** but bounded by Binaryen's true serial fraction (unknown +until measured). Going clearly below likely also needs Lever D and/or E. The +#5561 15.8Γ— is a ceiling demonstration, not a prediction (our *user* time is real). + +## The experiment plan (single Hetzner slot at a time) +Running one full CI per config is wasteful (re-compile + e2e). Instead a +dedicated bench builds the `-O2` **input once**, caches it as an artifact, and +replays the sweep over it β€” many data points per slot, later runs skip the build. + +- **Phase 0 (in run #1):** run `baseline` with `DIAGNOSTIC=1` to attribute the + kernel time. Decision rule: + - `native_flush_tlb_multi` / `smp_call_function_many` high + `madvise` flood β†’ + **Lever B** (allocator retain). + - `try_to_compact_pages` / `compaction_*` / `__alloc_pages_slowpath` + rising + `/proc/vmstat:compact_stall` β†’ **Lever C** (THP=never). + - `wasm::Type::*` / futex with **no** madvise flood β†’ **Lever D** (Binaryen ver). +- **Phase 1:** sweep B / C / B+C over the cached fixture; confirm each drops + voluntary ctx-switches and `madvise` count by 10–100Γ—. +- **Phase 2:** validate the winner end-to-end (full build + Chrome e2e) β€” `-O2` + exists to keep asyncify functions under V8's locals limit, so a faster config + that corrupts the module is worthless. + +## The bench harness (how the next agent runs it) +Added in this branch: +- **`.github/workflows/wasm-opt-bench.yml`** β€” ephemeral Hetzner ccx53, builds-or- + downloads the fixture, runs the sweep, uploads `o2-bench-results-`. + Triggers on **push to `bench/**`** (can't collide with main CI `[main]` or the + feature-branch Hetzner CI). `concurrency: wasm-opt-bench` (one VM at a time). +- **`scripts/bench/o2-config-sweep.sh`** β€” replays `wasm-opt -O2` over the fixture + under each preset; records `time -v` counters + a perf-stat `madvise/munmap` + count; `DIAGNOSTIC=1` adds vmstat/interrupts deltas + a perf kernel-symbol + sample. Preset menu is in the script's `config_env`. +- **`scripts/bench/sweep.conf`** β€” committed run parameters (CONFIGS / CORES / + FIXTURE_RUN_ID / DIAGNOSTIC). Edit + commit + push to `bench/**` to launch. + +**Drive it:** +1. Run #1 (this branch): `CONFIGS_CONF="baseline mimalloc-retain"`, + `FIXTURE_RUN_ID_CONF=""` (builds + caches fixture), `DIAGNOSTIC_CONF=1`. +2. Note run #1's id β†’ set `FIXTURE_RUN_ID_CONF` to it so later runs skip the + ~40-min build, then sweep `"thp-off jemalloc-retain glibc-retain + thp-off+mimalloc-retain"`. +3. Core sweep the winner: `CONFIGS=""`, `CORES_CONF=8` (then 16, 4). + +Pull results: `gh run download -n o2-bench-results-`, read +`results.csv` (the `vol_ctxsw`, `sys_s`, and `madvise` columns tell the story). + +## Why local QEMU is NOT a fair proxy (asked & answered) +The existing `scripts/bench/` QEMU harness can only run the *asyncify* pass +locally β€” three independent blockers for `-O2`: (1) **RAM** β€” `-O2` needs ~40 GB, +a 32 GB Mac caps a guest at ~20 GB β†’ OOM; (2) **arch** β€” the storm is x86 IPI +TLB-shootdowns, but Apple Silicon is aarch64 with hardware-broadcast `TLBI` +(different mechanism/scaling); (3) **core count** β€” can't reach the 32-core regime +where it's worst. Use QEMU only for the free "does this config stop madvise" +smoke test on the asyncify pass; do the real numbers on the disposable ccx53. + +## Branch / repo state at handoff +- Bench work on branch **`bench/wasm-opt-allocator-sweep`** (off + `istvanmatejcsok/feat/ci-hetzner-allcores`). Adds the three files above. +- CI uses **standalone Binaryen v121** (`get-wasm-opt.sh` fallback; CI has no + local emsdk). Lever D must keep this in sync with the emsdk Binaryen. +- Repo `emergence-engineering/pcbjam`. Main CI runs on **Ubicloud** (`[main]`); + the Hetzner ccx53 only spins for the two `ci-hetzner` feature branches and the + new `bench/**` branch. "One Hetzner slot at a time" is the operative limit. +- `apply-asyncify.sh`: jemalloc auto-preload + `ASYNCIFY_ONLY=1` (stops before + -O2 β€” used to build the bench fixture) + `WASM_OPT_PRELOAD=none` sentinel. + +## Useful commands +- Pull per-pass timing from a finished CI run's live log: + `gh run view --repo emergence-engineering/pcbjam --log | grep -iE "Running wasm-opt|User time|System time|Elapsed \(wall|Maximum resident|context switches|page faults"` +- Older runs (no live log): `gh run download -n e2e-logs` β†’ `logs/build/*.log`. +- Launch a bench run: edit `scripts/bench/sweep.conf`, commit, `git push` to the + `bench/**` branch. diff --git a/docs/wasm-exceptions-experiment.md b/docs/wasm-exceptions-experiment.md new file mode 100644 index 0000000..b258c44 --- /dev/null +++ b/docs/wasm-exceptions-experiment.md @@ -0,0 +1,255 @@ +# Experiment: native wasm exceptions (-fwasm-exceptions) to shrink the asyncify/-O2 critical path + +**Status: PARKED** (2026-06-11). Compiles and links end-to-end, but blocked by an LLVM +codegen bug in emscripten 4.0.2 β€” see "The blocker" below. The code changes were tried +locally and then dropped; the full patch is preserved in the appendix of this doc, +together with everything needed to resume. + +## Why this matters + +After the 3.3x CI win (see `ci-build-slowness-findings.md`), the critical path of the +full build is pcbnew's host-side wasm-opt chain: **asyncify ~5 min + `-O2` ~52 min** +(self-built Binaryen v130 on the Hetzner ccx53). That `-O2` time is a direct function of +how big the asyncified module is β€” and the module is big because of how exceptions work. + +Emscripten's default **JS-based exception handling** routes every potentially-throwing +call that appears inside a try/catch through a JavaScript `invoke_*` trampoline. +Asyncify must treat every JS round-trip as a potential suspension point, so in an +exception-heavy codebase (KiCad + OpenCASCADE + wxWidgets) it ends up instrumenting +nearly every function: pcbnew is **338 MB pre-`-O2`**. + +**Native wasm exceptions** (`-fwasm-exceptions`) keep throw/catch entirely inside wasm: + +- no `invoke_*` trampolines, no `dynCall` machinery (verified gone in the experiment), +- asyncify's instrumentation set collapses to the genuinely-suspending call graph, +- raw linked pcbnew.wasm measured at **92 MB** (vs 338 MB) before any wasm-opt pass. + +Expected payoff: a several-fold reduction in the asyncify + `-O2` wall time on the +critical path, plus smaller shipped binaries. + +Browser support is not a concern: Chrome 95+, Firefox 100+, Safari 15.2+. + +## What it takes (no KiCad C++ changes) + +Pure compile/link-flag change. The one hard rule: **every C++ object in the link must +agree on the EH model** β€” deps (boost, anything with setjmp like cairo), wxWidgets, and +all KiCad targets. The working flag set, threaded through every compile AND link: + +``` +-fwasm-exceptions -sSUPPORT_LONGJMP=wasm -sWASM_LEGACY_EXCEPTIONS=0 +``` + +The appendix below contains the full plumbing as a patch, gated behind `KICAD_WASM_EH=1` +(default 0 = byte-identical to today): `scripts/common/env.sh`, `scripts/deps/build-boost.sh`, +`scripts/deps/build-cairo.sh`, `scripts/build-wxuniversal-wasm.sh`, +`scripts/kicad/build-kicad-target.sh`, and `docker/build.sh` (env passthrough into the +container). Save the appendix diff to a file and `git apply` it to restore. + +### Why each flag, and the failures that taught us (in order hit) + +1. **`-fwasm-exceptions` alone fails immediately**: harfbuzz (C, uses setjmp) dies with + `clang: error: invalid argument '-fwasm-exceptions' not allowed with + '-enable-emscripten-sjlj'`. JS-based setjmp/longjmp and wasm EH can't mix β†’ + add `-sSUPPORT_LONGJMP=wasm` to every compile. +2. **Stale deps bite at link**: pcbnew link failed with `undefined symbol: + emscripten_longjmp`, traced via `llvm-nm` to `libcairo.a` (its png path uses + setjmp/longjmp). The deps scripts skip-if-stamped, so flag changes do NOT trigger + rebuilds β€” `rm build-wasm/stamps/cairo.stamp` (and any other C dep with sjlj) and + rebuild. A full `--clean` deps build is the safe path. +3. **`wasm-emscripten-finalize` / `wasm-opt -all` parse failure**: `[parse exception: + popping from empty stack]` on the linked module, with both the emsdk-bundled + binaryen and official v130. emscripten 4.0.2 defaults `WASM_LEGACY_EXCEPTIONS=true` + (the old, pre-standard `exnref`-less encoding) β†’ add `-sWASM_LEGACY_EXCEPTIONS=0` + (it's a `[compile+link]` setting β€” must be on every compile too, full rebuild). + +## The blocker: LLVM codegen bug in emscripten 4.0.2 + +With all three flags and a fully clean rebuild, pcbnew compiles and links (92 MB module, +no `invoke_*`/`dynCall`), but finalize still fails with the same parse exception β€” and +this time Binaryen is not at fault. Validating the raw module with V8 itself +(container node 22.16, `node --experimental-wasm-exnref`, `WebAssembly.compile`) gives +the definitive error: + +``` +Compiling function #96546:"ShapeUpgrade_SplitSurface::Build(bool)" failed: +br_table: label arity inconsistent with previous arity 0 @+52067104 +``` + +The clang/LLVM shipped in emscripten **4.0.2** emits an invalid `br_table` instruction +(branch targets with mismatched stack arity) in OpenCASCADE code when compiling under +wasm EH. The module is malformed at the source; no Binaryen version or flag can fix it. +Latest Binaryen release is still v130, so there is no newer tarball to try either. + +## How to resume + +1. Bump `ARG EMSCRIPTEN_VERSION=4.0.2` in `docker/Dockerfile` β€” emsdk **5.0.7** (latest + 5.x, conservative) or 6.0.0 β€” to pick up a newer LLVM with the br_table fix. + Expect ~2.5–3h for image + full clean deps/wx/kicad rebuild locally. +2. `git apply` the patch from the appendix, then + `KICAD_WASM_EH=1 BINARYEN_VERSION=130 ./docker/build.sh pcbnew --build-deps -j 8` + (use a separate `COMPOSE_PROJECT_NAME` to keep the main build volume intact). +3. If finalize + asyncify + `-O2` succeed: measure the wasm-opt chain vs the current + 5 min + 52 min, then a **small Hetzner repro** (never `all` for experiments), then + full e2e. +4. **e2e audit required even if green**: asyncify cannot suspend from inside a `catch` + block (binaryen issue #4470). Any KiCad path that calls a suspending function + (file dialogs, sleeps, network) inside a catch handler will trap. Build once with + `-sASYNCIFY_ASSERTIONS` / asyncify-asserts and exercise the e2e suite to flush + these out before adopting. + +## Risk notes + +- An emsdk bump changes the compiler for the *whole* project β€” it must be validated for + the normal (JS-EH) build too, not just this experiment. +- JSPI (the long-term replacement for asyncify) was evaluated and is not viable yet: + Firefox still flag-gates it. + +## Appendix: the full plumbing patch + +Applies cleanly on top of `a563746`. Save the block below to a file and `git apply` it. + +````diff +diff --git a/docker/build.sh b/docker/build.sh +index 268b03d..456f906 100755 +--- a/docker/build.sh ++++ b/docker/build.sh +@@ -182,7 +182,8 @@ compile_app() { + # -e EMSDK=/emsdk: `docker compose exec` bypasses the entrypoint that sources + # emsdk_env.sh, so the build shell would lack emcc/embuilder on PATH. Setting + # EMSDK lets scripts/common/env.sh source /emsdk/emsdk_env.sh and activate the toolchain. +- docker compose -f docker/docker-compose.yml exec -e EMSDK=/emsdk kicad-wasm-builder \ ++ docker compose -f docker/docker-compose.yml exec -e EMSDK=/emsdk \ ++ -e KICAD_WASM_EH="${KICAD_WASM_EH:-0}" kicad-wasm-builder \ + "/workspace/scripts/kicad/build-${app}.sh" "${ARGS[@]}" + + # Copy output to host-accessible directory. +diff --git a/scripts/build-wxuniversal-wasm.sh b/scripts/build-wxuniversal-wasm.sh +index 29b7f20..385b356 100755 +--- a/scripts/build-wxuniversal-wasm.sh ++++ b/scripts/build-wxuniversal-wasm.sh +@@ -137,9 +137,16 @@ if [ $NEEDS_CONFIGURE -eq 1 ]; then + echo "Building wxWidgets in RELEASE mode" + fi + ++ # EH model must match the rest of the build (see env.sh KICAD_WASM_EH). ++ if [ "${KICAD_WASM_EH:-0}" = "1" ]; then ++ WX_EH_FLAG="-fwasm-exceptions -sSUPPORT_LONGJMP=wasm -sWASM_LEGACY_EXCEPTIONS=0" ++ else ++ WX_EH_FLAG="-fexceptions" ++ fi ++ + # Include emscripten cache sysroot for zlib headers +- export CFLAGS="-DZ_HAVE_UNISTD_H=1 -I$EM_CACHE_SYSROOT/include ${WX_DEBUG_FLAGS} -fexceptions -pthread -matomics -mbulk-memory" +- export CXXFLAGS="-DZ_HAVE_UNISTD_H=1 -I$EM_CACHE_SYSROOT/include -I$PCRE2_INCLUDE ${WX_DEBUG_FLAGS} -fexceptions -pthread -matomics -mbulk-memory" ++ export CFLAGS="-DZ_HAVE_UNISTD_H=1 -I$EM_CACHE_SYSROOT/include ${WX_DEBUG_FLAGS} ${WX_EH_FLAG} -pthread -matomics -mbulk-memory" ++ export CXXFLAGS="-DZ_HAVE_UNISTD_H=1 -I$EM_CACHE_SYSROOT/include -I$PCRE2_INCLUDE ${WX_DEBUG_FLAGS} ${WX_EH_FLAG} -pthread -matomics -mbulk-memory" + export LDFLAGS="-L$EM_CACHE_SYSROOT/lib/wasm32-emscripten" + + emconfigure "$WX_SOURCE/configure" \ +diff --git a/scripts/common/env.sh b/scripts/common/env.sh +index 90fb61a..0445f99 100755 +--- a/scripts/common/env.sh ++++ b/scripts/common/env.sh +@@ -82,7 +82,22 @@ else + export DEBUG_LDFLAGS="" + fi + +-export DEBUG_BUILD BUILD_TYPE DEBUG_CFLAGS DEBUG_LDFLAGS ++# KICAD_WASM_EH=1 (EXPERIMENTAL): native WebAssembly exceptions instead of ++# emscripten's JS-based EH. JS-EH routes every potentially-throwing call inside ++# a try/catch through a JS invoke_* trampoline, which forces asyncify to ++# instrument nearly the whole exception-heavy codebase (pcbnew: 338 MB pre-O2). ++# Wasm EH (-fwasm-exceptions, Chrome 95+/Firefox 100+/Safari 15.2+) keeps ++# exceptions inside wasm β€” no invoke_*, far smaller asyncify set. ALL C++ must ++# agree on the EH model (deps + wx + kicad): this var feeds every compile. ++# Known limit: asyncify cannot suspend from inside a catch block (binaryen #4470). ++if [ "${KICAD_WASM_EH:-0}" = "1" ]; then ++ # -sSUPPORT_LONGJMP=wasm: setjmp/longjmp must use the same (wasm) machinery; ++ # without it emcc injects -enable-emscripten-sjlj, which clang rejects in ++ # combination with -fwasm-exceptions. ++ export DEBUG_CFLAGS="${DEBUG_CFLAGS} -fwasm-exceptions -sSUPPORT_LONGJMP=wasm -sWASM_LEGACY_EXCEPTIONS=0" ++fi ++ ++export DEBUG_BUILD BUILD_TYPE DEBUG_CFLAGS DEBUG_LDFLAGS KICAD_WASM_EH + + # Parallel jobs (default to 1 for memory-constrained environments like Docker) + # Can be overridden with -j N flag or by setting JOBS/PARALLEL_JOBS env vars +diff --git a/scripts/deps/build-boost.sh b/scripts/deps/build-boost.sh +index 8905e79..04da340 100755 +--- a/scripts/deps/build-boost.sh ++++ b/scripts/deps/build-boost.sh +@@ -72,6 +72,11 @@ else + BOOST_DEBUG_FLAGS="-O2" + fi + ++# EH model must match the rest of the build (see env.sh KICAD_WASM_EH). ++if [ "${KICAD_WASM_EH:-0}" = "1" ]; then ++ BOOST_DEBUG_FLAGS="${BOOST_DEBUG_FLAGS} -fwasm-exceptions -sSUPPORT_LONGJMP=wasm -sWASM_LEGACY_EXCEPTIONS=0" ++fi ++ + # Create user-config.jam for Emscripten + cat > user-config.jam << EOF + using clang : emscripten +diff --git a/scripts/deps/build-cairo.sh b/scripts/deps/build-cairo.sh +index 2580320..9d17e15 100755 +--- a/scripts/deps/build-cairo.sh ++++ b/scripts/deps/build-cairo.sh +@@ -65,6 +65,13 @@ else + MESON_DEBUG_FLAGS="'-O2'" + fi + ++# Cairo is C, but its png path uses setjmp/longjmp β€” the SJLJ machinery must ++# match the link (see env.sh KICAD_WASM_EH): without this, libcairo.a keeps ++# emscripten_longjmp references that are undefined under -sSUPPORT_LONGJMP=wasm. ++if [ "${KICAD_WASM_EH:-0}" = "1" ]; then ++ MESON_DEBUG_FLAGS="${MESON_DEBUG_FLAGS}, '-sSUPPORT_LONGJMP=wasm', '-sWASM_LEGACY_EXCEPTIONS=0'" ++fi ++ + # Cairo uses meson + cat > cross-file.txt << EOF + [binaries] +diff --git a/scripts/kicad/build-kicad-target.sh b/scripts/kicad/build-kicad-target.sh +index 6ace02b..0dc10f2 100755 +--- a/scripts/kicad/build-kicad-target.sh ++++ b/scripts/kicad/build-kicad-target.sh +@@ -193,25 +193,34 @@ log_info "Building KiCad ${APP_NAME} ${KICAD_VERSION} for WASM..." + + # Step 5: Set build type + # Use environment DEBUG_BUILD if set, otherwise check local --debug flag +-# -fexceptions is required because wxWidgets is built with exceptions enabled ++# Exceptions are required because wxWidgets is built with exceptions enabled. ++# EH model: JS-based (-fexceptions, default) or native wasm EH ++# (-fwasm-exceptions, KICAD_WASM_EH=1 β€” see env.sh). Must match deps + wx. + # -matomics -mbulk-memory are required for shared memory (pthreads) + # NOTE: We use -O1 for debug builds because -O0 produces WASM with too many + # locals for V8/Chrome to compile (error: "local count too large"). + # -O1 keeps debug info but optimizes enough to stay under V8's limits. ++if [ "${KICAD_WASM_EH:-0}" = "1" ]; then ++ EH_FLAG="-fwasm-exceptions -sSUPPORT_LONGJMP=wasm -sWASM_LEGACY_EXCEPTIONS=0" ++ log_info "Using native WebAssembly exceptions (-fwasm-exceptions)" ++else ++ EH_FLAG="-fexceptions" ++fi ++ + if [ "${DEBUG_BUILD:-0}" = "1" ] || [ $DEBUG -eq 1 ]; then + BUILD_TYPE="Debug" +- EXTRA_FLAGS="-g -O1 -fexceptions -matomics -mbulk-memory" ++ EXTRA_FLAGS="-g -O1 ${EH_FLAG} -matomics -mbulk-memory" + # -gseparate-dwarf puts debug info in a separate .debug.wasm file + # This keeps the main WASM small (~200MB) while preserving full debug info + # DevTools loads the debug file on-demand when debugging +- LINKER_DEBUG_FLAGS="-O1 -g -gseparate-dwarf -fexceptions" ++ LINKER_DEBUG_FLAGS="-O1 -g -gseparate-dwarf ${EH_FLAG}" + log_info "Building KiCad in DEBUG mode (separate DWARF for smaller main binary)" + else + BUILD_TYPE="Release" +- EXTRA_FLAGS="-O2 -fexceptions -matomics -mbulk-memory" ++ EXTRA_FLAGS="-O2 ${EH_FLAG} -matomics -mbulk-memory" + # -O0 at link time skips wasm-opt (which can OOM on large WASM files) + # Compilation is still -O2 for optimized code, but we skip post-link wasm-opt +- LINKER_DEBUG_FLAGS="-O0 -fexceptions" ++ LINKER_DEBUG_FLAGS="-O0 ${EH_FLAG}" + log_info "Building KiCad in RELEASE mode (skipping wasm-opt due to memory limits)" + fi + +````