Theseus: boot tracer under scripts/boot-trace

Measures dev-tree launches against a throwaway profile, without changing
main.js: time to app ready, toolbar and first page; main-thread blocks; add-on
activation; overlay pages loaded; main-process fetches; process count and
private memory at 15 s. One row per run, so a startup change can be compared
with the numbers before it.

  node scripts/boot-trace/run.mjs [--runs 3] [--seconds 25] [--fresh] [--profile <dir>]

scripts/boot-trace/run.mjs

@@ -0,0 +1,76 @@
+// Measure Theseus launches. Runs N traced starts of the dev tree against a
+// throwaway profile and prints one row per run, so a change can be checked
+// against the previous numbers.
+//
+//   node scripts/boot-trace/run.mjs [--runs 3] [--seconds 25] [--fresh] [--profile <dir>]
+//
+//   --fresh     start from an empty profile (the first run then also measures
+//               first-launch work: seeding the bundled add-ons, filter builds)
+//   --profile   profile dir to use (default: <tmp>/theseus-boot-trace)
+//
+// The profile never touches the real one (THESEUS_USER_DATA), and update
+// checks are off (THESEUS_NO_UPDATE_CHECK) so a dev tree that is older than
+// the live release can't offer — let alone install — an update.
+import { spawn } from "node:child_process";
+import { mkdirSync, rmSync, readFileSync, openSync, closeSync, existsSync } from "node:fs";
+import { tmpdir } from "node:os";
+import path from "node:path";
+import { fileURLToPath } from "node:url";
+
+const here = path.dirname(fileURLToPath(import.meta.url));
+const APP = path.resolve(here, "..", "..");
+const args = process.argv.slice(2);
+const opt = (k, d) => { const i = args.indexOf(k); return i >= 0 && args[i + 1] ? args[i + 1] : d; };
+const RUNS = Number(opt("--runs", 3));
+const SECONDS = Number(opt("--seconds", 25));
+const PROFILE = path.resolve(opt("--profile", path.join(tmpdir(), "theseus-boot-trace")));
+const ELECTRON = path.join(APP, "node_modules", "electron", "dist", process.platform === "win32" ? "electron.exe" : "electron");
+if (!existsSync(ELECTRON)) { console.error("electron binary not found:", ELECTRON); process.exit(1); }
+if (args.includes("--fresh")) rmSync(PROFILE, { recursive: true, force: true });
+mkdirSync(PROFILE, { recursive: true });
+const traceDir = path.join(PROFILE, "..", path.basename(PROFILE) + "-traces");
+mkdirSync(traceDir, { recursive: true });
+
+function runOnce(i) {
+  const out = path.join(traceDir, `run${i}.json`);
+  const log = openSync(path.join(traceDir, `run${i}.log`), "w");
+  return new Promise((resolve) => {
+    // Output to a file, not inherited: an Electron child holding the parent's
+    // pipes keeps a shell pipeline open after it exits.
+    const p = spawn(ELECTRON, [path.join(here, "trace-main.js")], {
+      cwd: APP, stdio: ["ignore", log, log], windowsHide: false,
+      env: { ...process.env, THESEUS_USER_DATA: PROFILE, THESEUS_NO_UPDATE_CHECK: "1", BOOT_TRACE_OUT: out, BOOT_TRACE_MS: String(SECONDS * 1000) },
+    });
+    const kill = setTimeout(() => { try { p.kill(); } catch {} }, SECONDS * 1000 + 30000);
+    p.on("exit", () => { clearTimeout(kill); closeSync(log); resolve(out); });
+  });
+}
+
+function summarise(file) {
+  const ev = JSON.parse(readFileSync(file, "utf8"));
+  const at = (re) => (ev.find((e) => re.test(e.label)) || {}).t ?? null;
+  const metric = (label) => ev.find((e) => e.kind === "metrics" && e.label === label) || {};
+  return {
+    ready: at(/^ready$/),
+    toolbar: at(/loaded #\d+ file:chrome\.html/),
+    firstPage: at(/loaded #\d+ file:home\.html/),
+    blocks6s: ev.filter((e) => e.kind === "block" && e.endedAt < 6000).reduce((a, e) => a + e.ms, 0),
+    addons: ev.filter((e) => e.kind === "addon").reduce((a, e) => a + e.ms, 0),
+    overlaysLoaded: ev.filter((e) => e.kind === "wc" && /loaded #\d+ file:(popover|engine-picker|downloads|address-picker|pw-fill|link-status|approval|js-dialog)\.html/.test(e.label)).length,
+    fetches6s: ev.filter((e) => e.kind === "fetch" && e.start < 6000).length,
+    proc15: metric("15s").processes ?? null,
+    mem15: metric("15s").privateMB ?? null,
+  };
+}
+
+const rows = [];
+for (let i = 1; i <= RUNS; i++) {
+  process.stdout.write(`run ${i}/${RUNS}… `);
+  const file = await runOnce(i);
+  if (!existsSync(file)) { console.log("no trace written (see " + file.replace(/json$/, "log") + ")"); continue; }
+  const r = summarise(file); rows.push(r); console.log("done");
+}
+const cols = [["ready", "ready"], ["toolbar", "toolbar"], ["firstPage", "1st page"], ["blocks6s", "blocked<6s"], ["addons", "addons"], ["overlaysLoaded", "overlays"], ["fetches6s", "fetch<6s"], ["proc15", "procs@15s"], ["mem15", "MB@15s"]];
+console.log("\n" + ["run", ...cols.map((c) => c[1])].map((h) => h.padStart(11)).join(""));
+rows.forEach((r, i) => console.log([String(i + 1), ...cols.map(([k]) => String(r[k] ?? "—"))].map((v) => v.padStart(11)).join("")));
+console.log(`\ntimes in ms since process start; MB = private memory of all Theseus processes. Traces: ${traceDir}`);

scripts/boot-trace/trace-main.js

@@ -0,0 +1,83 @@
+// Boot tracer — Electron entry that wraps main.js without changing it and
+// records what happens during the first BOOT_TRACE_MS of a launch. Started by
+// run.mjs (see there); writes BOOT_TRACE_OUT as JSON.
+//
+// Records: slow require()s, main-thread (event-loop) blocks, add-on
+// activation times, every main-process fetch(), WebContents creation and
+// first loads, selected log lines, and process count / private memory at
+// 5 s, 15 s and the end.
+"use strict";
+const T0 = performance.timeOrigin;
+const now = () => Math.round(performance.now());
+const fs = require("fs"), path = require("path"), Module = require("module");
+const APP = path.resolve(__dirname, "..", "..");
+const OUT = process.env.BOOT_TRACE_OUT;
+const DURATION = Number(process.env.BOOT_TRACE_MS || 40000);
+if (!OUT || !process.env.THESEUS_USER_DATA) { console.error("run via scripts/boot-trace/run.mjs"); process.exit(2); }
+const ev = [];
+const mark = (kind, label, extra) => ev.push({ t: now(), kind, label, ...extra });
+
+// Slow require()s, top-level only (self time including children).
+const origLoad = Module._load; let depth = 0;
+Module._load = function (request) {
+  const s = performance.now(); depth++;
+  try { return origLoad.apply(this, arguments); }
+  finally { depth--; const d = performance.now() - s; if (d > 15 && depth <= 1) mark("require", request, { ms: Math.round(d) }); }
+};
+
+// Event-loop blocks > 60 ms, sampled every 20 ms.
+let last = performance.now();
+setInterval(() => { const n = performance.now(); const block = n - last - 20; if (block > 60) mark("block", "event loop blocked", { ms: Math.round(block), endedAt: Math.round(n) }); last = n; }, 20).unref();
+
+// Main-process fetch() traffic.
+const origFetch = globalThis.fetch;
+globalThis.fetch = async function (input, init) {
+  const url = String((input && input.url) || input); const s = now();
+  try { const r = await origFetch(input, init); mark("fetch", url.slice(0, 110), { start: s, ms: now() - s, status: r.status }); return r; }
+  catch (e) { mark("fetch", url.slice(0, 110), { start: s, ms: now() - s, error: e?.cause?.code || e?.name }); throw e; }
+};
+
+for (const k of ["log", "warn", "error"]) {
+  const o = console[k].bind(console);
+  console[k] = (...a) => { const line = a.map(String).join(" "); if (/\[(bns|addons|update|tor)\]|activated|snapshot/i.test(line)) mark("log", line.slice(0, 160)); o(...a); };
+}
+
+const { app } = require("electron");
+app.setPath("userData", process.env.THESEUS_USER_DATA);
+// With a script as the entry, package.json isn't read: keep the real name and
+// version so profile paths and version checks behave as in a normal run.
+const pkg = JSON.parse(fs.readFileSync(path.join(APP, "package.json"), "utf8"));
+app.setName(pkg.productName || pkg.name);
+app.getVersion = () => pkg.version;
+
+app.on("ready", () => mark("app", "ready"));
+app.on("web-contents-created", (_e, wc) => {
+  const id = wc.id; mark("wc", "created #" + id);
+  wc.once("did-finish-load", () => { let u = ""; try { u = wc.getURL(); } catch {} mark("wc", `loaded #${id} ${u.replace(/^file:\/\/\/.*\//, "file:").slice(0, 90)}`); });
+});
+const metrics = (label) => {
+  try {
+    const m = app.getAppMetrics();
+    const kb = m.reduce((a, p) => a + (p.memory?.privateBytes || 0), 0);
+    mark("metrics", label, { processes: m.length, renderers: m.filter((p) => p.type === "Tab").length, privateMB: Math.round(kb / 1024) });
+  } catch {}
+};
+setTimeout(() => metrics("5s"), 5000);
+setTimeout(() => metrics("15s"), 15000);
+
+const AddonHostProto = require(path.join(APP, "addons-host.js")).AddonHost.prototype, origAct = AddonHostProto._activateOne;
+AddonHostProto._activateOne = function (manifest) {
+  const s = performance.now();
+  try { return origAct.apply(this, arguments); }
+  finally { mark("addon", manifest.id, { ms: Math.round(performance.now() - s) }); }
+};
+
+mark("trace", "main.js require start");
+require(path.join(APP, "main.js"));
+mark("trace", "main.js require done");
+
+setTimeout(() => {
+  metrics("end");
+  fs.writeFileSync(OUT, JSON.stringify(ev.sort((a, b) => a.t - b.t), null, 1));
+  app.exit(0);
+}, DURATION);