diff --git a/scripts/perf/metrics.mjs b/scripts/perf/metrics.mjs index adcf72d2..1b50b64e 100644 --- a/scripts/perf/metrics.mjs +++ b/scripts/perf/metrics.mjs @@ -37,6 +37,36 @@ export const percentile = (values, fraction) => { return round(sorted[rank]) } +// `RunTask` and `RunMicrotasks` are containers: their duration already +// includes the work below them, so counting them would double-count. +const CONTAINER_TRACE_EVENTS = new Set(["RunTask", "RunMicrotasks", "ProfileChunk", "Profile"]) + +/** + * Breaks recorded time down by trace event. + * + * A CPU sampling profile attributes native work to `(program)`, which hides + * whether time went to HTML parsing, style recalculation, layout, or paint. + * The timeline trace names that work explicitly, so this is what turns "76% of + * busy time is native" into an actionable list. + */ +export const summarizeTraceEvents = (traceEvents, topCount = 15) => { + const totals = new Map() + for (const event of traceEvents) { + if (event.ph !== "X" || !(Number(event.dur) > 0)) continue + if (CONTAINER_TRACE_EVENTS.has(event.name)) continue + const entry = totals.get(event.name) ?? { name: event.name, count: 0, totalMs: 0, maxMs: 0 } + const durationMs = Number(event.dur) / 1000 + entry.count += 1 + entry.totalMs += durationMs + if (durationMs > entry.maxMs) entry.maxMs = durationMs + totals.set(event.name, entry) + } + return [...totals.values()] + .sort((left, right) => right.totalMs - left.totalMs) + .slice(0, topCount) + .map((entry) => ({ ...entry, totalMs: round(entry.totalMs), maxMs: round(entry.maxMs) })) +} + /** * Long tasks block input and animation, so a streaming capture is judged by * its task-duration distribution rather than by an average frame rate. diff --git a/scripts/profile-session.mjs b/scripts/profile-session.mjs index f7c0e11e..e9483c40 100644 --- a/scripts/profile-session.mjs +++ b/scripts/profile-session.mjs @@ -29,7 +29,7 @@ import process from "node:process" import { CdpClient, createPageTarget, evaluateValue, launchChrome, reservePort, resolveChrome, wait } from "./perf/cdp.mjs" import { buildIdleProbeSource, IDLE_PROBE_GLOBAL } from "./perf/idle-probe.mjs" import { summarizeCpuProfile } from "./perf/cpu-profile.mjs" -import { growthPerSecond, metricMap, round, summarizeLongTasks } from "./perf/metrics.mjs" +import { growthPerSecond, metricMap, round, summarizeLongTasks, summarizeTraceEvents } from "./perf/metrics.mjs" const repoRoot = resolve(dirname(fileURLToPath(import.meta.url)), "..") const cliPath = join(repoRoot, "packages/web/bin/cli.js") @@ -224,6 +224,11 @@ const printReport = (summary, baseline) => { console.log(` ${String(entry.selfMs).padStart(9)} ms ${String(entry.percentOfBusy).padStart(5)}% ${entry.function}`) } + console.log("\nWhere recorded time went (timeline trace):") + for (const entry of summary.traceBreakdown?.slice(0, 14) ?? []) { + console.log(` ${String(entry.totalMs).padStart(9)} ms ${String(entry.count).padStart(6)}x max ${String(entry.maxMs).padStart(7)} ms ${entry.name}`) + } + const streamEntries = summary.streamPerformance?.entries ?? [] if (streamEntries.length > 0) { console.log("\nApplication stream counters (total ms / count):") @@ -435,6 +440,7 @@ const main = async () => { const renderedCharacterGrowth = renderedAfter.characters - renderedBefore.characters const tasks = summarizeLongTasks(traceEvents) + const traceBreakdown = summarizeTraceEvents(traceEvents) const delta = (name) => Number(after[name] ?? 0) - Number(before[name] ?? 0) const perSecond = (name) => round(delta(name) / elapsedSeconds) const heapSamples = samples.map((sample) => sample.jsHeapUsedMb) @@ -488,6 +494,7 @@ const main = async () => { }, frameLiveness, cpuProfile: summarizeCpuProfile(profile), + traceBreakdown, streamPerformance, syncCounters, scheduledWork: probe,