diff --git a/packages/coding-agent/scripts/dev-launch b/packages/coding-agent/scripts/dev-launch index 519ccff0f..c187c6161 100755 --- a/packages/coding-agent/scripts/dev-launch +++ b/packages/coding-agent/scripts/dev-launch @@ -28,6 +28,7 @@ done scripts_dir=$(CDPATH= cd -- "$(dirname -- "$self")" && pwd -P) cli=$scripts_dir/../src/cli.ts preload=$scripts_dir/dev-launch-preload.ts +timing_preload=$scripts_dir/../../utils/src/module-timer.ts launch_dir=${OMP_DEV_LAUNCH_DIR:-${HOME}/.omp/.dev-cwd} mkdir -p "$launch_dir" @@ -35,4 +36,7 @@ mkdir -p "$launch_dir" OMP_LAUNCH_CWD=$PWD export OMP_LAUNCH_CWD cd "$launch_dir" +if [ -n "${PI_TIMING:-}" ]; then + exec bun --preload "$preload" --preload "$timing_preload" "$cli" "$@" +fi exec bun --preload "$preload" "$cli" "$@" diff --git a/packages/utils/CHANGELOG.md b/packages/utils/CHANGELOG.md index 95442dc2a..ae4d73f15 100644 --- a/packages/utils/CHANGELOG.md +++ b/packages/utils/CHANGELOG.md @@ -4,7 +4,7 @@ ### Changed -- `logger.printTimings()` (the `PI_TIMING` startup tree) now surfaces two previously-invisible regions: a `(before instrumentation)` line for the runtime init + static module-graph load that elapses before the first marker (the dominant real-world startup cost, ~350ms — `startTiming()` only begins inside `runRootCommand`), and an `(unattributed self)` line for the root span's own untimed work so the gap between the visible top-level spans and `Total` is no longer silently swallowed. `Total` is now labelled `(since first marker)` to make the window explicit. +- `logger.printTimings()` (the `PI_TIMING` startup tree) now surfaces two previously-invisible regions: a `(before instrumentation)` line for runtime init / uncaptured pre-marker work, and an `(unattributed self)` line for the root span's own untimed work so the gap between visible top-level spans and `Total` is no longer swallowed. `Total` is now labelled `(since first marker)` to make the window explicit. The restored `module-timer.ts` preload can feed module spans into the report: each module records `onLoad` → final top-level marker as `total`, a prepended body marker → final marker as `body/TLA`, and resolved static imports as a bounded dependency tree so the report separates graph wait from actual top-level module work. ## [15.9.2] - 2026-06-05 diff --git a/packages/utils/src/logger.ts b/packages/utils/src/logger.ts index c682bbf8f..1591e1620 100644 --- a/packages/utils/src/logger.ts +++ b/packages/utils/src/logger.ts @@ -15,6 +15,7 @@ import { isPromise } from "node:util/types"; import winston from "winston"; import DailyRotateFile from "winston-daily-rotate-file"; import { getLogsDir } from "./dirs"; +import { drainModuleLoadEvents } from "./timing-buffer"; /** Ensure a logs directory exists; return the resolved path. */ function ensureDir(dir: string): string { @@ -166,12 +167,36 @@ interface Span { children: Span[]; /** Marker / point event without a duration. */ point?: boolean; + /** Absolute module path for module-load spans. */ + modulePath?: string; + /** Own top-level module body / TLA duration for module-load spans. */ + moduleBodyMs?: number; + /** Resolved static imports for module-load spans. */ + moduleImports?: string[]; } - const spanStorage = new AsyncLocalStorage(); let gRootSpan: Span | undefined; let gRecordTimings = false; +export function timingModeIncludes(option: "full" | "x"): boolean { + const value = process.env.PI_TIMING; + if (!value) return false; + if (value === option) return true; + let start = 0; + for (let i = 0; i <= value.length; i++) { + const code = i === value.length ? 44 : value.charCodeAt(i); + const separator = code === 44 || code === 58 || code === 59 || code === 43 || code <= 32; + if (!separator) continue; + if (i > start && value.slice(start, i) === option) return true; + start = i + 1; + } + return false; +} + +export function shouldExitAfterTimings(): boolean { + return timingModeIncludes("x") || timingModeIncludes("full"); +} + /** * Print collected timings as an indented tree. * Each span shows wall duration; parents with children also show "(self)" for unattributed time. @@ -184,13 +209,19 @@ export function printTimings(): void { } gRootSpan.end = performance.now(); + // Splice any preload-captured module-load events into the tree as root + // children and back-extend the root window over them, so the static-import + // phase that ran before the first explicit marker becomes visible (the + // `(modules)` summary below) instead of being lumped into the opaque + // `(before instrumentation)` figure. + spliceModuleLoadBuffer(); const lines: string[] = []; lines.push(""); lines.push("--- Startup timings (hierarchical) ---"); // performance.now() shares the process-start origin, so the root span's start - // is the wall time spent before the first marker — runtime init plus the - // static module-graph evaluation (~the dominant cost). It is otherwise - // invisible because Total only spans startTiming()→printTimings(). + // is the wall time before the first marker — runtime init plus any module + // loads not captured below. With the module-load preload active this shrinks + // to ~runtime init because the load phase is back-folded into the window. if (gRootSpan.start > LOGGED_TIMING_THRESHOLD_MS) { lines.push(`(before instrumentation): ${fmtMs(gRootSpan.start)} [runtime init + module load]`); } @@ -222,8 +253,8 @@ export function printTimings(): void { /** * Begin recording startup timings under a new root span. - * Idempotent: a second call while already recording is a no-op so that side-effect - * starters (see module-timer.ts) and explicit starters (main.ts) can coexist. + * Idempotent: a second call while already recording is a no-op, so an explicit + * starter (main.ts) and any future early starter can coexist. */ export function startTiming(): void { if (gRecordTimings) return; @@ -238,10 +269,16 @@ export function startTiming(): void { /** * Record an externally-measured span as a leaf child of the active span (or root - * when no span is active). Used by the module-load timing plugin to splice load - * events into the tree retroactively. + * when no span is active). Used by {@link spliceModuleLoadBuffer} to fold + * preload-captured module windows into the tree. */ -export function recordModuleLoadSpan(path: string, start: number, durationMs: number): void { +export function recordModuleLoadSpan( + path: string, + start: number, + durationMs: number, + bodyMs?: number, + imports: string[] = [], +): void { if (!gRecordTimings || !gRootSpan) return; const parent = spanStorage.getStore() ?? gRootSpan; const span: Span = { @@ -250,10 +287,32 @@ export function recordModuleLoadSpan(path: string, start: number, durationMs: nu end: start + durationMs, parent, children: [], + modulePath: path, + moduleBodyMs: bodyMs, + moduleImports: imports, }; parent.children.push(span); } +/** + * Drain the preload's module-load buffer (see module-timer.ts) into the tree as + * `load:` children of the root, then back-extend the root window to the earliest + * captured read so the pre-marker load phase is counted in Total rather than + * hidden as `(before instrumentation)`. No-op when nothing was captured (e.g. no + * `--preload`, or a compiled binary where module reads are not interceptable). + */ +function spliceModuleLoadBuffer(): void { + if (!gRootSpan) return; + const events = drainModuleLoadEvents(); + if (events.length === 0) return; + let earliest = gRootSpan.start; + for (const event of events) { + recordModuleLoadSpan(event.path, event.start, event.durationMs, event.bodyMs, event.imports); + if (event.start < earliest) earliest = event.start; + } + gRootSpan.start = earliest; +} + function shortenLoadPath(p: string): string { const cwd = process.cwd(); if (p.startsWith(`${cwd}/`)) return p.slice(cwd.length + 1); @@ -309,6 +368,16 @@ function fmtMs(ms: number): string { const MODULE_LOAD_PREFIX = "load:"; const MODULE_LOAD_VERBOSE_TOP = 10; +const MODULE_TREE_MAX_DEPTH = 5; +const MODULE_TREE_ROOT_TOP = 5; +const MODULE_TREE_CHILD_TOP = 8; + +interface ModuleTimingNode { + span: Span; + children: ModuleTimingNode[]; + parents: number; + body: number; +} function isModuleLoadSpan(span: Span): boolean { return span.op.startsWith(MODULE_LOAD_PREFIX); @@ -343,33 +412,118 @@ function printSpan(span: Span, depth: number, lines: string[]): void { } } -/** Collapse the (typically hundreds of) module-load spans into one summary line. */ +/** Render module-load spans as a dependency-aware DAG/tree. */ function printModuleLoadSummary(loads: Span[], depth: number, lines: string[]): void { const childIndent = " ".repeat(depth); const grandIndent = " ".repeat(depth + 1); let unionStart = Number.POSITIVE_INFINITY; let unionEnd = 0; - let totalSelf = 0; for (const span of loads) { if (span.end === undefined) continue; if (span.start < unionStart) unionStart = span.start; if (span.end > unionEnd) unionEnd = span.end; - totalSelf += span.end - span.start; } const wall = unionEnd > unionStart ? unionEnd - unionStart : 0; - lines.push(`${childIndent}(modules): ${loads.length} loaded, wall ${fmtMs(wall)}, sum ${fmtMs(totalSelf)}`); - const showAll = process.env.PI_TIMING === "full"; - const sorted = [...loads].sort((a, b) => durationOf(b) - durationOf(a)); - const visible = showAll ? sorted : sorted.slice(0, MODULE_LOAD_VERBOSE_TOP); - for (const span of visible) { - const dur = durationOf(span); - if (dur < LOGGED_TIMING_THRESHOLD_MS) break; - const tag = isParallel(span) ? " [parallel]" : ""; - lines.push(`${grandIndent}${span.op}: ${fmtMs(dur)}${tag}`); + const nodes = buildModuleTimingGraph(loads); + lines.push(`${childIndent}(modules): ${loads.length} loaded, wall ${fmtMs(wall)}`); + if (nodes.length === 0) return; + + const showAll = timingModeIncludes("full"); + const byBody = [...nodes].sort(compareModuleNodes); + const topBody = showAll ? byBody : byBody.slice(0, MODULE_LOAD_VERBOSE_TOP); + lines.push(`${grandIndent}top body/TLA:`); + for (const node of topBody) { + if (!showAll && node.body < LOGGED_TIMING_THRESHOLD_MS) break; + lines.push(`${grandIndent} ${node.span.op}: body ${fmtMs(node.body)} (total ${fmtMs(durationOf(node.span))})`); } - if (!showAll && sorted.length > MODULE_LOAD_VERBOSE_TOP) { - lines.push(`${grandIndent}… ${sorted.length - MODULE_LOAD_VERBOSE_TOP} more (PI_TIMING=full to show all)`); + if (!showAll && byBody.length > MODULE_LOAD_VERBOSE_TOP) { + lines.push(`${grandIndent} … ${byBody.length - MODULE_LOAD_VERBOSE_TOP} more (PI_TIMING=full to show all)`); } + + const roots = nodes.filter(node => node.parents === 0); + const treeRoots = (roots.length > 0 ? roots : nodes).sort((a, b) => durationOf(b.span) - durationOf(a.span)); + const visibleRoots = showAll ? treeRoots : treeRoots.slice(0, MODULE_TREE_ROOT_TOP); + lines.push(`${grandIndent}tree:`); + const rendered = new Set(); + for (const node of visibleRoots) { + renderModuleTimingNode(node, depth + 2, lines, rendered, new Set(), showAll); + } + if (!showAll && treeRoots.length > MODULE_TREE_ROOT_TOP) { + lines.push( + `${grandIndent} … ${treeRoots.length - MODULE_TREE_ROOT_TOP} more roots (PI_TIMING=full to show all)`, + ); + } +} + +function buildModuleTimingGraph(loads: Span[]): ModuleTimingNode[] { + const nodes = new Map(); + for (const span of loads) { + if (!span.modulePath || span.end === undefined) continue; + nodes.set(span.modulePath, { span, children: [], parents: 0, body: span.moduleBodyMs ?? 0 }); + } + for (const node of nodes.values()) { + for (const childPath of node.span.moduleImports ?? []) { + const child = nodes.get(childPath); + if (!child || child === node) continue; + node.children.push(child); + child.parents++; + } + } + for (const node of nodes.values()) { + node.children.sort(compareModuleNodes); + } + return [...nodes.values()]; +} + +function compareModuleNodes(a: ModuleTimingNode, b: ModuleTimingNode): number { + const bodyDiff = b.body - a.body; + if (Math.abs(bodyDiff) > 0.001) return bodyDiff; + return durationOf(b.span) - durationOf(a.span); +} + +function renderModuleTimingNode( + node: ModuleTimingNode, + depth: number, + lines: string[], + rendered: Set, + ancestors: Set, + showAll: boolean, +): void { + const path = node.span.modulePath; + if (!path) return; + const indent = " ".repeat(depth); + const total = durationOf(node.span); + if (!showAll && total < LOGGED_TIMING_THRESHOLD_MS && node.children.length === 0) return; + const wait = Math.max(0, total - node.body); + const shared = node.parents > 1 ? " [shared]" : ""; + const timing = + node.body > LOGGED_TIMING_THRESHOLD_MS || node.children.length > 0 + ? ` (body ${fmtMs(node.body)}, wait ${fmtMs(wait)})` + : ""; + const alreadyRendered = rendered.has(path); + const cycle = ancestors.has(path); + const suffix = cycle ? " [cycle]" : alreadyRendered ? " [already shown]" : ""; + lines.push(`${indent}${node.span.op}: ${fmtMs(total)}${timing}${shared}${suffix}`); + if (cycle || alreadyRendered) return; + rendered.add(path); + ancestors.add(path); + if (!showAll && ancestors.size >= MODULE_TREE_MAX_DEPTH) { + if (node.children.length > 0) { + lines.push(`${indent} … ${node.children.length} imports deeper (PI_TIMING=full to show all)`); + } + ancestors.delete(path); + return; + } + const visibleChildren = showAll ? node.children : node.children.slice(0, MODULE_TREE_CHILD_TOP); + for (const child of visibleChildren) { + renderModuleTimingNode(child, depth + 1, lines, rendered, ancestors, showAll); + } + if (!showAll && node.children.length > MODULE_TREE_CHILD_TOP) { + lines.push( + `${indent} … ${node.children.length - MODULE_TREE_CHILD_TOP} more imports (PI_TIMING=full to show all)`, + ); + } + ancestors.delete(path); } /** A span is parallel if it overlaps a sibling that started before it. */ diff --git a/packages/utils/src/module-timer.ts b/packages/utils/src/module-timer.ts new file mode 100644 index 000000000..b0ed91d39 --- /dev/null +++ b/packages/utils/src/module-timer.ts @@ -0,0 +1,148 @@ +/** + * Module-load timing preload. + * + * `bun --preload .../module-timer.ts ` installs Bun plugin hooks (only + * when `PI_TIMING` is set) that record an inclusive module window plus resolved + * static child edges: + * + * onLoad start → appended end marker after the module's top-level body + * + * Events are pushed into a process-global buffer that {@link logger.printTimings} + * drains and renders as a module DAG/tree. Each module row can therefore show + * both total time and `self` time after subtracting child module intervals. + * + * Why a preload (and not a normal import): Bun reads the *entire* statically + * reachable graph before evaluating any module, so hooks installed from inside + * that graph cannot observe its own loading — they only catch later dynamically + * loaded modules. A preload runs first, so it sees the static-import phase that + * dominates startup. + * + * Kept dependency-free on purpose: the sole import is Bun's `plugin`, so this is + * cheap to preload before pi-utils (and winston) exist. The buffer is shared with + * the logger via a registry Symbol so neither side needs to import the other. + * + * **What is measured:** an inclusive per-module window. `onLoad` stamps the + * start before reading source; the returned source has a tiny marker appended at + * the end of the module. That marker runs after Bun parses/transpiles the module + * and after any top-level await in that module completes, so the duration + * includes read + parse/transpile + dependency wait + top-level execution/TLA. + * If a module throws before its final statement, no end marker is recorded. + * + * **Tree shape:** `onResolve` observes importer → specifier edges and resolves + * them with `Bun.resolveSync` without taking over Bun's real resolution. The + * logger renders these edges as a DAG/tree and computes module `self` time by + * subtracting the union of child intervals, avoiding misleading flat inclusive + * totals. + * + * **Coverage limits:** + * - TS/TSX only — intercepting `node_modules` CJS `.js`/`.cjs` and forcing ESM + * breaks their default-export detection, so they are left to Bun's default path. + * - **Dev runs only.** In the compiled `omp` binary every module is pre-bundled + * into bunfs, so `onLoad` never fires; profile with a `bun --preload` dev run. + */ +import { plugin } from "bun"; +import { moduleLoadBuffer } from "./timing-buffer"; + +// Restrict to TS/TSX only. node_modules ships CommonJS `.js`/`.cjs` that Bun +// auto-detects when loaded via its default path; if we intercept and return +// `{ contents, loader: "js" }`, Bun forces ESM and CJS modules fail to load +// (e.g. `Missing 'default' export`). Our own source tree (where the interesting +// timing lives) is uniformly TypeScript, so a TS-only filter is both safe and +// sufficient. +const MODULE_LOADER_FILTER = /\.[mc]?tsx?$/; +const MODULE_COMPLETE_KEY: symbol = Symbol.for("omp.moduleLoadComplete"); +const MODULE_BODY_START_KEY: symbol = Symbol.for("omp.moduleBodyStart"); +const STATIC_IMPORT_PATTERN = + /\b(?:import|export)\s+(?:type\s+)?(?:[^"']*?\s+from\s+)?["']([^"']+)["']|\bimport\s*\(\s*["']([^"']+)["']\s*\)/g; + +type CompleteStore = Record void) | undefined>; + +function bodyStartMarker(path: string): string { + return `;globalThis[Symbol.for("omp.moduleBodyStart")]?.(${JSON.stringify(path)});\n`; +} + +function completionMarker(path: string): string { + return `\n;globalThis[Symbol.for("omp.moduleLoadComplete")]?.(${JSON.stringify(path)});\n`; +} + +function instrumentContents(path: string, contents: string): string { + const start = bodyStartMarker(path); + const end = completionMarker(path); + if (!contents.startsWith("#!")) return `${start}${contents}${end}`; + const newline = contents.indexOf("\n"); + if (newline === -1) return `${contents}\n${start}${end}`; + return `${contents.slice(0, newline + 1)}${start}${contents.slice(newline + 1)}${end}`; +} +function importerDir(importer: string): string { + const slash = importer.lastIndexOf("/"); + if (slash === -1) return "."; + return importer.slice(0, slash); +} + +function childSetFor(importsByPath: Map>, path: string): Set { + let children = importsByPath.get(path); + if (!children) { + children = new Set(); + importsByPath.set(path, children); + } + return children; +} + +function addImportEdges(importsByPath: Map>, importer: string, contents: string): void { + STATIC_IMPORT_PATTERN.lastIndex = 0; + for (const match of contents.matchAll(STATIC_IMPORT_PATTERN)) { + const specifier = match[1] ?? match[2]; + if (!specifier) continue; + try { + const resolved = Bun.resolveSync(specifier, importerDir(importer)); + if (MODULE_LOADER_FILTER.test(resolved) && resolved !== importer) { + childSetFor(importsByPath, importer).add(resolved); + } + } catch { + // Leave Bun's real resolver/runtime to surface any error. This scanner is only an observer. + } + } +} + +if (process.env.PI_TIMING) { + const buffer = moduleLoadBuffer(); + const starts = new Map(); + const bodyStarts = new Map(); + const importsByPath = new Map>(); + const store = globalThis as unknown as CompleteStore; + store[MODULE_BODY_START_KEY] = (path: string): void => { + bodyStarts.set(path, performance.now()); + }; + store[MODULE_COMPLETE_KEY] = (path: string): void => { + const start = starts.get(path); + if (start === undefined) return; + starts.delete(path); + const end = performance.now(); + const bodyStart = bodyStarts.get(path); + bodyStarts.delete(path); + const imports = importsByPath.get(path); + buffer.push({ + path, + start, + durationMs: end - start, + bodyMs: bodyStart === undefined ? undefined : end - bodyStart, + imports: imports ? [...imports] : [], + }); + }; + + plugin({ + name: "pi-module-load-timer", + setup(build) { + build.onLoad({ filter: MODULE_LOADER_FILTER }, async args => { + starts.set(args.path, performance.now()); + childSetFor(importsByPath, args.path); + const contents = await Bun.file(args.path).text(); + addImportEdges(importsByPath, args.path, contents); + return { + contents: instrumentContents(args.path, contents), + loader: args.path.endsWith(".tsx") ? "tsx" : "ts", + }; + }); + }, + }); +} diff --git a/packages/utils/src/timing-buffer.ts b/packages/utils/src/timing-buffer.ts new file mode 100644 index 000000000..4208f9298 --- /dev/null +++ b/packages/utils/src/timing-buffer.ts @@ -0,0 +1,47 @@ +/** + * Shared contract between the {@link module-timer} preload and {@link logger}'s + * timing tree. Kept in its own dependency-free module so the preload can import + * it without pulling in winston (via logger) and the logger can drain the buffer + * without importing the Bun-plugin preload. + */ + +export interface ModuleLoadEvent { + /** Absolute or Bun-resolved module path. */ + path: string; + /** `performance.now()` timestamp captured at Bun `onLoad` entry. */ + start: number; + /** Inclusive module window: `onLoad` entry → appended final marker. */ + durationMs: number; + /** Own top-level body / TLA time: prepended body marker → appended final marker. */ + bodyMs?: number; + /** Resolved static children imported by this module. */ + imports: string[]; +} + +/** + * Registry-global key under which the preload accumulates module-load events. + * `Symbol.for` so both modules resolve the same symbol independently. + */ +const KEY: symbol = Symbol.for("omp.moduleLoadBuffer"); + +type Store = Record; + +/** The append-only buffer the preload pushes into (created on first access). */ +export function moduleLoadBuffer(): ModuleLoadEvent[] { + const store = globalThis as unknown as Store; + let buffer = store[KEY]; + if (!buffer) { + buffer = []; + store[KEY] = buffer; + } + return buffer; +} + +/** Drain and return all buffered events, leaving the buffer empty. */ +export function drainModuleLoadEvents(): ModuleLoadEvent[] { + const store = globalThis as unknown as Store; + const buffer = store[KEY]; + if (!buffer || buffer.length === 0) return []; + store[KEY] = []; + return buffer; +}