diff --git a/web/standalone/src/components/WasmTool.tsx b/web/standalone/src/components/WasmTool.tsx index 0139741..eadbeef 100644 --- a/web/standalone/src/components/WasmTool.tsx +++ b/web/standalone/src/components/WasmTool.tsx @@ -61,6 +61,7 @@ import { } from "@/wasm/libs/models-bridge"; import { memfsFilePath, memfsProjectDir, TOOL_BUNDLE, TOOL_FRAME } from "@/wasm/constants"; import { driveProjectIntoTool, type ToolFile } from "@/wasm/kicad-runner"; +import { dump as dumpTrace, mark } from "@/wasm/load-trace"; import { registerSaveHook, type SaveBytes } from "@/wasm/save-flow"; import type { KicadCollabHandle, @@ -1161,12 +1162,14 @@ export function WasmTool({ const msg = e.error instanceof Error ? `${e.error.message}` : String(e.message ?? ""); if (!terminal(msg)) return; append(`[fatal] window error: ${msg}`); + append(dumpTrace()); setFatal(msg); }; const onRejection = (e: PromiseRejectionEvent) => { const msg = e.reason instanceof Error ? e.reason.message : String(e.reason ?? ""); if (!terminal(msg)) return; append(`[fatal] unhandled rejection: ${msg}`); + append(dumpTrace()); setFatal(msg); }; window.addEventListener("error", onError); @@ -1447,6 +1450,7 @@ export function WasmTool({ }); }; const presyncSettled = startLibPresync(); + void presyncSettled.then(() => append(mark("presync:settled"))); // Lib editors (fileless): their frame eagerly enumerates EVERY lib of // its kind at boot, one mutex-serialized bridge crossing at a time // (g_pcbjamProxyMutex in the plugins) — a cold lib would network-fetch @@ -1754,11 +1758,17 @@ export function WasmTool({ if (enumerateGate) await presyncSettled; // Tool booted + project opened. Wait for the wx UI to actually build // before dropping the overlay, so we don't reveal a still-blank editor. + // First paint reached. Past this point the GAL is initialized, so the + // refresh-timer self-rearm loop — the precondition for the production + // load trap — is over. A crash report that contains this mark rules + // that mechanism out; one that stops before it does not. await waitForWxUi(win); + append(mark("ui:ready")); setStatus(""); setReady(true); } catch (err) { append(`[fatal] ${String(err)}`); + append(dumpTrace()); setStatus(`Error: ${String(err)}`); setFatal(String(err)); } diff --git a/web/standalone/src/wasm/kicad-runner.ts b/web/standalone/src/wasm/kicad-runner.ts index 18d3c55..2df7296 100644 --- a/web/standalone/src/wasm/kicad-runner.ts +++ b/web/standalone/src/wasm/kicad-runner.ts @@ -2,6 +2,7 @@ import type { Tool } from "@pcbjam/shared"; import { FILELESS_TOOLS, toolForFile } from "@pcbjam/shared"; import { defaultKicadPro } from "../lib/new-file"; import { memfsFilePath, memfsProjectDir } from "./constants"; +import { mark } from "./load-trace"; import { prescanBoardModels } from "./libs/models-bridge"; import { openFileInTool } from "./open-flow"; @@ -219,14 +220,17 @@ export async function driveProjectIntoTool( const { log, onStatus } = opts; onStatus("Waiting for runtime…"); + log(mark("fs:wait")); const fsReady = await waitFor( () => !!(win.FS && typeof win.FS.writeFile === "function"), 90000, ); if (!fsReady) throw new Error("runtime did not initialize (no FS) in 90s"); + log(mark("fs:ready")); onStatus("Loading project files…"); await syncProjectToMemfs(win, opts); + log(mark("stage:done", `${opts.files.length} file(s)`)); synthesizeProjectFile(win, opts); let result: "programmatic" | "ui" | "failed" | "none" = "none"; @@ -240,7 +244,13 @@ export async function driveProjectIntoTool( } else if (opts.targetPath && !FILELESS_TOOLS.has(opts.tool)) { onStatus("Opening file…"); const abs = memfsFilePath(opts.slug, opts.targetPath); + // The open window is where the prod crash lives: OpenProjectFiles runs the + // footprint-library preload INLINE on the main thread, and the GAL refresh + // timer re-arms every 100 ms until first paint. Bracketing it is what lets a + // crash report be placed inside or outside that window. + log(mark("open:start", opts.targetPath)); result = await openFileInTool(win, abs, { log }); + log(mark("open:settled", `result=${result}`)); log(`[open] result: ${result}`); } onStatus(""); diff --git a/web/standalone/src/wasm/load-trace.test.ts b/web/standalone/src/wasm/load-trace.test.ts new file mode 100644 index 0000000..660d4c8 --- /dev/null +++ b/web/standalone/src/wasm/load-trace.test.ts @@ -0,0 +1,29 @@ +import { describe, expect, it } from "vitest"; +import { dump, mark, resetTrace } from "./load-trace"; + +describe("load-trace", () => { + it("records marks and renders a timeline block", () => { + resetTrace(); + mark("fs:ready"); + mark("open:start", "board.kicad_pcb"); + mark("open:settled", "result=programmatic"); + const out = dump(); + expect(out).toContain("load timeline (3 marks"); + expect(out).toContain("open:start board.kicad_pcb"); + expect(out).toContain("open:settled result=programmatic"); + }); + + it("says so rather than throwing when nothing was recorded", () => { + resetTrace(); + expect(dump()).toBe("[trace] (no entries)"); + }); + + it("is bounded, so a pathological load cannot grow it without limit", () => { + resetTrace(); + for (let i = 0; i < 260; i++) mark(`p${i}`); + const out = dump(); + expect(out).toContain("load timeline (200 marks"); + expect(out).not.toContain(" p0 "); // oldest evicted + expect(out).toContain("p259"); + }); +}); diff --git a/web/standalone/src/wasm/load-trace.ts b/web/standalone/src/wasm/load-trace.ts new file mode 100644 index 0000000..5fd2261 --- /dev/null +++ b/web/standalone/src/wasm/load-trace.ts @@ -0,0 +1,121 @@ +/** + * Load timeline for diagnosing the production board-load crash + * (`RuntimeError: table index is out of bounds` / `indirect call signature + * mismatch`), which we have never reproduced locally across many attempts. + * + * The symbolized stack puts the fault in the GAL refresh timer re-arming itself + * (`onRefreshTimer` -> `ForceRefresh` -> `wxTimer::Start` -> `emscripten_async_call`), + * a loop that only runs while the canvas has not yet initialized — i.e. inside + * `OpenProjectFiles`, during the `PreloadLibraries` pass that runs INLINE on the + * main thread in the WASM build. Every prod report so far has been a console + * dump with no timing and no state, which is why five theories died slowly. + * + * So this records the few facts that would actually discriminate between the + * surviving hypotheses, and nothing else: + * + * - WHEN each phase happened, on one monotonic clock, so a crash can be placed + * inside or outside the open window rather than guessed at from log order; + * - HEAP SIZE at every mark, and every growth event. Growing wasm memory + * detaches JS-side views, and a stale view writing into a detached buffer is + * one of the few mechanisms that produces exactly a bad function-table index + * much later. Locally the heap barely moves; in production it should not be + * guessed at; + * - whether the wx UI ever reached first paint, which is the precondition that + * closes the vulnerable window. + * + * Cheap enough to leave on in production: a bounded array, a handful of marks + * per load, and one `console.info` line each. `dump()` is what a fatal handler + * prints — the whole timeline at once, so a user pasting one block gives us + * everything instead of a screenshot of the last line. + */ + +export interface TraceEntry { + /** ms since the trace started (monotonic; `performance.now`-based). */ + t: number; + phase: string; + detail?: string; + /** wasm linear-memory size at this mark, in bytes (0 when not yet up). */ + heap: number; +} + +const MAX_ENTRIES = 200; +const entries: TraceEntry[] = []; +const t0 = typeof performance !== "undefined" ? performance.now() : 0; +let lastHeap = 0; + +function now(): number { + return (typeof performance !== "undefined" ? performance.now() : 0) - t0; +} + +/** + * Current wasm linear-memory size. Emscripten replaces the HEAP* views on + * growth, so reading `byteLength` off the live view each time reports the + * CURRENT size rather than a cached one. + */ +export function heapBytes(win: unknown = globalThis): number { + const w = win as { + wasmMemory?: { buffer?: ArrayBuffer }; + Module?: { HEAPU8?: { byteLength?: number }; wasmMemory?: { buffer?: ArrayBuffer } }; + }; + return ( + w.wasmMemory?.buffer?.byteLength ?? + w.Module?.wasmMemory?.buffer?.byteLength ?? + w.Module?.HEAPU8?.byteLength ?? + 0 + ); +} + +const mb = (bytes: number): string => `${(bytes / (1024 * 1024)).toFixed(0)}MB`; + +/** + * Record one phase transition. Returns the formatted line so a caller can also + * put it in the in-app log panel (which the fatal overlay now shows) without + * formatting it twice. + */ +export function mark(phase: string, detail?: string): string { + const heap = heapBytes(); + const t = now(); + if (entries.length >= MAX_ENTRIES) entries.shift(); + entries.push(detail ? { t, phase, detail, heap } : { t, phase, heap }); + + // Growth is called out explicitly: it's the event most likely to matter and + // the one hardest to spot in a wall of absolute numbers. + let grew = ""; + if (lastHeap && heap > lastHeap) grew = ` GREW +${mb(heap - lastHeap)}`; + lastHeap = heap; + + const line = + `[trace] +${(t / 1000).toFixed(1)}s ${phase}` + + (detail ? ` ${detail}` : "") + + (heap ? ` heap=${mb(heap)}${grew}` : ""); + try { + console.info(line); + } catch { + /* console unavailable — the entry is still recorded for dump() */ + } + return line; +} + +/** + * The whole timeline as one block, for a fatal handler to print. One paste from + * a user then carries the full load shape instead of a single error line. + */ +export function dump(): string { + if (entries.length === 0) return "[trace] (no entries)"; + const rows = entries.map( + (e) => + ` +${(e.t / 1000).toFixed(1)}s ${e.phase}${e.detail ? ` ${e.detail}` : ""}` + + (e.heap ? ` heap=${mb(e.heap)}` : ""), + ); + const peak = entries.reduce((m, e) => Math.max(m, e.heap), 0); + return [ + `[trace] load timeline (${entries.length} marks, peak heap ${mb(peak)}):`, + ...rows, + ].join("\n"); +} + +/** Test seam / re-mount reset. */ +export function resetTrace(): void { + entries.length = 0; + lastHeap = 0; +}