perf(tooling): break streaming time down by timeline trace event

A CPU sampling profile attributes native work to `(program)`, which during
streaming accounted for three quarters of all busy time and said nothing about
where it went. The timeline trace names that work, so the streaming report now
lists total and maximum time per trace event, skipping container events whose
duration already includes the work below them.
This commit is contained in:
Bohdan Triapitsyn
2026-08-03 16:17:51 +03:00
parent 107fe45248
commit fe9e2471cb
2 changed files with 38 additions and 1 deletions
+30
View File
@@ -37,6 +37,36 @@ export const percentile = (values, fraction) => {
return round(sorted[rank]) 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 * Long tasks block input and animation, so a streaming capture is judged by
* its task-duration distribution rather than by an average frame rate. * its task-duration distribution rather than by an average frame rate.
+8 -1
View File
@@ -29,7 +29,7 @@ import process from "node:process"
import { CdpClient, createPageTarget, evaluateValue, launchChrome, reservePort, resolveChrome, wait } from "./perf/cdp.mjs" import { CdpClient, createPageTarget, evaluateValue, launchChrome, reservePort, resolveChrome, wait } from "./perf/cdp.mjs"
import { buildIdleProbeSource, IDLE_PROBE_GLOBAL } from "./perf/idle-probe.mjs" import { buildIdleProbeSource, IDLE_PROBE_GLOBAL } from "./perf/idle-probe.mjs"
import { summarizeCpuProfile } from "./perf/cpu-profile.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 repoRoot = resolve(dirname(fileURLToPath(import.meta.url)), "..")
const cliPath = join(repoRoot, "packages/web/bin/cli.js") 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(` ${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 ?? [] const streamEntries = summary.streamPerformance?.entries ?? []
if (streamEntries.length > 0) { if (streamEntries.length > 0) {
console.log("\nApplication stream counters (total ms / count):") console.log("\nApplication stream counters (total ms / count):")
@@ -435,6 +440,7 @@ const main = async () => {
const renderedCharacterGrowth = renderedAfter.characters - renderedBefore.characters const renderedCharacterGrowth = renderedAfter.characters - renderedBefore.characters
const tasks = summarizeLongTasks(traceEvents) const tasks = summarizeLongTasks(traceEvents)
const traceBreakdown = summarizeTraceEvents(traceEvents)
const delta = (name) => Number(after[name] ?? 0) - Number(before[name] ?? 0) const delta = (name) => Number(after[name] ?? 0) - Number(before[name] ?? 0)
const perSecond = (name) => round(delta(name) / elapsedSeconds) const perSecond = (name) => round(delta(name) / elapsedSeconds)
const heapSamples = samples.map((sample) => sample.jsHeapUsedMb) const heapSamples = samples.map((sample) => sample.jsHeapUsedMb)
@@ -488,6 +494,7 @@ const main = async () => {
}, },
frameLiveness, frameLiveness,
cpuProfile: summarizeCpuProfile(profile), cpuProfile: summarizeCpuProfile(profile),
traceBreakdown,
streamPerformance, streamPerformance,
syncCounters, syncCounters,
scheduledWork: probe, scheduledWork: probe,