From f419a1fedd0417b58396ffd120aca5a37f54aa1e Mon Sep 17 00:00:00 2001 From: Viktor Vaczi Date: Sat, 22 Aug 2026 12:53:00 +0200 Subject: [PATCH] build+perf: wasm-opt the shipped wasm, and measure real frames in CI MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit emcc only runs Binaryen at link -O2+ (link.py: should_run_binaryen_optimizer returns OPT_LEVEL >= 2) and we link at -O1, so the shipped module had never seen wasm-opt at all — it kept its entire 19.56 MB name section, ~20% of the editor (-sJSPI sets ASYNCIFY=2, which suppresses wasm-ld's --strip-debug, leaving wasm-opt as the only thing that would drop it). Step 8.2 runs it post-link and in-container, so CI's cached compile phase covers it and the host post-process stays pure-host. Default -O2, picked by measuring every level on the same module: -O0 already captures 27% of the raw win (it is mostly the name section), -O2 costs 23 s and gives the best frame rate, and -O3/-O4/-Os/-Oz cost 48-132 s for at most 1.5% more brotli — -O4 is not even smaller than -O3. Targets that already link -O2/-Oz (occ_service, kicad_tools) are skipped by testing for the target_features section, which emcc strips whenever it ran the optimizer itself, so there is no hard-coded target list to drift. Feature flags come from the module's own target_features section and so cannot diverge from the link. The perf specs reported requestAnimationFrame ticks as "FPS". That is not a frame rate: rAF fires on the compositor's schedule whether or not the GAL redrew, and it read 120/s on a board where the renderer completed zero frames in six seconds. measureInteractionFps now counts completed GAL frames — runs of draws to the default framebuffer, exactly one per frame in every AA mode — and drives a pure middle-drag pan after a zoom-to-fit. Mixing wheel zoom into the drive made the result depend on where the wheel left the view: +-20% across identical repeats, against +-2% for pan alone. The report gains a GAL fps column with a regression flag on the 1x number; rAF is kept so historical runs stay comparable. CI has no GPU, so its number is a software-rasteriser redraw rate — a regression signal, not a user-facing frame rate. Method and measurements in the bench report. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_016X9eh1s5sTx1o9Em9KBuwR --- .../jspi-vs-asyncify-bench-2026-08.md | 352 ++++++++++++++++-- scripts/build-monitor.sh | 1 + scripts/kicad/build-kicad-target.sh | 27 +- tests/kicad/eeschema-perf.spec.ts | 14 +- tests/kicad/pcbnew-perf.spec.ts | 14 +- tests/kicad/utils/perf-utils.ts | 127 +++++++ tests/tools/screenshots/perf-report.ts | 51 ++- 7 files changed, 533 insertions(+), 53 deletions(-) diff --git a/docs/features/async/migration-evidence/jspi-vs-asyncify-bench-2026-08.md b/docs/features/async/migration-evidence/jspi-vs-asyncify-bench-2026-08.md index 0f374e2..708f66b 100644 --- a/docs/features/async/migration-evidence/jspi-vs-asyncify-bench-2026-08.md +++ b/docs/features/async/migration-evidence/jspi-vs-asyncify-bench-2026-08.md @@ -22,6 +22,25 @@ default), docker caps 10 CPU / 32 GB, `-j 10`, `BINARYEN_CORES=8`, Machine: Apple M4 Max, 16 cores, 64 GB; Docker Desktop VM 12 CPU / 28 GiB; macOS 26.5.2. Raw data: [`bench-data-2026-08/`](bench-data-2026-08/). +> **Revised 2026-08-14 (evening).** The build, size, load and board-open numbers +> stand. The **interaction-FPS numbers were wrong and have been re-measured** — +> see [§4.4](#44-interaction-fps-re-measured-2026-08-14-evening). The original +> `distinctFps` counter hashed a 48×48 downscale of the canvas, which (a) misses +> redraws that change few pixels and (b) stalls the renderer through the pixel +> readback, badly so under software rasterisation. Frames are now counted from +> the WebGL command stream, the view is zoomed-to-fit before every measurement so +> each run sees the same geometry, and both a real GPU and a software rasteriser +> are reported. Direction of the result is unchanged; the magnitudes are not. +> +> **Second revision, same evening.** The two arms were never built the same way: +> the Asyncify pipeline always finished with a host-side `wasm-opt -O1`, while +> the JSPI build got **no Binaryen pass at all** (emcc only runs wasm-opt at link +> -O2+, and we link at -O1). So every number above compares an optimised module +> against an unoptimised one — in JSPI's favour, since JSPI won anyway. A +> post-link `wasm-opt` step has now been added to the build and re-benchmarked: +> [§6](#6-post-link-wasm-opt). The original unoptimised numbers are kept +> throughout; §7 adds the third arm. + ## TL;DR | Metric | Asyncify | JSPI | Δ | @@ -33,16 +52,27 @@ macOS 26.5.2. Raw data: [`bench-data-2026-08/`](bench-data-2026-08/). | Clean rebuild (warm ccache) | 165 s | 95 s | **−42 %** | | Cold load (median of 5) | 2 576 ms | 1 538 ms | **−40 %** | | Open vme-wren (27.7 MB board) | 6 465 ms | 3 551 ms | **−45 %** | -| Real redraws/s @1× (vme-wren) | 7.8 | 9.4 | **+21 %** | -| Real redraws/s @4× throttle | 3.1 | 5.2 | **+68 %** | +| GAL frames/s, vme-wren pan (GPU) | 12.7 | 19.5 | **+54 %** | +| GAL frames/s, vme-wren zoom (GPU) | 26.2 | 39.5 | **+51 %** | +| GAL frames/s, jetson pan (GPU) | 11.7 | 15.5 | **+32 %** | | Wasm heap after big-board open | 962 MB | 802 MB | **−17 %** | | Jetson 80.9 MB board open | 14.6 s, peak 1.90 GB | 8.6 s, peak 1.73 GB | **−41 %** | +| JSPI wasm, raw — **with `wasm-opt -O1`** | — | **63.3 MB** | **−36 %** vs unoptimised JSPI | +| JSPI wasm, brotli — **with `wasm-opt -O1`** | — | **10.6 MB** | **−15 %** vs unoptimised JSPI | + +(The last two rows are the third arm added in [§6](#6-post-link-wasm-opt); every +other row is the original A/B, both arms as they were actually built.) + The asyncify tax was real on every axis: bytes (instrumented code also compresses ~2× worse), build time (a mandatory 6-GB-RSS host pass per link), -load (bigger download + more code to tier), compute (slower opens, fewer real -frames — the gap *widens* under CPU throttle, the doc-12 signature of -per-operation overhead rather than mere size), and memory. +load (bigger download + more code to tier), compute (slower opens, ~50–70 % +fewer rendered frames), and memory. The frame-rate advantage holds at a roughly +*constant ratio* across CPU throttle rates (+63 % / +51 % / +73 % at 1× / 4× / +6×), i.e. JSPI does less work per frame rather than merely loading a smaller +module. The earlier claim that the gap *widened* under throttle (+21 % → +68 %) +does not survive re-measurement — it was an artefact of the old counter being +clipped at 1×. ## 1. Build time @@ -141,30 +171,96 @@ throttling channel. Neither arm OOMs even on the 80.9 MB board — both stay well under the 4 GB cap. -**Interaction FPS** on vme-wren (Lissajous pan + wheel zoom, 6 s × 2 reps; -`rafFps` = main-thread rAF; `distinctFps` = distinct GAL glcanvas frames at a -~30 Hz pixel-hash sampler — the honest "real redraws" number, since rAF keeps -vsync-ticking when the GAL skips): +### 4.4 Interaction FPS (re-measured 2026-08-14 evening) -| Throttle | Asyncify raf / distinct | JSPI raf / distinct | -|---|---|---| -| 1× | 44.5–49.1 / **7.8** | 51.9–55.7 / **9.2–9.6** | -| 4× | 32.4–37.6 / **3.0–3.1** | 39.2–41.4 / **5.1–5.2** | -| 6× | 34.3–39.9 / **2.8–4.1** | 34.3–41.8 / **3.3–5.3** | +**What the first pass got wrong.** `distinctFps` counted samples of a 48×48 +downscale hash of the GAL canvas at ~30 Hz. That under-counts real redraws by +2–3.5× (a moving crosshair changes too few pixels to survive the downscale), it +is capped at the 30 Hz sample rate, and the `drawImage`+`getImageData` readback +it performs is itself expensive — under software rasterisation it was a +significant share of the very thing being measured. The `rafFps` column was +never a frame rate at all: rAF ticks on the compositor's schedule whether or not +the GAL redrew anything. -The distinct-frame gap grows from +21 % at 1× to +68 % at 4× — the same -"advantage widens under throttle" signature doc-12 used to prove lower -CPU-per-operation (as opposed to just a smaller module). +**The corrected metric.** A GAL frame ends with the compositor blitting to the +default framebuffer, so a *run* of draw calls issued while no framebuffer is +bound is exactly one completed frame. The run must be collapsed — the number of +present draws per frame varies with the AA mode (1 under supersampling, 2 under +`AA_NONE`, +1 when the crosshair is drawn) — but a run boundary happens once per +frame in every mode, so no divisor is needed. This is now what +`measureInteractionFps()` in `tests/kicad/utils/perf-utils.ts` reports, and what +CI records. -**FPS on jetson-agx-thor (80.9 MB)** — added 2026-08-14 pm: at this scale BOTH -arms saturate outright and the backend difference disappears into noise -(asyncify raf 2.1–5.3 / distinct 0.2–0.8; JSPI raf 1.9–5.0 / distinct -0.1–0.7; post-FPS heap 1.90 vs 1.73 GB). With <1 real redraw/s the 6 s -windows count 1–5 frames, i.e. quantization noise. Reading: suspension -overhead is a per-event-loop-turn cost — once per-frame GAL/geometry work is -hundreds of ms, it no longer discriminates. vme-wren (~27 MB) is the size -class where the backend visibly matters for interaction; jetson is the -"both need render-side optimization" regime. +**Two further methodology fixes.** Each pattern gets a discarded warm-up drive +(the first pass pays first-time tessellation and measures caching, not steady +state), and the view is **zoomed to fit before every drive**. Without the reset a +preceding wheel-zoom leaves an arbitrary zoom level and the next pattern sees a +different amount of geometry — run-to-run spread reached 2×. With it, repeats +land within ~1% (measured: 21.3 / 21.3 / 21.1 fps over three runs). Zoom-to-fit +also means every number below is the *whole board in view*, i.e. the worst case. + +Both arms were re-run back-to-back on the same machine in the same session, from +their own static servers (asyncify served read-only out of the `staging` +worktree's `output/`; the jspi tree's harness page and board fixtures shared by +both, so only the 5-file artifact set differs). + +**vme-wren (27.7 MB, 1 508 fp, 24 858 seg) — GAL frames/s:** + +| Renderer | Pattern | Asyncify | JSPI | Δ | +|---|---|---|---|---| +| GPU (ANGLE Metal) | crosshair only | 66.4 | 64.9 | −2 % | +| GPU (ANGLE Metal) | wheel zoom | 26.2 | **39.5** | **+51 %** | +| GPU (ANGLE Metal) | middle-drag pan | 12.7 | **19.5** | **+54 %** | +| Software (SwiftShader) | crosshair only | 59.5 | 65.9 | +11 % | +| Software (SwiftShader) | wheel zoom | 11.6 | **39.3** | **+239 %** | +| Software (SwiftShader) | middle-drag pan | 9.9 | 9.5 | −4 % | + +**jetson-agx-thor (80.9 MB) — GAL frames/s:** + +| Renderer | Pattern | Asyncify | JSPI | Δ | +|---|---|---|---|---| +| GPU (ANGLE Metal) | crosshair only | 66.0 | 63.7 | −3 % | +| GPU (ANGLE Metal) | wheel zoom | 16.0 | **19.4** | **+21 %** | +| GPU (ANGLE Metal) | middle-drag pan | 11.7 | **15.5** | **+32 %** | +| Software (SwiftShader) | any | **0** | **0** | — | + +**CPU-throttle sweep** (vme-wren, GPU, middle-drag pan, GAL frames/s): + +| Throttle | Asyncify | JSPI | Δ | +|---|---|---|---| +| 1× | 12.5 | 20.4 | **+63 %** | +| 4× | 4.1 | 6.2 | **+51 %** | +| 6× | 2.6 | 4.5 | **+73 %** | + +Readings: + +- **JSPI's interaction advantage is real and larger than first reported**: ~+50 % + on vme-wren and ~+30 % on jetson, on a real GPU, where the first pass claimed + +21 %. +- **Crosshair-only motion is identical on both arms** (~65 fps everywhere, zero + vertex upload). Moving the cursor only re-composites; it never touches + geometry, so the suspension backend has nothing to do with it. This is the + control case, and it behaving as a control is a good sign for the rest. +- **The earlier "jetson saturates, the backend stops mattering" conclusion was an + artefact** of the broken counter. On a real GPU the backend still separates the + arms by ~30 % at 80.9 MB. What *is* true is that neither arm renders the jetson + board at all under software rasterisation: no frame completes within a 6 s + window, and re-running with a 45 s settle and a 20 s window still yields zero + (rAF 2.8/s, 233 GL calls/s). A single redraw there takes over 20 seconds. +- **The advantage does not widen under throttle** — it is a roughly constant + ratio (+51 % to +73 %, the spread being run noise). That still points at less + work per frame rather than a pure module-size effect, but the original + "+21 % → +68 % widening" reading was an artefact: the old counter's 30 Hz + ceiling and under-counting compressed the measured 1× gap specifically. +- **Software-rasteriser numbers do not rank the arms reliably** — vme-wren pan is + a tie (9.9 vs 9.5) while zoom is a 3.4× gap. Rank the backends on the GPU + numbers; treat the software column as the CI-shaped regression signal it is. + +Absolute frame rates here are lower than the old `distinctFps` figures would +suggest at first glance only because zoom-to-fit puts the entire board in view. +Load and board-open times re-measured in the same runs reproduced §4's originals +(e.g. vme-wren open 6 475 vs 2 088 ms; jetson open 14 510 vs 8 094 ms), which is +the cross-check that the new rig measures the same builds as the old one. **Memory checkpoints** (wasm linear memory; Chromium `usedJSHeapSize` tracked alongside, differences <10 %): boot 557 vs 387 MB; after vme-wren open 962 vs @@ -195,7 +291,209 @@ alongside, differences <10 %): boot 557 vs 387 MB; after vme-wren open 962 vs `public/wasm` symlink pointed at a stash during the swap window) and verified serving the JSPI wasm afterwards. -## 6. Reproduce +## 6. Post-link wasm-opt + +**The asymmetry.** Arm A's pipeline ended with `wasm-opt --hoist-cpp-catches` → +`--asyncify` → **`-O1`** on the host. Arm B ended with nothing: emcc only runs +Binaryen at link `-O2`+ (`tools/link.py`, `should_run_binaryen_optimizer()` +returns `settings.OPT_LEVEL >= 2`), and at -O0/-O1 the pass list comes back empty +so `wasm-opt` is never even spawned. The section tables confirm it — the asyncify +module has **no name section** (its host `wasm-opt` stripped it) while the JSPI +module still carries **19.56 MB** of names, because `-sJSPI` sets `ASYNCIFY=2`, +which suppresses wasm-ld's `--strip-debug`, leaving wasm-opt as the only thing +that would have dropped them. + +So §§3–4 compare an optimised module against an unoptimised one. That understates +JSPI: on a like-for-like code-section basis it was 66.7 MB (never optimised) +against asyncify's 106.3 MB (optimised). + +**The build step.** Added to `scripts/kicad/build-kicad-target.sh` as step 8.2, +after the link and before `copy-output`. It runs in-container (wasm-opt ships +with emsdk, so CI's cached `--compile-only` phase covers it and the host +`--postprocess-only` phase stays pure-host). Defaults to `-O1`, matching the +Asyncify-era pipeline; override with `KICAD_WASM_OPT` (`-O2`, `-O1 -g` to keep +the name section, `off` to skip). No feature flags are passed: Binaryen reads the +module's own `target_features` section, so the enabled-feature list cannot drift +from the link. That same section is the skip signal — emcc strips it via +`--strip-target-features` whenever it ran the optimizer itself, so targets that +link at -O2/-Oz (`occ_service`, `kicad_tools`) are detected and skipped rather +than hard-coded by name. A stamp file makes it idempotent across relink-free +rebuilds, and a failure leaves the linked module untouched and fails the build. + +**Cost: 9 s**, in a 121 s no-change rebuild (~7 %). For contrast the Asyncify host +tail cost 63.4 s and 6.09 GB RSS per link. The "wasm-opt OOMs on large modules" +comment that justified `-O0` in the release path is Asyncify-era: it predates +JSPI and was written when instrumentation had roughly doubled the function count. + +**What it does to the module:** code 66.7 → 51.0 MB, name section 19.56 MB → 0, +`external_debug_info` preserved (so `-gseparate-dwarf` DWARF still resolves). + +### 6.1 Size + +| Editor wasm | Asyncify | JSPI | JSPI + `wasm-opt -O1` | +|---|---|---|---| +| raw | 118.6 MB | 98.7 MB | **63.3 MB** | +| gzip −9 | 38.5 MB | 19.5 MB | **16.1 MB** | +| brotli | 21.0 MB | 12.5 MB | **10.6 MB** | + +Against unoptimised JSPI: **−36 % raw, −17 % gzip, −15 % brotli**. Against +asyncify: −47 % raw, −58 % gzip, −49 % brotli. The raw delta is much larger than +the compressed one because most of it is the name section, which compresses well. + +### 6.2 Runtime + +Three arms, same session, GPU (ANGLE Metal), zoom-to-fit, 6 s drives. Pan is the +headline: it repeats within ~2 %. Zoom was dropped from the harness entirely +after this run — the wheel drive continuously changes how much geometry is +visible, so it spread ±20 % run to run (34.7 / 42.1 / 27.1 on three identical +repeats) and discriminated nothing. The CI perf specs now drive a pure +middle-drag pan for the same reason. Cursor is the control: crosshair-only motion +touches no geometry. + +| vme-wren, GPU | Asyncify | JSPI | JSPI + `wasm-opt -O1` | +|---|---|---|---| +| cold load | 2 145 ms | 1 153 ms | **1 063 ms** | +| open board | 6 347 ms | 3 381 ms | 3 317 ms | +| **pan, GAL fps** | 11.9 | 18.3 | **18.1** | +| cursor, GAL fps (control) | 65.4 | 64.8 | 65.3 | +| zoom, GAL fps (noisy) | 20.0 | 32.4 | 23.0 | + +| jetson-agx-thor, GPU | Asyncify | JSPI | JSPI + `wasm-opt -O1` | +|---|---|---|---| +| cold load | 2 135 ms | 1 173 ms | **1 050 ms** | +| open board | 14 651 ms | 8 080 ms | 8 013 ms | +| **pan, GAL fps** | 11.4 | 14.3 | **14.4** | + +**Reading: `wasm-opt -O1` is a size and startup win, not a frame-rate win.** +Frame rate is unchanged within noise on both boards (18.3 → 18.1 and 14.3 → 14.4 +— the two arms are indistinguishable). Cold load improves 8–10 % (1 153 → 1 063 +and 1 173 → 1 050), which is what a 36 % smaller download and less code to tier +buys. Board open is flat, consistent with it being dominated by parsing and +connectivity rather than code quality. + +That frame rate does not move is the expected result rather than a +disappointment: the per-frame hot path is scene traversal in code LLVM already +optimised at the translation-unit level, and Binaryen `-O1` on top of clang -O1 +mostly removes cross-module redundancy and dead weight. It also means the +original A/B's *interaction* conclusions are not disturbed by the asymmetry — the +JSPI-vs-asyncify frame-rate gap was never an artefact of the missing pass. The +size and load-time comparisons in §§3–4, however, were: JSPI's real advantage +there is larger than those sections state. + +### 6.3 Every optimization level, measured + +All seven Binaryen levels run on the same pristine unoptimised module +(98.7 MB), then each served against identical glue and benchmarked. `-O0` is the +control: it optimises nothing, so it isolates what a plain round-trip plus +dropping the name section is worth on its own. + +| Level | wasm-opt wall | raw | gzip −9 | **brotli** | pan GAL fps | cold load | +|---|---|---|---|---|---|---| +| none | — | 98.7 MB | 19.47 MB | **12.51 MB** | 18.8 | 1 257–1 609 ms | +| `-O0` | 4 s | 72.3 MB | 17.39 MB | **11.21 MB** | 19.5 | ~1 145 ms | +| `-O1` *(shipped default)* | 8 s | 63.3 MB | 16.12 MB | **10.61 MB** | 19.5 | ~1 090 ms | +| `-O2` | 23 s | 60.7 MB | 15.95 MB | **10.66 MB** | **21.1** | ~1 090 ms | +| `-O3` | 98 s | 60.1 MB | 15.83 MB | **10.53 MB** | 20.4 | ~1 070 ms | +| `-O4` | 132 s | 60.1 MB | 15.86 MB | **10.56 MB** | 21.8 | ~1 094 ms | +| `-Os` | 48 s | 60.0 MB | 15.85 MB | **10.53 MB** | 22.1 | ~1 068 ms | +| `-Oz` | 97 s | 57.2 MB | 15.68 MB | **10.49 MB** | 20.4 | ~1 076 ms | + +Pan is the mean of two reps where two were run (none, `-O0`, `-O2`, `-Oz`); +repeats agreed within ~5%, and the `settled` time — how long until the app goes +quiet after opening — repeated within 0.4% (e.g. none 6 941 / 6 938 ms against +`-O2` 6 106 / 6 123 ms), which is what gives confidence the gaps are real. + +Three things fall out: + +- **Most of the size win is not optimisation.** `-O0` — which does no + optimisation at all — already captures 26.7% of the raw reduction, because the + bulk of it is the 19.56 MB name section being dropped. +- **Compressed size is flat from `-O1` onward.** Brotli is what actually goes over + the wire, and every level from `-O1` to `-Oz` lands in a 10.49–10.66 MB band — + a 1.6% spread. Raw size keeps falling to `-Oz` (57.2 MB), which matters for + parse and memory but not for download. +- **Build cost explodes for nothing.** `-O3`, `-O4`, `-Os` and `-Oz` cost 48–132 s + against `-O2`'s 23 s and `-O1`'s 8 s, and buy at most 1.5% more brotli. `-O4` + is not smaller than `-O3` at all (60 097 004 vs 60 091 979 bytes) while taking + 35% longer. + +**Recommendation: `-O2` is the value pick** — 23 s for the best measured frame +rate (+13% pan over unoptimised, versus +4% at `-O1`) and essentially the same +download as anything more expensive. The build currently defaults to `-O1` to +mirror the Asyncify-era pipeline; moving it is a one-word change to +`KICAD_WASM_OPT`. Anything past `-O2` is not worth its build time on this module. + +### 6.4 Release (non-debug) build + +The build that ships is the **debug** one (`DEBUG_BUILD` defaults to 1). This +tests whether dropping debug mode buys anything, with `wasm-opt -O2` held +constant on both sides so the only variable is the compile/link mode: + +| | Debug | Release | +|---|---|---| +| KiCad + deps + wx TUs | `-g -O1` | `-O2` | +| link | `-O1 -g -gseparate-dwarf` | `-O0` | +| post-link | `wasm-opt -O2` | `wasm-opt -O2` | + +**Consistency first.** `check_stamp()` is only `[ -f "$stamp_file" ]` — it does +not encode the build mode — so flipping `DEBUG_BUILD=0` rebuilds KiCad while +silently reusing debug-built dependencies. That matters beyond lost optimisation: +wxWidgets' ABI depends on its debug level. Every stamp was therefore wiped and wx +forced through reconfigure, and the result verified by checking for DWARF, which +only a `-g` build emits: OCCT (`libTKernel`), cairo, freetype, harfbuzz, +boost_locale, protobuf, wx base, wx core and the KiCad objects all came back +DWARF-free. Since `env.sh` ties `-g -O1` and `-O2` to the same switch, no DWARF +proves the `-O2` branch. (`docker/build.sh` already forwards `DEBUG_BUILD` into +the container for exactly this reason — its comment notes that `--release` alone +reaches KiCad's flag block but never `DEBUG_CFLAGS`/`WX_DEBUG_FLAGS`.) + +**Size — release is slightly *worse*:** + +| | Debug + `wasm-opt -O2` | Release + `wasm-opt -O2` | Δ | +|---|---|---|---| +| raw | 60.7 MB | 62.5 MB | **+3.0 %** | +| gzip −9 | 15.95 MB | 16.24 MB | +1.8 % | +| brotli | 10.66 MB | 10.80 MB | +1.3 % | +| code section | 48.5 MB | 50.3 MB | +3.7 % | +| data section | 12.0 MB | 12.0 MB | — | + +`-O2` inlines more, so it trades size for speed — the code section grows while +data is byte-identical. + +**Speed — no measurable win:** + +| vme-wren, GPU | Debug + `wasm-opt -O2` | Release + `wasm-opt -O2` | +|---|---|---| +| pan GAL fps (2 reps) | 19.4 / 19.5 | 19.0 / 20.8 | +| cold load | 1 091 / 1 041 ms | 1 067 / 1 081 ms | +| settle after open | 6 790 / 6 907 ms | 6 671 / 6 003 ms | + +Frame rate is **+2.3 % on the means, inside run noise** (the release arm's two +reps, 19.0 and 20.8, straddle the debug arm's pair). Cold load is identical. +Settle is ~7 % faster, the only consistent signal. + +**Reading: `clang -O2` and `wasm-opt -O2` are largely redundant here — you want +one of them, not both.** The measured jump is from *no* whole-module optimisation +to *any* (+4 % at `wasm-opt -O1`, +13 % at `-O2`); which tool supplies it barely +matters. That also explains the earlier observation that unoptimised debug loaded +much slower than the optimised variants: that gap was the 19.56 MB **name +section** inflating the download, not code quality. With names stripped on both +sides here, load times converge exactly. + +So debug mode is not costing meaningful speed, and release costs 1–3 % more +bytes while giving up all debug info — no separate DWARF, no symbolised stack +traces. On this evidence there is no reason to switch, which is a useful thing to +know: the cheap `wasm-opt` step already captured what was available, and the +remaining render cost is structural (see §6.2's reading), not a missing flag. + +**Still not measured:** LTO (`-flto`) and `-msimd128`, neither of which appears +anywhere in the build. LTO is the interesting one — this is a merged multi-app +binary, so there is a large cross-TU inlining surface that neither per-file +`-O2` nor Binaryen can reach. Also unmeasured: a `-O3`/`-Oz` *link* level, whose +metadce pass (gated on `OPT_LEVEL >= 3` or `SHRINK_LEVEL >= 1`, so it does not +engage at `-O2`) would drop unused JS-library and wasm exports. + +## 7. Reproduce ```bash # build side (each arm, serialized; see §1 for scenario commands) diff --git a/scripts/build-monitor.sh b/scripts/build-monitor.sh index c608207..527301d 100755 --- a/scripts/build-monitor.sh +++ b/scripts/build-monitor.sh @@ -98,6 +98,7 @@ BEGIN { ord[++ROWN] = "kicad-configure"; lab["kicad-configure"] = "KiCad configure (CMake)" ord[++ROWN] = "kicad-compile"; lab["kicad-compile"] = "KiCad compile" ord[++ROWN] = "kicad-bitmaps"; lab["kicad-bitmaps"] = "Bitmap resources" + ord[++ROWN] = "wasm-opt"; lab["wasm-opt"] = "wasm-opt (Binaryen)" ord[++ROWN] = "copy-output"; lab["copy-output"] = "Copy output" ord[++ROWN] = "env-shim"; lab["env-shim"] = "ENV merge shim" for (i = 1; i <= ROWN; i++) ridx[ord[i]] = i diff --git a/scripts/kicad/build-kicad-target.sh b/scripts/kicad/build-kicad-target.sh index 4205aa6..bf60b52 100755 --- a/scripts/kicad/build-kicad-target.sh +++ b/scripts/kicad/build-kicad-target.sh @@ -290,10 +290,12 @@ else BUILD_TYPE="Release" EXTRA_FLAGS="-O2 ${KICAD_EH_FLAGS} -matomics -mbulk-memory" EMBIND_CONFIG_DEFINES="" # Release defines no DEBUG in either TU → vtable layouts already match - # -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 + # -O0 at link time means emcc does not run wasm-opt itself (it only does at + # -O2+). That is fine: step 8.2 below runs wasm-opt explicitly, so the module + # is optimized either way. The old "wasm-opt OOMs on large modules" reason for + # -O0 was Asyncify-era and no longer applies. LINKER_DEBUG_FLAGS="-O0 ${KICAD_EH_FLAGS}" - log_info "Building KiCad in RELEASE mode (skipping wasm-opt due to memory limits)" + log_info "Building KiCad in RELEASE mode (post-link wasm-opt runs in step 8.2)" fi # Suspension backend: JSPI (native stack switching). The headless CLIs @@ -696,6 +698,25 @@ if [ "${APP_NAME}" != "kicad_tools" ] && [ "${APP_NAME}" != "occ_service" ]; the emmake make bitmap_archive_build fi +# Step 8.2: post-link Binaryen pass. emcc only runs wasm-opt at link -O2+ +# (link.py: should_run_binaryen_optimizer -> OPT_LEVEL >= 2) and we link at -O1, +# so without this the module gets no Binaryen pass at all and keeps its whole +# name section (measured 19.56 MB, ~20% of the editor wasm — -sJSPI sets +# ASYNCIFY=2, which suppresses wasm-ld's --strip-debug, leaving wasm-opt as the +# only thing that would drop it). Skipped for targets that already link -O2/-Oz +# (occ_service, kicad_tools, ngspice_service): emcc strips target_features when +# it ran the optimizer itself, so there is no hard-coded target list to +# maintain. Feature flags come from the module's own target_features section and +# so cannot drift from the link. Override with KICAD_WASM_OPT ("-Oz" for the +# smallest raw module, "-O2 -g" to keep the name section, "off" to skip). +KICAD_WASM_OPT="${KICAD_WASM_OPT:--O2}" +if [ "${KICAD_WASM_OPT}" != "off" ] && grep -aq "target_features" "${LINK_OUT_WASM}"; then + kw_stage wasm-opt + log_info "wasm-opt ${KICAD_WASM_OPT} on ${APP_NAME}.wasm..." + "${EMSDK:-/emsdk}/upstream/bin/wasm-opt" ${KICAD_WASM_OPT} "${LINK_OUT_WASM}" -o "${LINK_OUT_WASM}.tmp" + mv -f "${LINK_OUT_WASM}.tmp" "${LINK_OUT_WASM}" +fi + # Step 9: Create stamp file create_stamp "${KICAD_STAMP}" log_info "KiCad ${APP_NAME} build complete!" diff --git a/tests/kicad/eeschema-perf.spec.ts b/tests/kicad/eeschema-perf.spec.ts index 934cd02..255d0d4 100644 --- a/tests/kicad/eeschema-perf.spec.ts +++ b/tests/kicad/eeschema-perf.spec.ts @@ -1,12 +1,12 @@ import { test, expect } from './fixtures'; import * as path from 'path'; -import { measureLoad, measureOpenRender, measureFps, setThrottle, recordPerf } from './utils/perf-utils'; +import { measureLoad, measureOpenRender, measureInteractionFps, setThrottle, recordPerf } from './utils/perf-utils'; /** * eeschema runtime-perf (TRACK-ONLY, no gating). * * Measures the CURRENT build: cold load, open+render of the demo schematic, and - * sustained pan/zoom FPS across CPU-throttle rates. Numbers are logged and written + * sustained pan FPS across CPU-throttle rates. Numbers are logged and written * to tests/test-results/perf-eeschema.json (CI uploads it). The only assertions are * "the app booted and the doc opened" — never a perf threshold (would flake CI). * Runs on the Chromium 'perf' project (CDP throttling); pass --headed for real-GPU FPS. @@ -29,12 +29,14 @@ test.describe('eeschema perf', () => { await page.keyboard.press('Escape').catch(() => {}); // eslint-disable-line -- best-effort Escape (may not apply in all states) const cdp = await page.context().newCDPSession(page); - const fps: { throttle: number; fps: number }[] = []; + // galFps is the real frame rate (completed GAL frames). fps is the legacy + // rAF tick count, kept so historical CI numbers stay comparable. + const fps: { throttle: number; fps: number; galFps: number }[] = []; for (const rate of THROTTLES) { await setThrottle(cdp, rate); - const f = await measureFps(page, FPS_SECS); - console.log(`[perf] eeschema FPS @ ${rate}x = ${f}`); - fps.push({ throttle: rate, fps: f }); + const f = await measureInteractionFps(page, FPS_SECS); + console.log(`[perf] eeschema @ ${rate}x: GAL ${f.galFps} fps (rAF ${f.rafFps})`); + fps.push({ throttle: rate, fps: f.rafFps, galFps: f.galFps }); } await setThrottle(cdp, 1); diff --git a/tests/kicad/pcbnew-perf.spec.ts b/tests/kicad/pcbnew-perf.spec.ts index 08c9be6..b7ebb33 100644 --- a/tests/kicad/pcbnew-perf.spec.ts +++ b/tests/kicad/pcbnew-perf.spec.ts @@ -1,12 +1,12 @@ import { test, expect } from './fixtures'; import * as path from 'path'; -import { measureLoad, measureOpenRender, measureFps, setThrottle, recordPerf } from './utils/perf-utils'; +import { measureLoad, measureOpenRender, measureInteractionFps, setThrottle, recordPerf } from './utils/perf-utils'; /** * pcbnew runtime-perf (TRACK-ONLY, no gating). Mirrors eeschema-perf for the board editor. * * Measures the CURRENT build: cold load, open+render of the demo board, and sustained - * pan/zoom FPS across CPU-throttle rates → tests/test-results/perf-pcbnew.json (CI uploads it). + * pan FPS across CPU-throttle rates → tests/test-results/perf-pcbnew.json (CI uploads it). * Runs on the Chromium 'perf' project (pcbnew's big module OOMs Firefox/SpiderMonkey anyway, * and CDP throttling is Chromium-only). Only asserts booted + opened; never a perf threshold. */ @@ -27,12 +27,14 @@ test.describe('pcbnew perf', () => { await page.keyboard.press('Escape').catch(() => {}); // eslint-disable-line -- best-effort Escape (may not apply in all states) const cdp = await page.context().newCDPSession(page); - const fps: { throttle: number; fps: number }[] = []; + // galFps is the real frame rate (completed GAL frames). fps is the legacy + // rAF tick count, kept so historical CI numbers stay comparable. + const fps: { throttle: number; fps: number; galFps: number }[] = []; for (const rate of THROTTLES) { await setThrottle(cdp, rate); - const f = await measureFps(page, FPS_SECS); - console.log(`[perf] pcbnew FPS @ ${rate}x = ${f}`); - fps.push({ throttle: rate, fps: f }); + const f = await measureInteractionFps(page, FPS_SECS); + console.log(`[perf] pcbnew @ ${rate}x: GAL ${f.galFps} fps (rAF ${f.rafFps})`); + fps.push({ throttle: rate, fps: f.rafFps, galFps: f.galFps }); } await setThrottle(cdp, 1); diff --git a/tests/kicad/utils/perf-utils.ts b/tests/kicad/utils/perf-utils.ts index f5847fb..074b564 100644 --- a/tests/kicad/utils/perf-utils.ts +++ b/tests/kicad/utils/perf-utils.ts @@ -166,10 +166,137 @@ export async function setThrottle(cdp: CDPSession, rate: number): Promise await cdp.send('Emulation.setCPUThrottlingRate', { rate }); } +/** + * Count completed GAL frames instead of rAF ticks. + * + * A GAL frame ends with the compositor blitting to the DEFAULT framebuffer, so a + * run of draws issued while no framebuffer is bound is exactly one frame. The run + * has to be collapsed: the number of present draws per frame depends on the AA + * mode (1 under supersampling, 2 under AA_NONE, +1 when the crosshair is drawn), + * but a run *boundary* happens once per frame in every mode — so no divisor. + * + * Wrapping the prototypes works even though the context already exists: methods + * resolve on the prototype at call time, not at context creation. The initial + * framebuffer binding is assumed to be the default and self-corrects on the first + * bindFramebuffer, which the GAL issues several times per frame. + */ +async function installGalFrameCounter(page: Page): Promise { + await page.evaluate(() => { + const w = window as unknown as { __galFrames?: number; __galHooked?: boolean }; + w.__galFrames = 0; + if (w.__galHooked) return; + w.__galHooked = true; + const protos = [ + (window as unknown as { WebGL2RenderingContext?: { prototype: object } }).WebGL2RenderingContext, + (window as unknown as { WebGLRenderingContext?: { prototype: object } }).WebGLRenderingContext, + ].filter(Boolean) as Array<{ prototype: Record }>; + const state = new WeakMap(); + const st = (ctx: object) => { + let s = state.get(ctx); + if (!s) { s = { fb: null, inPresent: false }; state.set(ctx, s); } + return s; + }; + const DRAWS = ['drawArrays', 'drawElements', 'drawArraysInstanced', 'drawElementsInstanced', 'drawRangeElements']; + for (const proto of protos) { + for (const name of ['bindFramebuffer', ...DRAWS]) { + const orig = proto.prototype[name] as ((...a: unknown[]) => unknown) | undefined; + if (typeof orig !== 'function') continue; + const isDraw = DRAWS.indexOf(name) >= 0; + proto.prototype[name] = function (this: object, ...args: unknown[]) { + const s = st(this); + if (!isDraw) { + s.fb = args[1]; + if (args[1]) s.inPresent = false; + } else if (s.fb === null || s.fb === undefined) { + if (!s.inPresent) { s.inPresent = true; w.__galFrames = (w.__galFrames ?? 0) + 1; } + } else { + s.inPresent = false; + } + return orig.apply(this, args); + }; + } + } + }); +} + +/** Zoom-to-fit, so every measurement starts from the same visible geometry. */ +async function resetViewToFit(page: Page, cx: number, cy: number): Promise { + await page.mouse.move(cx, cy); + await page.keyboard.press('Escape').catch(() => {}); // eslint-disable-line -- best-effort + await page.keyboard.press('Home').catch(() => {}); // eslint-disable-line -- best-effort + await page.waitForFunction(() => true, null, { timeout: 5000 }); +} + +/** + * Sustained interaction FPS, reported two ways. + * + * `galFps` is the real one: completed GAL frames per second (see + * installGalFrameCounter). `rafFps` is the legacy main-thread requestAnimationFrame + * count, kept only so historical CI numbers stay comparable — it is NOT a frame + * rate. rAF ticks on the compositor's schedule whether or not the GAL redrew, so + * it can read 120 while the renderer is completely stalled (measured: the 80 MB + * jetson board on a software rasteriser renders 0 frames while rAF reports 120). + * + * The drive is a pure middle-drag PAN. Wheel zoom used to be mixed into the same + * loop, and it makes the metric unusable: zooming continuously changes how much + * geometry is on screen, so the result depends on where the wheel happens to + * leave the view. Measured spread across three identical repeats was ±20% + * (34.7 / 42.1 / 27.1 fps) with zoom in the loop, versus ±2% (19.9 / 19.0 / 19.6) + * for pan alone. Pan also keeps the workload honest — it continuously reveals + * geometry that has to be cached, which is the expensive path. + * + * The view is zoomed to fit first, so every run starts from the same visible + * geometry (the whole board — the worst case) rather than inheriting whatever + * zoom level the previous measurement left behind. + */ +export async function measureInteractionFps( + page: Page, + seconds: number, +): Promise<{ rafFps: number; galFps: number }> { + const box = await page.locator(MAIN_CANVAS).boundingBox(); + if (!box) return { rafFps: 0, galFps: 0 }; + const cx = box.x + box.width / 2; + const cy = box.y + box.height / 2; + await resetViewToFit(page, cx, cy); + await installGalFrameCounter(page); + + type W = { __perfFrames: number; __perfRAF?: number; __galFrames?: number }; + await page.evaluate(() => { + const w = window as unknown as W; + if (w.__perfRAF !== undefined) cancelAnimationFrame(w.__perfRAF); + w.__perfFrames = 0; + w.__galFrames = 0; + const loop = () => { + w.__perfFrames++; + w.__perfRAF = requestAnimationFrame(loop); + }; + w.__perfRAF = requestAnimationFrame(loop); + }); + const start = Date.now(); + let k = 0; + await page.mouse.move(cx, cy); + await page.mouse.down({ button: 'middle' }); + while (Date.now() - start < seconds * 1000) { + await page.mouse.move(cx + Math.round(140 * Math.sin(k / 6)), cy + Math.round(90 * Math.cos(k / 7))); + k++; + } + await page.mouse.up({ button: 'middle' }); + const elapsed = Date.now() - start; + const counts = await page.evaluate(() => { + const w = window as unknown as W; + if (w.__perfRAF !== undefined) cancelAnimationFrame(w.__perfRAF); + return { raf: w.__perfFrames, gal: w.__galFrames ?? 0 }; + }); + const secs = elapsed / 1000; + return { rafFps: +(counts.raf / secs).toFixed(1), galFps: +(counts.gal / secs).toFixed(1) }; +} + /** * Sustained interaction FPS: drive real pan/zoom on #canvas (the emscripten input * surface — glcanvas-* can be display:none) for `seconds`, counting main-thread rAF * frames. Whatever throttle is currently set applies. + * + * @deprecated rAF ticks are not GAL frames — use measureInteractionFps().galFps. */ export async function measureFps(page: Page, seconds: number): Promise { const box = await page.locator(MAIN_CANVAS).boundingBox(); diff --git a/tests/tools/screenshots/perf-report.ts b/tests/tools/screenshots/perf-report.ts index c04d0d0..2fbcd85 100644 --- a/tests/tools/screenshots/perf-report.ts +++ b/tests/tools/screenshots/perf-report.ts @@ -2,16 +2,17 @@ * Renders the track-only runtime-perf block for the CI-on-main Discord comment. * * The perf e2e (tests/kicad/{eeschema,pcbnew}-perf.spec.ts) already writes - * test-results/perf-{app}.json — schema { app, when, loadMs, openMs, fps:[{throttle,fps}] }. + * test-results/perf-{app}.json — schema { app, when, loadMs, openMs, fps:[{throttle,fps,galFps}] }. * We read those, fetch the PREVIOUS successful main run's perf via `gh run * download` (so we can show a Δ without committing a baseline — stays * no-write-back), and format an aligned monospace table (Discord doesn't render * markdown tables, so it goes in a ``` code block). * * Track-only: nothing here gates the build. A regression past REGRESSION_PCT on - * the stable metrics (loadMs/openMs) is only flagged (a `*`), never failed. FPS - * is CPU-bound/noisy on CI's headless SwiftShader path, so it's shown but marked - * indicative. + * the stable metrics (loadMs/openMs) is only flagged (a `*`), never failed. Both + * FPS columns are measured on CI's software rasteriser (ANGLE over Mesa llvmpipe, + * under Xvfb — there is no GPU on the runner), so they are a regression signal + * only and never a user-facing frame rate. * * CLI (from tests/): * tsx tools/screenshots/perf-report.ts [--results DIR] [--prev DIR] [--repo owner/repo] @@ -26,7 +27,8 @@ export const PERF_APPS = ['eeschema', 'pcbnew'] as const; const REGRESSION_PCT = 10; // stable-metric regression past this is flagged with `*` const CI_WORKFLOW = 'ci-ubicloud.yml'; -export type Fps = { throttle: number; fps: number }; +/** `fps` is the legacy rAF tick count; `galFps` is the real frame rate. */ +export type Fps = { throttle: number; fps: number; galFps?: number }; export type PerfData = { app: string; when?: string; loadMs: number; openMs: number; fps: Fps[] }; export function readPerf(dir: string): Map { @@ -101,10 +103,32 @@ function fmtMetric(cur: number, prev?: number): string { return `${cur} ${arrow}${Math.abs(p).toFixed(0)}%${flag}`; } -function fmtFps(fps: Fps[]): string { +/** + * GAL fps with a Δ vs the previous main run, flagged on REGRESSION. + * + * Higher is better here, so the sign convention is inverted relative to + * fmtMetric: a DROP past the threshold gets the `*`. Only the 1x-throttle + * number drives the flag — it is the one that repeats within ~2% (pan-only + * drive, zoom-to-fit before each measurement), so it is safe to act on. + * CI has no GPU, so this is a software-rasteriser redraw rate: useful precisely + * because it is consistent, not because it is the user-facing frame rate. + */ +function fmtGalFps(fps: Fps[], prev?: Fps[]): string { + const triple = fmtFps(fps, 'galFps'); + const cur = fps.find((f) => f.throttle === 1)?.galFps; + const was = prev?.find((f) => f.throttle === 1)?.galFps; + if (cur === undefined || was === undefined || was === 0) return triple; + const p = pct(cur, was); // + = faster than before + const arrow = p > 0 ? '▲' : p < 0 ? '▼' : '·'; + const flag = -p > REGRESSION_PCT ? '*' : ''; + return `${triple} ${arrow}${Math.abs(p).toFixed(0)}%${flag}`; +} + +function fmtFps(fps: Fps[], key: 'fps' | 'galFps' = 'fps'): string { return [1, 4, 6].map((t) => { const hit = fps.find((f) => f.throttle === t); - return hit ? Math.round(hit.fps) : '–'; + const v = hit?.[key]; + return v === undefined ? '–' : Math.round(v); }).join('/'); } @@ -120,7 +144,7 @@ export function buildPerfReport(opts: { resultsDir?: string; prevDir?: string | if (cur.size === 0) return { block: '', regressed: false }; const prev = opts.prevDir ? readPerf(opts.prevDir) : new Map(); - const headers = ['app', 'loadMs (Δ)', 'openMs (Δ)', 'FPS 1/4/6']; + const headers = ['app', 'loadMs (Δ)', 'openMs (Δ)', 'GAL fps 1/4/6 (Δ@1x)', 'rAF 1/4/6']; const rows: string[][] = []; let regressed = false; for (const app of PERF_APPS) { @@ -129,8 +153,9 @@ export function buildPerfReport(opts: { resultsDir?: string; prevDir?: string | const p = prev.get(app); const loadCell = fmtMetric(c.loadMs, p?.loadMs); const openCell = fmtMetric(c.openMs, p?.openMs); - if (loadCell.endsWith('*') || openCell.endsWith('*')) regressed = true; - rows.push([app, loadCell, openCell, fmtFps(c.fps)]); + const galCell = fmtGalFps(c.fps, p?.fps); + if (loadCell.endsWith('*') || openCell.endsWith('*') || galCell.endsWith('*')) regressed = true; + rows.push([app, loadCell, openCell, galCell, fmtFps(c.fps, 'fps')]); } if (rows.length === 0) return { block: '', regressed: false }; @@ -138,7 +163,11 @@ export function buildPerfReport(opts: { resultsDir?: string; prevDir?: string | const line = (cells: string[]) => cells.map((c, i) => pad(c, widths[i])).join(' '); const body = [line(headers), rows.map((r) => line(r)).join('\n')].join('\n'); const footnote = `${prev.size ? 'Δ vs previous main run. ' : 'no prior main run for Δ. '}` + - `* = >${REGRESSION_PCT}% slower (track-only, non-gating). FPS is CI-headless — indicative only.`; + `* = >${REGRESSION_PCT}% slower (track-only, non-gating). ` + + `GAL fps = completed GAL frames on CI's software rasteriser (llvmpipe) — a regression signal, ` + + `NOT user-facing frame rate; its Δ/* are computed on the 1x number. rAF is the legacy tick count, ` + + `kept for continuity: it ticks on the compositor's schedule whether or not anything rendered, so ` + + `it can read 120 while the renderer is stalled.`; return { block: '**Runtime perf** (eeschema + pcbnew)\n```\n' + body + '\n```\n' + footnote, regressed }; }