From a57d20751b6e18723dcb708bc6f1b5d834ef8123 Mon Sep 17 00:00:00 2001 From: Local Dev Date: Sat, 3 Oct 2026 13:26:44 +0200 Subject: [PATCH] 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 ] --- scripts/boot-trace/run.mjs | 76 +++++++++++++++++++++++++++++ scripts/boot-trace/trace-main.js | 83 ++++++++++++++++++++++++++++++++ 2 files changed, 159 insertions(+) create mode 100644 scripts/boot-trace/run.mjs create mode 100644 scripts/boot-trace/trace-main.js diff --git a/scripts/boot-trace/run.mjs b/scripts/boot-trace/run.mjs new file mode 100644 index 00000000..976055ec --- /dev/null +++ b/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 ] +// +// --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: /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}`); diff --git a/scripts/boot-trace/trace-main.js b/scripts/boot-trace/trace-main.js new file mode 100644 index 00000000..5ab3a833 --- /dev/null +++ b/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);