#!/usr/bin/env bun /** * Rust build-time profiler. * * Runs `cargo build --timings` with the exact args/rustflags/env the real * build uses (shared with `scripts/build/rust.ts::emitRust`), parses the * HTML report, and prints the critical path, slowest crates, and * low-parallelism windows so you can see where wall time actually goes. * * Usage: * bun run rust:timings # incremental timing (warm cache) * bun run rust:timings --clean # clean-build timing into a scratch target dir * bun run rust:timings --profile=release * bun run rust:timings --report # re-analyze an existing report * bun run rust:timings --self-profile # also emit per-crate rustc -Zself-profile traces * bun run rust:timings --llvm-lines bun_runtime # cargo-llvm-lines for one crate * * The raw `cargo-timing.html` is written under the target dir; open it in a * browser for the Gantt chart. */ import { spawnSync } from "node:child_process"; import { existsSync, readFileSync, rmSync } from "node:fs"; import { join, resolve } from "node:path"; import { resolveConfig } from "./build/config.ts"; import { resolveToolchain } from "./build/configure.ts"; import { getProfile } from "./build/profiles.ts"; import { cargoBuildInvocation, cargoProfile } from "./build/rust.ts"; const repo = resolve(import.meta.dirname, ".."); interface Options { profile: string; clean: boolean; report: string | undefined; selfProfile: boolean; llvmLines: string | undefined; top: number; } function parseArgs(argv: string[]): Options { const opts: Options = { profile: "debug", clean: false, report: undefined, selfProfile: false, llvmLines: undefined, top: 20, }; for (let i = 0; i < argv.length; i++) { const a = argv[i]; if (a === "--clean") opts.clean = true; else if (a === "--self-profile") opts.selfProfile = true; else if (a === "--report") opts.report = argv[++i]; else if (a === "--llvm-lines") opts.llvmLines = argv[++i]; else if (a === "--top") opts.top = parseInt(argv[++i], 10); else if (a.startsWith("--profile=")) opts.profile = a.slice("--profile=".length); else if (a === "--profile") opts.profile = argv[++i]; else if (a === "--help" || a === "-h") { console.log(readFileSync(import.meta.filename, "utf8").match(/\/\*\*[\s\S]*?\*\//)![0]); process.exit(0); } else { console.error(`unknown arg: ${a}`); process.exit(1); } } return opts; } // ─── cargo-timings HTML parsing ──────────────────────────────────────────── interface Section { start: number; end: number; } interface Unit { i: number; name: string; version: string; target: string; start: number; duration: number; /** Units unblocked when this unit's rlib is done. */ unblocked_units: number[]; /** Units unblocked when this unit's rmeta is done (pipelining). */ unblocked_rmeta_units: number[]; sections?: [string, Section][]; } function parseTimingsHtml(path: string): { units: Unit[]; total: number } { const html = readFileSync(path, "utf8"); const m = html.match(/const UNIT_DATA = (\[[\s\S]*?\n?\]);/); if (!m) throw new Error(`no UNIT_DATA in ${path}`); const units: Unit[] = JSON.parse(m[1]); const total = units.length === 0 ? 0 : Math.max(...units.map(u => u.start + u.duration)); return { units, total }; } /** * Time at which this unit unblocks downstream rmeta-dependents. For a * pipelined rlib that's when the frontend finishes (rmeta written), not * when codegen is done. */ function rmetaEnd(u: Unit): number { const fe = u.sections?.find(s => s[0] === "frontend"); return u.start + (fe ? fe[1].end : u.duration); } function section(u: Unit, name: string): number { const s = u.sections?.find(x => x[0] === name); return s ? s[1].end - s[1].start : 0; } /** * Trace the critical path: walk backwards from the last unit, at each step * picking the dependency whose unblock time matches this unit's start. cargo * records `unblocked_units`/`unblocked_rmeta_units` on the *blocker*, so * inverting that map gives "who was I waiting on". */ function criticalPath(units: Unit[]): Unit[] { const waitsOn = new Map(); for (const u of units) { for (const d of u.unblocked_units ?? []) { (waitsOn.get(d) ?? waitsOn.set(d, []).get(d)!).push({ unit: u, at: u.start + u.duration }); } for (const d of u.unblocked_rmeta_units ?? []) { (waitsOn.get(d) ?? waitsOn.set(d, []).get(d)!).push({ unit: u, at: rmetaEnd(u) }); } } let cur = units.reduce((a, b) => (a.start + a.duration > b.start + b.duration ? a : b)); const path = [cur]; while (true) { const blockers = waitsOn.get(cur.i) ?? []; // The immediate cause of `cur` starting is whichever blocker unblocked // latest (≤ cur.start, modulo cargo's scheduler jitter). const next = blockers.filter(b => b.at <= cur.start + 0.5).sort((a, b) => b.at - a.at)[0]; if (!next || path.length > 80) break; path.push(next.unit); cur = next.unit; } return path.reverse(); } /** Wall-clock windows where ≤ `maxActive` units are running for > `minDur` s. */ function serialWindows(units: Unit[], maxActive: number, minDur: number): [number, number, string[]][] { const events: [number, number][] = []; for (const u of units) { events.push([u.start, 1]); events.push([u.start + u.duration, -1]); } events.sort((a, b) => a[0] - b[0]); const out: [number, number, string[]][] = []; let active = 0; // The build starts in a ≤maxActive window (nothing is running yet), so open // the first window at t=0 rather than waiting for a downward crossing. let since: number | null = 0; for (const [t, d] of events) { const was = active; active += d; if (was > maxActive && active <= maxActive) since = t; if (was <= maxActive && active > maxActive && since !== null) { if (t - since > minDur) { const running = [...new Set(units.filter(u => u.start < t && u.start + u.duration > since!).map(u => u.name))]; out.push([since, t, running]); } since = null; } } if (since !== null) { const end = Math.max(...units.map(u => u.start + u.duration)); if (end - since > minDur) { const running = [...new Set(units.filter(u => u.start + u.duration > since!).map(u => u.name))]; out.push([since, end, running]); } } return out; } function fmt(s: number): string { return s.toFixed(1).padStart(5) + "s"; } function report(htmlPath: string, top: number): void { const { units, total } = parseTimingsHtml(htmlPath); const cpuSecs = units.reduce((s, u) => s + u.duration, 0); console.log(`\n${dim("report:")} ${htmlPath}`); if (total < 0.1) { console.log( `${bold("total")} ${fmt(total)} ${dim(`(all ${units.length} units fresh; run with --clean for a cold baseline)`)}\n`, ); return; } console.log( `${bold("total")} ${fmt(total)} wall ${cpuSecs.toFixed(0)} unit-s ` + `${(cpuSecs / total).toFixed(1)}× avg parallelism ${units.length} units\n`, ); console.log(bold(`slowest ${top} units`)); const byDur = [...units].sort((a, b) => b.duration - a.duration).slice(0, top); for (const u of byDur) { const fe = section(u, "frontend"); const cg = section(u, "codegen"); const suffix = u.target && u.target !== "lib" ? ` ${dim(u.target)}` : ""; const split = cg > 0 ? ` ${dim(`fe=${fe.toFixed(1)}s cg=${cg.toFixed(1)}s`)}` : ""; console.log(` ${fmt(u.duration)} ${u.name}${suffix}${split}`); } console.log(`\n${bold("critical path")} ${dim("(last-blocker chain to final unit)")}`); const path = criticalPath(units); let sum = 0; for (const u of path) { const fe = u.sections?.find(s => s[0] === "frontend"); const unblocks = u.unblocked_rmeta_units.length > 0 && fe ? fe[1].end : u.duration; sum += unblocks; console.log( ` ${fmt(u.start)} → ${fmt(u.start + u.duration)} ${u.name.padEnd(24)}` + ` ${dim(`blocks next for ${unblocks.toFixed(1)}s`)}`, ); } console.log(` ${dim(`critical-path sum: ${sum.toFixed(1)}s`)}`); const serial = serialWindows(units, 2, 1.0); if (serial.length > 0) { console.log(`\n${bold("low-parallelism windows")} ${dim("(≤2 units active for >1s)")}`); for (const [s, e, names] of serial) { console.log(` ${fmt(s)} – ${fmt(e)} (${(e - s).toFixed(1)}s) ${names.slice(0, 4).join(", ")}`); } } console.log(); } // ─── terminal helpers ────────────────────────────────────────────────────── const isTTY = process.stdout.isTTY; const bold = (s: string) => (isTTY ? `\x1b[1m${s}\x1b[0m` : s); const dim = (s: string) => (isTTY ? `\x1b[2m${s}\x1b[0m` : s); const cyan = (s: string) => (isTTY ? `\x1b[36m${s}\x1b[0m` : s); // ─── main ────────────────────────────────────────────────────────────────── const opts = parseArgs(process.argv.slice(2)); if (opts.report !== undefined) { report(opts.report, opts.top); process.exit(0); } const toolchain = resolveToolchain(); const cfg = resolveConfig(getProfile(opts.profile), toolchain); if (cfg.cargo === undefined) { console.error("cargo not found (resolveToolchain)"); process.exit(1); } // Codegen + vendored path deps must exist before cargo can load the workspace // manifest. The configure step is a no-op when already done. if (!existsSync(cfg.codegenDir) || !existsSync(join(repo, "vendor/lolhtml/Cargo.toml"))) { console.log(cyan("[setup]") + " bun scripts/build.ts --configure-only --profile=" + opts.profile); const r = spawnSync(process.execPath, ["scripts/build.ts", "--configure-only", `--profile=${opts.profile}`], { stdio: "inherit", cwd: repo, }); if (r.status !== 0) process.exit(1); const nr = spawnSync("ninja", ["-C", cfg.buildDir, "codegen", "clone-lolhtml"], { stdio: "inherit", cwd: repo }); if (nr.error || nr.status !== 0) { console.error(nr.error ? `ninja: ${nr.error.message}` : "ninja codegen/clone-lolhtml failed"); process.exit(1); } } const inv = cargoBuildInvocation(cfg); // `--llvm-lines `: delegate to cargo-llvm-lines with our rustflags. // Forces codegen-units=1 and emits LLVM IR, so it's a separate build; point it // at a scratch target dir so it doesn't poison incremental state. if (opts.llvmLines !== undefined) { const llDir = join(cfg.buildDir, "rust-llvm-lines"); const llArgs = [ "llvm-lines", "-p", opts.llvmLines, "--target", inv.triple, "--target-dir", llDir, "--profile", cargoProfile(cfg).name, ]; console.log(cyan("[llvm-lines]") + ` cargo ${llArgs.join(" ")}`); const r = spawnSync(cfg.cargo, llArgs, { cwd: repo, stdio: "inherit", env: { ...process.env, ...inv.env }, }); process.exit(r.status ?? 1); } // `--clean`: profile a from-scratch build into a throwaway target dir so the // real one keeps its incremental cache. let targetDir = inv.targetDir; let args = inv.args; if (opts.clean) { targetDir = join(cfg.buildDir, "rust-timings"); console.log(cyan("[clean]") + ` removing ${targetDir}`); rmSync(targetDir, { recursive: true, force: true }); args = args.map(a => (a === inv.targetDir ? targetDir : a)); } // `--self-profile`: also write per-crate rustc self-profile traces. Summarize // with `cargo install --locked measureme-cli && summarize /-*`. const env = { ...process.env, ...inv.env }; if (opts.selfProfile) { const spDir = join(targetDir, "self-profile"); rmSync(spDir, { recursive: true, force: true }); const extra = `-Zself-profile=${spDir}\x1f-Zself-profile-events=default`; env.CARGO_ENCODED_RUSTFLAGS = env.CARGO_ENCODED_RUSTFLAGS ? `${env.CARGO_ENCODED_RUSTFLAGS}\x1f${extra}` : extra; console.log(cyan("[self-profile]") + ` rustc traces → ${spDir}`); } console.log(cyan("[cargo]") + ` build ${args.join(" ")} --timings`); const r = spawnSync(cfg.cargo, ["build", ...args, "--timings"], { cwd: repo, stdio: "inherit", env, }); if (r.status !== 0) process.exit(r.status ?? 1); const htmlPath = join(targetDir, "cargo-timings", "cargo-timing.html"); if (!existsSync(htmlPath)) { console.error(`no timing report at ${htmlPath}`); process.exit(1); } report(htmlPath, opts.top);