diff --git a/DEBUG.md b/DEBUG.md new file mode 100644 index 0000000..c279ff6 --- /dev/null +++ b/DEBUG.md @@ -0,0 +1,272 @@ +# Debugging guide — KiCad / wxWidgets WASM + +A practical reference for debugging this project: the kinds of issues WASM + +Asyncify + browser builds throw at you, the tools that actually work here, and +the gotchas of our specific build pipeline. It is **not** a writeup of any one +bug — for a concrete worked example see [§6](#6-a-worked-example) and the +project memory. + +If you're new to this codebase, read [§5 (project gotchas)](#5-project-specific-gotchas) +first — most wasted hours come from not knowing how the split build and the +shim layer behave. + +--- + +## 1. Classes of issue we hit here + +- **Engine-specific intolerance** — the same `pcbnew.wasm` runs in Firefox but + not Chrome (or vice versa). Usually a V8-vs-SpiderMonkey difference in how an + Asyncify-instrumented or very large function is handled. +- **Silent stalls vs. hard crashes** — execution stops making progress with *no* + exception, trap, or crash report. Distinguishing "crashed" from "hung" from + "stalled" is half the battle (§2.6). +- **Asyncify state problems** — unwind/rewind not completing, instrumentation on + a function that shouldn't have it, or a function too large once instrumented. +- **Shim/codegen coupling** — `inject-dyncall-shims.sh` patches Emscripten output + by pattern; a flag change that alters codegen can silently break those patches. +- **Tooling blind spots** — async console delivery, stripped name sections, + Playwright hiding the renderer's stderr (§4). + +--- + +## 2. Tools & techniques + +### 2.1 Stub-bisection *(the workhorse)* +Comment out / early-`return` a suspect call, rebuild, and observe a **binary +survives-or-fails** outcome. This is the most reliable signal we have because it +does **not** depend on reading logs (which lag — see §4). Narrow by halving: +disable half the suspects, see which half flips the outcome. +- *When:* you can localize a failure to "before/after some call." +- *Caveat:* at `-O2`, dead-code elimination removes more around an early `return` + than you intend — keep this in mind when a stub "fixes" too much. + +### 2.2 `SHIM_DIAGNOSTICS=1` fast loop *(skip the rebuild)* +The only host-side JS step is `inject-dyncall-shims.sh`. Re-run it on a pristine +`pcbnew.js` while keeping the already-finalized/asyncified `pcbnew.wasm` — JS-only +changes go from a multi-minute rebuild to seconds: +```bash +cp output/pcbnew.pristine.js output/pcbnew.js +SHIM_DIAGNOSTICS=1 ./scripts/common/inject-dyncall-shims.sh output/pcbnew.js +cd tests && npm run setup:kicad +``` +See the `wasm-build-fast-iteration` project memory. + +### 2.3 Logging-only diagnostics module (`scripts/common/shims/diagnostics.js`) +Injected **only** when `SHIM_DIAGNOSTICS=1` (off by default, safe to leave in +tree). Provides hooks that need no rebuild: +- Asyncify lifecycle: `doRewind`, `handleSleep` (unwind/rewind markers). +- Modal lifecycle. +- A **WebGL call tracer** (did any GL call happen before the failure?). +- A **dynCall tracer**: wraps the shim-bound `dynCall_ii`/`dynCall_vi` to log + `ptr`, `getWasmTableEntry(ptr).name` (the function index), and a JS stack for + rare/large table indices. Arm it at the main rewind to bound log volume. +- Periodic asyncify-state monitor (catch "JS task queue stopped pumping"). + +Output is at `console.log` level (not error/warn). This is the JS-side tracer; the +C++ source diagnostics are separate and flag-gated — see §2.9. + +### 2.4 Symbolizing wasm function indices +The loaded (post-asyncify) wasm has **no `name` section**, so V8/Firefox report +bare function indices (`func[20736]`). The Asyncify pass **preserves function +indices**, so a symbol map taken from the *pre-asyncify* wasm is still valid: +```bash +# the in-container wasm-opt is a STUB; use the real one +/emsdk/upstream/bin/wasm-opt.real --symbolmap=/tmp/syms.map +# then look up the index, e.g. 20736 -> PCB_EDIT_FRAME::setupUIConditions() +``` +Generate the map from a build that still has names (the debug build's +pre-asyncify wasm). See §5 on names/DWARF. + +### 2.5 Cross-engine comparison +Run the **same** diagnostics build in Firefox and Chrome and compare state at the +**same dispatch point** (e.g. asyncify `state`/`currData` at the suspect +`dynCall`). If both reach a point with identical state but only one proceeds, you +have isolated an engine-specific bug and can stop looking for a logic error. + +### 2.6 Crash vs. hang vs. stall +A failure with no exception is not necessarily a crash. Find the renderer PID and +inspect it: +```bash +ps -axo pid,%cpu,%mem,command | grep -i 'Google Chrome' +sample 3 # what is the main thread doing? +``` +- **Idle in `CFRunLoop`/`mach_msg2_trap`, ~0% CPU** → a *stall* (event loop alive, + but nothing scheduled to run). Not a deadlock. +- **Blocked on a futex / `Atomics.wait`** → a pthread/lock issue. +- **Spinning at 100%** → an infinite loop. +- **Gone + a `.ips` report** → a real signal crash. + +To see the **renderer's own stderr** and a real crash reason, launch system +Chrome **outside Playwright** (Playwright forces `--disable-breakpad` and only +pipes the *browser* process stderr): serve `tests/apps` with the COOP/COEP headers +(`tests/serve.json`) and open the page in a normal Chrome with crash reporting on. +On-load failures need no interaction to reproduce. + +### 2.7 Build-flag diagnostics +- `-sASSERTIONS=2` turns silent UB into named errors. **But** it changes + Emscripten codegen and can break `inject-dyncall-shims.sh`'s `sed` patterns + (causing a *different*, red-herring failure), and it implicitly enables + `STACK_OVERFLOW_CHECK`, whose `___set_stack_limits` our host Asyncify pass + strips → pair it with `-sSTACK_OVERFLOW_CHECK=0`. Prefer the §2.3 dynCall + tracer on a normal build when you can. +- `--pass-arg=asyncify-asserts` (added to the `wasm-opt --asyncify` invocation in + `apply-asyncify.sh`) adds Asyncify state-machine runtime checks — use it to + validate the removelist (a wrongly-excluded function that *does* unwind is + otherwise silent corruption). + +### 2.8 Isolated standalone probes +`tests/apps/standalone/coroutine-pthread/` builds minimal C++ probes with the +*real* libcontext + Asyncify + pthreads + DYNCALLS + the shim, run via +`tests/e2e/coroutine-pthread.spec.ts`. Use these to reproduce a mechanism in +isolation. **Reality check:** an isolated probe often *won't* reproduce a bug +that needs the full app runtime — don't over-trust a green probe. + +### 2.9 Source diagnostic logging flags (`--diag=`) +The KiCad C++ source carries built-in diagnostic logging, **off by default**, +enabled per category at build time: +```bash +./docker/build.sh --debug --diag=gal,coroutine,ctor # or: --diag=all +``` +| `--diag=` value | covers | +|---|---| +| `gal` | `[DIAG_GAL]` — GAL/WebGL pipeline (paint, context create/lock, init) | +| `coroutine` | `[WASM_FCONTEXT]` fiber switches + `[DIAG_TOOL]`/`[DIAG_DISP]` tool dispatch | +| `ctor` | `[DIAG_CTOR]` — `PCB_EDIT_FRAME` startup milestones | + +- Each value maps to a `-DKICAD_DIAG_*` define that gates the `KI_DIAG_*` macros + in `kicad/include/kicad_wasm_diag.h`. All output goes to **stdout** → it shows + as `[KICAD_OUT]` logs, never `[KICAD_ERR]` errors. +- **Compile-time:** changing `--diag` changes `CMAKE_CXX_FLAGS`, so it forces a + recompile (slow once per flag combo, then ccache-cached). Works with `--debug` + or `--release`. +- Separate from the JS shim tracer (§2.3), which stays `SHIM_DIAGNOSTICS`-gated. + +--- + +## 3. Principles + +1. **Reproduce cleanly first** — a stable engine-X-fails / engine-Y-passes + baseline before changing anything. +2. **Fix the build infra before iterating** — a flaky build wastes every + subsequent experiment. +3. **Narrow by bisection**, with binary outcomes, not by staring at logs. +4. **Turn silent failures into named ones** (assertions, asyncify-asserts) or + into a state comparison across engines. +5. **Know the tooling's blind spots** (§4) before trusting what it shows you. + +--- + +## 4. Tooling blind spots (read before trusting output) + +- **Console is async** — `printf`/`console.*` from WASM reaches Playwright via + CDP asynchronously; the *last delivered* line can lag the real failure point. + Use stub-bisection for ground truth, not "the last log line." +- **No name section** in the shipped wasm → bare indices (§2.4). +- **Asyncify shifts code offsets** — DWARF line info is generated before the host + Asyncify pass rewrites the code, so source-line mapping on the *shipped* wasm is + stale. Asyncify *does* preserve function indices and names. +- **Playwright hides the renderer** — forces `--disable-breakpad`, pipes only the + browser process stderr (§2.6). +- **macOS `sample`/`.ips`** see wasm frames as numeric offsets, not C++ names. + +--- + +## 5. Project-specific gotchas + +- **Split build.** `docker/build.sh` compiles + links inside Docker, but the + in-container `wasm-opt` and `wasm-emscripten-finalize` are **stubbed** (they OOM + on the large wasm). The real `wasm-emscripten-finalize` and + `wasm-opt --asyncify` run **on the host** afterward (`apply-finalize.sh`, + `apply-asyncify.sh`). Real binary: `…/upstream/bin/wasm-opt.real`. +- **Per-branch Docker volumes.** The compose project name is derived from the git + branch, so each branch has its own build-cache volume/container. Switching + optimization level (`-O1`↔`-O2`) busts ccache and forces a full recompile. +- **COOP/COEP.** SharedArrayBuffer/pthreads need cross-origin isolation headers; + serve `tests/apps` with `tests/serve.json` (`npx serve apps -c ../serve.json`). +- **The shim layer.** `inject-dyncall-shims.sh` binds bare `dynCall_` to the + real `DYNCALLS=1` exports and patches several Emscripten empty-stub callbacks by + `sed` pattern — so codegen-changing flags can silently break it. +- **Names / DWARF, concretely.** Neither build keeps a `name` section in the + *runtime* wasm (it carries only `external_debug_info` + `target_features`). The + **debug** build (`-O1 -g -gseparate-dwarf`) puts full DWARF in a ~1.5 GB + `pcbnew.wasm.debug.wasm` sidecar (loaded on demand by DevTools' C/C++ extension); + the **release** build (`-O2`, no `-g`) has neither names nor DWARF. So readable + symbols come from the debug build's DWARF / the §2.4 symbol map, not from the + shipped binary. + +--- + +## 6. A worked example + +The **Chrome-only startup stall** (May 2026): V8 could not run the +Asyncify-*instrumented* `PCB_EDIT_FRAME::setupUIConditions()` (a huge function +that never actually unwinds) when it was invoked from the Asyncify-rewound +constructor stack — a silent stall, not a crash; Firefox ran the identical wasm +fine. Found with stub-bisection (§2.1) + the dynCall tracer (§2.3) + symbol map +(§2.4) + cross-engine state comparison (§2.5) + `sample` (§2.6). + +Two fixes, both valid (see [§7](#7-debug-vs-production-builds)): +1. **Targeted:** add the function to `ASYNCIFY_REMOVE` in `apply-asyncify.sh` (it + never unwinds, so excluding it from instrumentation is correct). ← committed default. +2. **Systemic:** run the optimization Asyncify requires (§7), which shrinks the + instrumented function below V8's limit and removes the need for the manual entry. + +Details: the `chrome-asyncify-rewind-crash` and `bundle-size-asyncify-optimization` +project memories, and git history of `apply-asyncify.sh`. + +--- + +## 7. Debug vs. production builds + +The committed default is the **debug** build with a manual `ASYNCIFY_REMOVE` +list — maximally debuggable, but large (~338 MB wasm / ~137 MB gzip). You can +**always** produce a much smaller production build, and the recipe is below. + +### What the knobs do +Two independent knobs: +- **`-g` (debug info)** — whether a source map exists at all. Debug = + `-g -gseparate-dwarf` (DWARF sidecar); release = none. +- **`-O` (optimization)** — how much the code is rewritten. This is what actually + fixes the "function too big for V8" class of bug, because Asyncify emits + deliberately verbose instrumentation (spills every live local) and **relies on + the optimizer to coalesce it back down**. The Emscripten/Binaryen docs are + emphatic that you must optimize when using Asyncify. + +### Recipe: production build (release + Asyncify optimization) +This is a documented procedure — **leave the committed code as-is** (debug + +removelist) and apply these when you want a shippable build: + +1. **Build in release mode** (drops `-g`, compiles `-O2`): + ```bash + ./docker/build.sh # no --debug => Release + ``` + (The debug build is `./docker/build.sh --debug`.) + +2. **Add the optimization pass to Asyncify.** In + `scripts/common/apply-asyncify.sh`, run `wasm-opt --asyncify …` as today, then + a second pass over the result: + ```bash + "${WASM_OPT}" -O2 "${ASYNCIFIED_WASM}" -o "${OUTPUT_WASM}" + ``` + Run it as a **separate** invocation after `--asyncify` (asyncify-then-optimize) + so the optimizer cleans up the instrumentation; doing it sequentially also + keeps peak RAM lower (one heavy `wasm-opt` at a time — it needs ~10–15 GB). + +3. **Drop the now-unnecessary removelist entries.** With the optimization pass, + functions like `PCB_EDIT_FRAME::setupUIConditions()` no longer exceed V8's + limit, so they don't need to be in `ASYNCIFY_REMOVE`. (Keep any entry that is + still needed; validate with `asyncify-asserts`, §2.7.) + +### Measured result (May 2026) +| build | raw wasm | gzip | source-level debugging | +|---|---|---|---| +| debug + removelist (committed) | 338 MB | 137 MB | full (DWARF sidecar) | +| release + `-O2` asyncify | 187 MB | **65 MB** | none | + +The release+optimized build passed the Chrome **and** Firefox PCBnew e2e +("select draw lines") **without** the `setupUIConditions` removelist entry — i.e. +optimization fixes the stall systemically. Trade-off: it loses DWARF/source-level +debugging (see §5). **Keep the debug build for investigation** — most of our +effective tooling (`printf` milestones, the JS-side tracers in §2.3) works +identically in release, but symbol resolution and variable inspection need the +debug build. diff --git a/kicad b/kicad index f6e9239..6efc02a 160000 --- a/kicad +++ b/kicad @@ -1 +1 @@ -Subproject commit f6e9239aaa61700e1d434dc7602afc2f7f7b7f7e +Subproject commit 6efc02aacfc876323e0bef14425fb7c7ae56eea5 diff --git a/scripts/common/apply-asyncify.sh b/scripts/common/apply-asyncify.sh index c5a7dd6..f74e0a2 100755 --- a/scripts/common/apply-asyncify.sh +++ b/scripts/common/apply-asyncify.sh @@ -45,6 +45,7 @@ StepAP214_Protocol::StepAP214_Protocol() BRepCheck_ParallelAnalyzer::operator()(int) const ShapeFix_Wire::FixGap3d(int, bool) ShapeFix_Wire::FixGap2d(int, bool) +PCB_EDIT_FRAME::setupUIConditions() REMOVELIST ) diff --git a/scripts/common/shims/diagnostics.js b/scripts/common/shims/diagnostics.js index be5743e..c67c6a2 100644 --- a/scripts/common/shims/diagnostics.js +++ b/scripts/common/shims/diagnostics.js @@ -7,6 +7,9 @@ // observed right up to the faulting point. (function() { var modalActive = false; + var glTraceActive = false; // armed at the first main rewind (rewindId===0) below + var glCallSeq = 0; + var glTraceCap = 8000; // safety cap so a non-crashing run can't log forever var tableLen = function() { return (typeof wasmTable !== "undefined" && wasmTable) ? wasmTable.length : -1; }; var asyncState = function() { return (typeof Asyncify !== "undefined") ? Asyncify.state : "N/A"; }; @@ -15,9 +18,9 @@ var __origAsyncCall = _emscripten_async_call; _emscripten_async_call = function(func, arg, millis) { var inBounds = func >= 0 && func < tableLen(); - console.warn("[DIAG_ASYNC_CALL] func=" + func + " arg=" + arg + " millis=" + millis + + console.log("[DIAG_ASYNC_CALL] func=" + func + " arg=" + arg + " millis=" + millis + " inBounds=" + inBounds + " modalActive=" + modalActive + " state=" + asyncState()); - if (!inBounds) { console.error("[DIAG_ASYNC_CALL] OUT OF BOUNDS at schedule time! func=" + func); console.trace(); } + if (!inBounds) { console.log("[DIAG_ASYNC_CALL] OUT OF BOUNDS at schedule time! func=" + func); console.trace(); } return __origAsyncCall(func, arg, millis); }; } @@ -26,7 +29,7 @@ if (typeof Asyncify !== "undefined" && Asyncify.setDataRewindFunc) { var __origSetRewind = Asyncify.setDataRewindFunc.bind(Asyncify); Asyncify.setDataRewindFunc = function(ptr, forced) { - console.warn("[DIAG_REWIND_FUNC] ptr=" + ptr + " forced=" + forced + " state=" + Asyncify.state + + console.log("[DIAG_REWIND_FUNC] ptr=" + ptr + " forced=" + forced + " state=" + Asyncify.state + " modalActive=" + modalActive + " callStack=" + JSON.stringify(Asyncify.exportCallStack)); return __origSetRewind(ptr, forced); }; @@ -36,12 +39,38 @@ // immediately before re-entering wasm, so the last line before the crash names it. if (typeof Asyncify !== "undefined" && typeof Asyncify.doRewind === "function") { var __origDoRewind = Asyncify.doRewind.bind(Asyncify); + var heap32 = function () { return (typeof GROWABLE_HEAP_I32 === "function") ? GROWABLE_HEAP_I32() : HEAP32; }; Asyncify.doRewind = function(ptr) { - var rewindId = -1; - try { rewindId = (typeof GROWABLE_HEAP_I32 === "function") ? GROWABLE_HEAP_I32()[((ptr + 8) >> 2)] : HEAP32[((ptr + 8) >> 2)]; } catch (e) {} - console.warn("[DIAG_DOREWIND] ptr=" + ptr + " rewindId=" + rewindId + " state=" + asyncState() + - " modalActive=" + modalActive + " — re-entering wasm now"); - return __origDoRewind(ptr); + var H = heap32(); + var rd = function (off) { try { return H[((ptr + off) >> 2)]; } catch (e) { return -999; } }; + // asyncify_data layout: [ptr+0]=current stack pos (top of saved data), + // [ptr+4]=stack end, [ptr+8]=rewindId. Saved call-index/locals live below [ptr+0]. + var curPos = rd(0), stackEnd = rd(4), rewindId = rd(8); + var name = (Asyncify.callStackIdToName && Asyncify.callStackIdToName[rewindId]) || "?"; + var usedBytes = curPos - (ptr + 12); + console.log("[DIAG_DOREWIND] ptr=" + ptr + " rewindId=" + rewindId + " (" + name + ")" + + " curPos=" + curPos + " stackEnd=" + stackEnd + " usedBytes=" + usedBytes + + " state=" + asyncState() + " — re-entering wasm now"); + // Arm the WebGL tracer exactly at the main rewind (the crash window: the silent V8 + // abort happens right after this rewind returns to main, before coroutine #2/first paint). + if (rewindId === 0 && !glTraceActive) { + glTraceActive = true; + console.log("[DIAG_GL] tracing ARMED at main rewind (rewindId=0)"); + } + // Dump the saved call-index chain (first words of the buffer) so we can see the + // depth/shape of what the rewind replays at the crash. + try { + var words = []; + var start = ptr + 12; + for (var a = start; a < curPos && a < start + 256; a += 4) words.push(H[(a >> 2)]); + console.log("[DIAG_DOREWIND] saved-data[" + words.length + "w]: " + JSON.stringify(words)); + } catch (e) {} + try { + return __origDoRewind(ptr); + } catch (e) { + console.log("[DIAG_DOREWIND] EXCEPTION during rewind: " + e + " | " + (e && e.stack)); + throw e; + } }; } @@ -50,7 +79,7 @@ var __origDynCallVi = dynCall_vi; dynCall_vi = function(index, a0) { if (index < 0 || index >= tableLen()) { - console.error("[DIAG_DYNCALL_VI] OUT OF BOUNDS index=" + index + " tableLen=" + tableLen() + + console.log("[DIAG_DYNCALL_VI] OUT OF BOUNDS index=" + index + " tableLen=" + tableLen() + " modalActive=" + modalActive + " state=" + asyncState()); console.trace(); } @@ -64,16 +93,16 @@ setInterval(function() { if (Module._endModal && !seen) { seen = true; modalActive = true; - console.warn("[DIAG_MODAL] modal started, state=" + asyncState()); + console.log("[DIAG_MODAL] modal started, state=" + asyncState()); var __origEnd = Module._endModal; Module._endModal = function(code) { - console.warn("[DIAG_MODAL] EndModal code=" + code + " state=" + asyncState()); + console.log("[DIAG_MODAL] EndModal code=" + code + " state=" + asyncState()); modalActive = false; return __origEnd(code); }; } else if (!Module._endModal && seen) { seen = false; - console.warn("[DIAG_MODAL] modal cleanup, state=" + asyncState()); + console.log("[DIAG_MODAL] modal cleanup, state=" + asyncState()); } }, 100); } @@ -86,11 +115,11 @@ var diagSleepId = 0; Asyncify.handleSleep = function(startAsync) { var id = ++diagSleepId; - console.warn("[DIAG_SLEEP] ENTER id=" + id + " state=" + asyncState() + + console.log("[DIAG_SLEEP] ENTER id=" + id + " state=" + asyncState() + " currData=" + ((typeof Asyncify.currData !== "undefined" && Asyncify.currData) || "null")); return __diagOrigHandleSleep(function(wakeUp) { return startAsync(function(result) { - console.warn("[DIAG_SLEEP] WAKE id=" + id + " state=" + asyncState() + + console.log("[DIAG_SLEEP] WAKE id=" + id + " state=" + asyncState() + " currData=" + ((typeof Asyncify.currData !== "undefined" && Asyncify.currData) || "null")); return wakeUp(result); }); @@ -98,6 +127,119 @@ }; } - console.warn("[DIAG] Asyncify/fiber/modal diagnostics installed (logging only)"); + // 7. WebGL call tracer — pinpoint the exact GL op that crashes Chrome's renderer. + // KiCad runs the GAL on an OffscreenCanvas in the pthread worker (PROXY_TO_PTHREAD + + // OFFSCREENCANVAS_SUPPORT), and this diagnostics code runs in that same worker, so we + // hook getContext where the context is actually created. Each call logs via + // console.error (immediate flush → captured even just before a hard V8 abort), but + // only once glTraceActive is set (at the main rewind), so volume = the crash window. + function wrapGLContext(ctx, kind) { + if (!ctx) return ctx; + try { if (ctx.__diagWrapped) return ctx; ctx.__diagWrapped = true; } catch (e) {} + console.log("[DIAG_GL] context created kind=" + kind); + return new Proxy(ctx, { + get: function(target, prop) { + var val = target[prop]; + if (typeof val === "function") { + return function() { + if (glTraceActive && glCallSeq < glTraceCap) { + console.log("[DIAG_GL] #" + (++glCallSeq) + " " + String(prop)); + } + return val.apply(target, arguments); + }; + } + return val; + } + }); + } + function hookGetContext(proto, kind) { + if (!proto || typeof proto.getContext !== "function" || proto.__diagGCHooked) return; + proto.__diagGCHooked = true; + var orig = proto.getContext; + proto.getContext = function(type) { + // Log the ATTEMPT before calling through, so if getContext itself crashes the + // renderer (e.g. a Chrome/ANGLE WebGL-context bug) this is the last line we see. + if (type === "webgl2" || type === "webgl" || type === "experimental-webgl") { + var attrs = ""; + try { attrs = JSON.stringify(arguments[1] || {}); } catch (e) {} + console.log("[DIAG_GL] getContext(" + kind + ":" + type + ") attrs=" + attrs + " — calling through now"); + } + var ctx = orig.apply(this, arguments); + if (type === "webgl2" || type === "webgl" || type === "experimental-webgl") { + console.log("[DIAG_GL] getContext returned " + (ctx ? "a context" : "NULL")); + try { return wrapGLContext(ctx, kind + ":" + type); } catch (e) { return ctx; } + } + return ctx; + }; + } + if (typeof OffscreenCanvas !== "undefined") hookGetContext(OffscreenCanvas.prototype, "offscreen"); + if (typeof HTMLCanvasElement !== "undefined") hookGetContext(HTMLCanvasElement.prototype, "html"); + + // 8. dynCall_ii / dynCall_vi invocation tracer (logging only). The shim routes the + // pthread-entry (ii) and fiber-entry/signal/timer (vi) callbacks through these bound + // instrumented dynCall_. Wrap them to log each invocation + the function pointer, + // armed at the main rewind (glTraceActive) so volume = the crash window. The LAST line + // before the silent crash names the faulting dispatch + its ptr. Tag thread for context. + var __thr = (typeof ENVIRONMENT_IS_PTHREAD !== "undefined" && ENVIRONMENT_IS_PTHREAD) ? "worker" : "main"; + var __fnName = function(ptr) { + try { var f = getWasmTableEntry(ptr); return (f && f.name) ? f.name : "?"; } catch (e) { return "?err"; } + }; + try { + if (typeof dynCall_ii === "function") { + var __origDCii = dynCall_ii; + dynCall_ii = function(ptr, a0) { + if (glTraceActive && glCallSeq < glTraceCap) + console.log("[DIAG_DC] " + __thr + " dynCall_ii ptr=" + ptr + " name=" + __fnName(ptr) + " #" + (++glCallSeq)); + return __origDCii(ptr, a0); + }; + } + } catch (e) {} + try { + if (typeof dynCall_vi === "function") { + var __origDCvi = dynCall_vi; + var __asy = function() { + if (typeof Asyncify === "undefined") return "noAsyncify"; + var st = Asyncify.state; + var cd = (Asyncify.currData || 0); + return "state=" + st + " currData=" + cd; + }; + dynCall_vi = function(ptr, a0) { + var big = glTraceActive && ptr > 15000; // the rare large-index 'vi' dispatches (incl. the stalling 20078) + if (glTraceActive && glCallSeq < glTraceCap) { + console.log("[DIAG_DC] " + __thr + " dynCall_vi ptr=" + ptr + " name=" + __fnName(ptr) + " arg=" + a0 + " #" + (++glCallSeq)); + } + if (big) { + // Asyncify state going IN: if it's non-NORMAL (1=unwinding, 2=rewinding) the + // leftover coroutine state is making the instrumented dispatch misbehave. + console.log("[DIAG_DC_VI] ENTER ptr=" + ptr + " " + __asy()); + var r = __origDCvi(ptr, a0); + // If this RETURNED line never appears, the dispatch unwound/stalled and never came back. + console.log("[DIAG_DC_VI] RETURNED ptr=" + ptr + " " + __asy()); + return r; + } + return __origDCvi(ptr, a0); + }; + } + } catch (e) {} + + // 9. Periodic asyncify-state monitor (main thread). After dynCall_vi(20078)= + // setupUIConditions appears to unwind-and-never-rewind, this timer (which still runs + // on the idle event loop) reveals the post-stall Asyncify.state: if it's stuck at + // 1 (UNWINDING) or 2 (REWINDING) with a fixed currData, the app yielded and the + // rewind was never scheduled. Logs only on change + a heartbeat. + if (typeof Asyncify !== "undefined" && __thr === "main") { + var __lastSt = -999, __lastCd = -999, __hb = 0; + setInterval(function() { + var st = Asyncify.state, cd = (Asyncify.currData || 0); + if (st !== __lastSt || cd !== __lastCd) { + console.log("[DIAG_ASTATE] change -> state=" + st + " currData=" + cd); + __lastSt = st; __lastCd = cd; + } else if (st !== 0 && (++__hb % 6 === 0)) { + console.log("[DIAG_ASTATE] STILL state=" + st + " currData=" + cd + " (stuck?)"); + } + }, 500); + } + + console.log("[DIAG] Asyncify/fiber/modal diagnostics installed (logging only) [" + __thr + "]"); })(); // === End diagnostics === diff --git a/scripts/kicad/build-pcbnew.sh b/scripts/kicad/build-pcbnew.sh index 2f7ac46..fc1044f 100755 --- a/scripts/kicad/build-pcbnew.sh +++ b/scripts/kicad/build-pcbnew.sh @@ -41,6 +41,7 @@ NO_CLEAN=1 FULL_CLEAN=0 SKIP_DEPS=1 DEBUG=0 +DIAG_LIST="" while [[ $# -gt 0 ]]; do case $1 in --full) @@ -66,6 +67,14 @@ while [[ $# -gt 0 ]]; do export DEBUG_BUILD shift ;; + --diag=*) + DIAG_LIST="${1#--diag=}" + shift + ;; + --diag) + DIAG_LIST="$2" + shift 2 + ;; -j) export JOBS="$2" shift 2 @@ -80,6 +89,25 @@ while [[ $# -gt 0 ]]; do esac done +# Diagnostic preprocessor defines from --diag= (gal, coroutine, ctor, all). +# These gate the KI_DIAG_* macros in kicad/include/kicad_wasm_diag.h. Output goes +# to stdout ([KICAD_OUT] logs), never errors. Off by default. +DIAG_DEFINES="" +if [ -n "${DIAG_LIST}" ]; then + IFS=',' read -ra _diag_cats <<< "${DIAG_LIST}" + for _cat in "${_diag_cats[@]}"; do + case "${_cat}" in + gal) DIAG_DEFINES="${DIAG_DEFINES} -DKICAD_DIAG_GAL=1" ;; + coroutine) DIAG_DEFINES="${DIAG_DEFINES} -DKICAD_DIAG_COROUTINE=1" ;; + ctor) DIAG_DEFINES="${DIAG_DEFINES} -DKICAD_DIAG_CTOR=1" ;; + all) DIAG_DEFINES="${DIAG_DEFINES} -DKICAD_DIAG_GAL=1 -DKICAD_DIAG_COROUTINE=1 -DKICAD_DIAG_CTOR=1" ;; + "") ;; + *) log_warn "Unknown --diag category: '${_cat}' (valid: gal, coroutine, ctor, all)" ;; + esac + done + log_info "Diagnostic logging enabled:${DIAG_DEFINES}" +fi + log_info "Using ${JOBS} parallel jobs" # Step 1: Clean build directories @@ -241,7 +269,7 @@ emcmake cmake "${KICAD_DIR}" \ -DCMAKE_MODULE_PATH="${WASM_LAYER}/cmake" \ -DSYSROOT="${SYSROOT}" \ -DCMAKE_POLICY_VERSION_MINIMUM=3.5 \ - -DCMAKE_CXX_FLAGS="${EXTRA_FLAGS} -pthread -sUSE_ZLIB=1 -DKICAD_USE_PLATFORM_WASM=1 -I${SYSROOT}/include -I${STUBS_DIR}" \ + -DCMAKE_CXX_FLAGS="${EXTRA_FLAGS} -pthread -sUSE_ZLIB=1 -DKICAD_USE_PLATFORM_WASM=1${DIAG_DEFINES} -I${SYSROOT}/include -I${STUBS_DIR}" \ -DCMAKE_C_FLAGS="${EXTRA_FLAGS} -pthread -sUSE_ZLIB=1 -I${SYSROOT}/include -I${STUBS_DIR}" \ -DCMAKE_EXE_LINKER_FLAGS="${LINKER_DEBUG_FLAGS} -pthread -sUSE_ZLIB=1 -sASYNCIFY=1 -sDYNCALLS=1 -sASYNCIFY_STACK_SIZE=65536 -sUSE_PTHREADS=1 -sPTHREAD_POOL_SIZE='navigator.hardwareConcurrency' -sPTHREAD_POOL_SIZE_STRICT=0 -sALLOW_MEMORY_GROWTH=1 -sINITIAL_MEMORY=256MB -sMAXIMUM_MEMORY=4GB -sMAX_WEBGL_VERSION=2 -sEXPORTED_RUNTIME_METHODS=['ccall','cwrap','UTF8ToString','stringToUTF8','lengthBytesUTF8','dynCall'] -sDEFAULT_LIBRARY_FUNCS_TO_INCLUDE=['\$dynCall'] --bind -L${SYSROOT}/lib ${STUBS_BUILD}/libgit2_stub.a ${STUBS_BUILD}/libcurl_stub.a ${STUBS_BUILD}/libpcbnew_scripting_stub.a ${STUBS_BUILD}/libnng_stub.a ${STUBS_BUILD}/pcbnew_embind.o" \ -DCMAKE_PREFIX_PATH="${SYSROOT};${WX_BUILD}" \ diff --git a/tests/apps/Makefile.wasm b/tests/apps/Makefile.wasm index 5389a2e..d2e7620 100644 --- a/tests/apps/Makefile.wasm +++ b/tests/apps/Makefile.wasm @@ -650,3 +650,45 @@ $(S)/coroutine-pthread/mainloop_repro.html: $(S)/coroutine-pthread/mainloop_repr coroutine-pthread-mainloop: $(S)/coroutine-pthread/mainloop_repro.html .PHONY: coroutine-pthread-mainloop + +# WebGL2 + coroutine reproduction (no wx, no pthreads, default shell with #canvas) +LDFLAGS_COROUTINE_GL = $(DEBUG_LDFLAGS) -sALLOW_MEMORY_GROWTH -sERROR_ON_UNDEFINED_SYMBOLS=0 \ + -sASYNCIFY=1 -sASYNCIFY_STACK_SIZE=65536 -sASYNCIFY_IMPORTS=['emscripten_fiber_swap'] \ + -sDYNCALLS=1 -sMAX_WEBGL_VERSION=2 -sMIN_WEBGL_VERSION=2 -sEXPORTED_RUNTIME_METHODS=['ccall'] + +$(S)/coroutine-pthread/gl_repro.o: $(S)/coroutine-pthread/gl_repro.cpp $(S)/coroutine/kicad_coroutine_harness.h + @mkdir -p $(S)/coroutine-pthread + $(CXX) -c $(CXXFLAGS) -I$(KICAD_ROOT)/thirdparty/libcontext -I$(S)/coroutine $< -o $@ + +$(S)/coroutine-pthread/gl_repro.html: $(S)/coroutine-pthread/gl_repro.o $(S)/coroutine/libcontext.o + $(CXX) $^ $(LDFLAGS_COROUTINE_GL) -o $@ + ../../scripts/common/inject-dyncall-shims.sh $(basename $@).js + +coroutine-pthread-gl: $(S)/coroutine-pthread/gl_repro.html +.PHONY: coroutine-pthread-gl + +# WebGL2 + coroutine + PTHREADS (the last untested combo: KiCad uses GL + pthreads together) +LDFLAGS_COROUTINE_GL_PTHREAD = $(LDFLAGS_COROUTINE_GL) -pthread \ + -sPTHREAD_POOL_SIZE='navigator.hardwareConcurrency' -sPTHREAD_POOL_SIZE_STRICT=0 + +$(S)/coroutine-pthread/gl_repro_pt.o: $(S)/coroutine-pthread/gl_repro.cpp $(S)/coroutine/kicad_coroutine_harness.h + @mkdir -p $(S)/coroutine-pthread + $(CXX) -c $(CXXFLAGS) -pthread -I$(KICAD_ROOT)/thirdparty/libcontext -I$(S)/coroutine $< -o $@ + +$(S)/coroutine-pthread/gl_repro_pt.html: $(S)/coroutine-pthread/gl_repro_pt.o $(S)/coroutine-pthread/libcontext_pt.o + $(CXX) $^ $(LDFLAGS_COROUTINE_GL_PTHREAD) -o $@ + ../../scripts/common/inject-dyncall-shims.sh $(basename $@).js + +coroutine-pthread-gl-pt: $(S)/coroutine-pthread/gl_repro_pt.html +.PHONY: coroutine-pthread-gl-pt + +$(S)/coroutine-pthread/vcall_repro.o: $(S)/coroutine-pthread/vcall_repro.cpp $(S)/coroutine/kicad_coroutine_harness.h + @mkdir -p $(S)/coroutine-pthread + $(CXX) -c $(CXXFLAGS) -pthread -I$(KICAD_ROOT)/thirdparty/libcontext -I$(S)/coroutine $< -o $@ + +$(S)/coroutine-pthread/vcall_repro.html: $(S)/coroutine-pthread/vcall_repro.o $(S)/coroutine-pthread/libcontext_pt.o + $(CXX) $^ $(LDFLAGS_COROUTINE_PTHREAD_NOWX) -o $@ + ../../scripts/common/inject-dyncall-shims.sh $(basename $@).js + +coroutine-pthread-vcall: $(S)/coroutine-pthread/vcall_repro.html +.PHONY: coroutine-pthread-vcall diff --git a/tests/apps/standalone/coroutine-pthread/gl_repro.cpp b/tests/apps/standalone/coroutine-pthread/gl_repro.cpp new file mode 100644 index 0000000..e7463f6 --- /dev/null +++ b/tests/apps/standalone/coroutine-pthread/gl_repro.cpp @@ -0,0 +1,78 @@ +// Reproduction probe #5: WebGL 2.0 + coroutine, the last untested KiCad factor. +// +// KiCad's GAL renders via WebGL 2.0 in the rAF refresh, and tool coroutines activate +// during the same refresh — so the Asyncify unwind/rewind happens MID-RENDER-FRAME with +// the GL context current. This probe creates a real WebGL-2.0 context and activates the +// coroutine between GL draw calls inside an emscripten_set_main_loop(rAF) frame, then the +// coroutine yields back -> main rewinds the render frame. +// +// No-wx (single-threaded first; GL+pthreads needs OFFSCREEN proxying — add later if this +// passes). Firefox should reach "[REPRO] DONE"; if system Chrome crashes before DONE, the +// WebGL x coroutine-rewind interaction is the missing factor. + +#include "kicad_coroutine_harness.h" + +#include +#include +#include + +#include + +using coroutine_test::TestCoroutine; + +static EMSCRIPTEN_WEBGL_CONTEXT_HANDLE g_ctx = 0; +static int g_frame = 0; + +static void run_coroutine() +{ + TestCoroutine co( []( TestCoroutine& self ) { + std::printf( "[REPRO] coroutine body running (mid-GL-frame), about to yield\n" ); + std::fflush( stdout ); + self.Yield( 42 ); + } ); + + bool running = co.Call( 1 ); // unwinds the render frame back to dynCall_v; yields back + std::printf( "[REPRO] after Call: running=%d lastValue=%ld\n", + (int) running, (long) co.LastReturnValue() ); + std::fflush( stdout ); + + running = co.Resume( 2 ); + std::printf( "[REPRO] after Resume: running=%d\n", (int) running ); + std::fflush( stdout ); +} + +static void render_frame() +{ + ++g_frame; + glClearColor( 0.1f, 0.2f, 0.3f, 1.0f ); + glClear( GL_COLOR_BUFFER_BIT ); // a real WebGL2 draw call before the coroutine + + if( g_frame >= 2 ) + { + std::printf( "[REPRO] frame %d: activating coroutine mid-GL-frame\n", g_frame ); + std::fflush( stdout ); + + run_coroutine(); // coroutine yields -> Asyncify rewinds the render frame + + glClearColor( 0.3f, 0.2f, 0.1f, 1.0f ); + glClear( GL_COLOR_BUFFER_BIT ); // another GL call after the coroutine resumes + std::printf( "[REPRO] DONE\n" ); + std::fflush( stdout ); + emscripten_cancel_main_loop(); + } +} + +int main() +{ + EmscriptenWebGLContextAttributes attrs; + emscripten_webgl_init_context_attributes( &attrs ); + attrs.majorVersion = 2; + attrs.minorVersion = 0; + g_ctx = emscripten_webgl_create_context( "#canvas", &attrs ); + emscripten_webgl_make_context_current( g_ctx ); + std::printf( "[REPRO] start; WebGL2 context=%d\n", (int) g_ctx ); + std::fflush( stdout ); + + emscripten_set_main_loop( render_frame, 0, 0 ); + return 0; +} diff --git a/tests/apps/standalone/coroutine-pthread/vcall_repro.cpp b/tests/apps/standalone/coroutine-pthread/vcall_repro.cpp new file mode 100644 index 0000000..efd2038 --- /dev/null +++ b/tests/apps/standalone/coroutine-pthread/vcall_repro.cpp @@ -0,0 +1,135 @@ +// Reproduction probe #N for the KiCad Asyncify-fiber Chrome crash. +// +// Root-cause finding (DEBUG.md): the crash is the PCB_EDIT_FRAME ctor calling the +// VIRTUAL setupUIConditions() *after* the first tool coroutine (InvokeTool) has +// unwound+rewound the (deep) ctor stack via asyncify. That virtual call dispatches +// indirectly (-fexceptions) as: wasm -> invoke_vi(JS) -> instrumented dynCall_vi(JS) +// -> setupUIConditions. Chrome's V8 hard-crashes on it; Firefox tolerates it. +// +// nested_repro.cpp recreated the nested invoke_/dynCall chain + a coroutine yield and +// PASSED in both browsers. The factor it did NOT have: a NEW indirect "vi" call made +// from the rewound frame AFTER the coroutine round-trip. This probe adds exactly that. +// +// Shape (mirrors KiCad): +// main -> level(N) ... -> level(0) (deep stack via invoke_ try-hops) +// -> run_coroutine(): co.Call -> Yield -> co.Resume (asyncify unwind+rewind of main) +// -> THEN g_obj->setupConditions() (virtual, in try => invoke_vi -> dynCall_vi) +// +// Built no-wx + pthreads + -fexceptions + DYNCALLS + asyncify + the dyncall shim +// (LDFLAGS_COROUTINE_PTHREAD_NOWX). Firefox should reach "[REPRO] DONE"; if system +// Chrome crashes before DONE, we've reproduced the crash in isolation. + +#include "kicad_coroutine_harness.h" + +#include + +#include +#include + +using coroutine_test::TestCoroutine; + +static const int kBoundaries = 20; // nested invoke_/dynCall JS<->wasm hops (KiCad had ~11) + +typedef void ( *LevelFn )( int ); +static LevelFn g_level = nullptr; + +// Polymorphic hierarchy so the post-coroutine call is a genuine (non-devirtualizable) +// virtual dispatch => call_indirect signature "vi" (the `this` pointer) => invoke_vi -> +// dynCall_vi, exactly like PCB_EDIT_FRAME's virtual setupUIConditions(). +struct Base +{ + virtual void setupConditions() { std::printf( "[REPRO] Base::setupConditions\n" ); } + virtual ~Base() {} +}; +struct Derived : Base +{ + int m_n = 0; + void setupConditions() override + { + // Mimic setupUIConditions: a biggish body with calls + allocations. + volatile int s = 0; + for( int i = 0; i < 64; ++i ) + s += i; + m_n = s; + std::printf( "[REPRO] Derived::setupConditions ran (n=%d)\n", m_n ); + std::fflush( stdout ); + } +}; + +// noinline factory returning a base pointer of a runtime-chosen type so the compiler +// cannot devirtualize the later g_obj->setupConditions() call. +static Base* makeObj( int seed ) __attribute__( ( noinline ) ); +static Base* makeObj( int seed ) +{ + return ( seed & 1 ) ? static_cast( new Derived() ) : new Base(); +} +static Base* g_obj = nullptr; + +static void run_coroutine() +{ + // Mirror KiCad's TOOL_MANAGER pattern: RunMainStack (ContinueAfterRoot bounce) + Yield. + TestCoroutine co( []( TestCoroutine& self ) { + self.RunMainStack( []() {} ); + self.Yield( 42 ); + } ); + + bool running = co.Call( 1 ); // drives the bounce + unwinds main through the invoke_ chain + running = co.Resume( 2 ); // rewinds main + resumes + std::printf( "[REPRO] coroutine done running=%d\n", (int) running ); + std::fflush( stdout ); + + // *** THE CRASH FACTOR *** + // Now (main stack just unwound+rewound) make a VIRTUAL call via invoke_vi -> + // instrumented dynCall_vi from this rewound frame — exactly what the PCB_EDIT_FRAME + // ctor does when it calls the virtual setupUIConditions() after InvokeTool. + try + { + g_obj->setupConditions(); + } + catch( ... ) + { + } + std::printf( "[REPRO] post-coroutine virtual call returned OK\n" ); + std::fflush( stdout ); +} + +extern "C" EMSCRIPTEN_KEEPALIVE void level( int depth ) +{ + if( depth > 0 ) + { + // Indirect call inside a try-region => invoke_vi wrapper => one nested + // asyncify-unwindable JS<->wasm boundary per hop (the KiCad shape). + try + { + g_level( depth - 1 ); + } + catch( ... ) + { + throw; + } + return; + } + + run_coroutine(); // deepest hop +} + +int main() +{ + g_obj = makeObj( 1 ); // a Derived, but via a noinline factory (non-devirtualizable) + g_level = &level; + std::printf( "[REPRO] start, %d nested boundaries, then a virtual call after the coroutine\n", + kBoundaries ); + std::fflush( stdout ); + + try + { + g_level( kBoundaries ); + } + catch( ... ) + { + } + + std::printf( "[REPRO] DONE\n" ); + std::fflush( stdout ); + return 0; +} diff --git a/tests/e2e/coroutine-pthread.spec.ts b/tests/e2e/coroutine-pthread.spec.ts index 5093e1a..fc93b3a 100644 --- a/tests/e2e/coroutine-pthread.spec.ts +++ b/tests/e2e/coroutine-pthread.spec.ts @@ -95,4 +95,56 @@ test.describe('Coroutine pthread main() reproduction', () => { 'main loop should have run and activated the coroutine' ).toBe(true); }); + + // Probe #6: WebGL 2.0 + coroutine activated mid-render-frame (KiCad's GAL render path). + test('WebGL2 + mid-frame fiber reaches DONE without renderer crash', async ({ page, testLogger }) => { + await page.goto('/standalone/coroutine-pthread/gl_repro.html'); + await tryLoadApp(page, 20000).catch(() => {}); + + await expect + .poll(() => testLogger.consoleLogs.some((l) => l.includes('[REPRO] DONE')), { + timeout: 30000, + message: 'should reach [REPRO] DONE (rewind of a mid-GL-frame survived)', + }) + .toBe(true); + + expect( + testLogger.consoleLogs.some((l) => l.includes('WebGL2 context=')), + 'a WebGL2 context should have been created' + ).toBe(true); + }); + + // Probe #7: WebGL2 + coroutine mid-frame + PTHREADS (the GL x pthreads combo KiCad uses). + test('WebGL2 + pthreads mid-frame fiber reaches DONE without renderer crash', async ({ page, testLogger }) => { + await page.goto('/standalone/coroutine-pthread/gl_repro_pt.html'); + await tryLoadApp(page, 25000).catch(() => {}); + + await expect + .poll(() => testLogger.consoleLogs.some((l) => l.includes('[REPRO] DONE')), { + timeout: 30000, + message: 'should reach [REPRO] DONE (GL + pthreads mid-frame rewind survived)', + }) + .toBe(true); + }); + + // Probe #8: a VIRTUAL call via invoke_vi -> instrumented dynCall_vi made from the + // asyncify-rewound frame AFTER a coroutine round-trip. This is the exact factor the + // KiCad crash has that nested_repro lacked: PCB_EDIT_FRAME's ctor calls the virtual + // setupUIConditions() after InvokeTool's first coroutine unwinds/rewinds the ctor stack. + test('post-coroutine virtual call (invoke_vi->dynCall_vi) reaches DONE without renderer crash', async ({ page, testLogger }) => { + await page.goto('/standalone/coroutine-pthread/vcall_repro.html'); + await tryLoadApp(page, 25000).catch(() => {}); + + await expect + .poll(() => testLogger.consoleLogs.some((l) => l.includes('[REPRO] DONE')), { + timeout: 30000, + message: 'should reach [REPRO] DONE (virtual call from the rewound frame survived)', + }) + .toBe(true); + + expect( + testLogger.consoleLogs.some((l) => l.includes('post-coroutine virtual call returned OK')), + 'the post-coroutine virtual call should have completed' + ).toBe(true); + }); }); diff --git a/wxwidgets b/wxwidgets index bb80f91..d1d1627 160000 --- a/wxwidgets +++ b/wxwidgets @@ -1 +1 @@ -Subproject commit bb80f91e8b1f4db8af24f215fc6f77e0d9590794 +Subproject commit d1d1627b279672fc71deb4ff4512a7771dfc2cc8