chore(editor): load timeline with heap tracking, dumped on any fatal
Every production report of the board-load crash so far has been a console dump with no timing and no state, which is why five theories died slowly and none reproduced locally. This records the few facts that would actually discriminate between the ones still standing, and nothing else. Marks: fs:wait, fs:ready, stage:done, open:start, open:settled, presync:settled, ui:ready — on one monotonic clock, each carrying the wasm heap size, with growth called out explicitly. Why these: - The open window is where the crash lives: OpenProjectFiles runs the footprint library preload INLINE on the main thread in the WASM build. Bracketing it lets a crash be placed inside or outside that window instead of inferred from log order. - ui:ready is first paint. The symbolized trap needs !m_gal->IsInitialized(), so a report containing this mark rules that mechanism out and one stopping before it does not. - Heap size at every mark, because growing wasm memory detaches JS-side views, and a stale view writing into a detached buffer is one of the few mechanisms that yields a bad function-table index much later. Already earning its keep: a local Leonardo load grows 256MB -> 443MB during staging, immediately before the open. Locally that is survivable; production should not be guessed at. dump() prints the whole timeline and is wired into all three fatal paths (boot catch, window error, unhandled rejection), so one paste from a user carries the full load shape. Bounded at 200 entries; unit-tested including eviction. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_0137pGo8W7asomGUTRMB7RzM
This commit is contained in:
parent
ad777bcbba
commit
bf0e195ddc
4 changed files with 170 additions and 0 deletions
|
|
@ -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));
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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("");
|
||||
|
|
|
|||
29
web/standalone/src/wasm/load-trace.test.ts
Normal file
29
web/standalone/src/wasm/load-trace.test.ts
Normal file
|
|
@ -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");
|
||||
});
|
||||
});
|
||||
121
web/standalone/src/wasm/load-trace.ts
Normal file
121
web/standalone/src/wasm/load-trace.ts
Normal file
|
|
@ -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;
|
||||
}
|
||||
Loading…
Reference in a new issue