diff --git a/packages/tool-server/src/tools/profiler/query/profiler-commit-query.ts b/packages/tool-server/src/tools/profiler/query/profiler-commit-query.ts index 1a3cf1133..c9a75f7d5 100644 --- a/packages/tool-server/src/tools/profiler/query/profiler-commit-query.ts +++ b/packages/tool-server/src/tools/profiler/query/profiler-commit-query.ts @@ -10,8 +10,16 @@ import { deriveReason } from "../../../utils/react-profiler/pipeline/utils"; import { readCommitTree } from "../../../utils/react-profiler/debug/dump"; const timeRangeSchema = z.object({ - start: z.coerce.number().describe("Start of range in ms (performance.now clock)"), - end: z.coerce.number().describe("End of range in ms (performance.now clock)"), + start: z.coerce + .number() + .describe( + "Start of range in ms since profiling started — the same clock profiler-commit-query prints" + ), + end: z.coerce + .number() + .describe( + "End of range in ms since profiling started — the same clock profiler-commit-query prints" + ), }); const zodSchema = z.object({ diff --git a/packages/tool-server/src/tools/profiler/query/profiler-cpu-query.ts b/packages/tool-server/src/tools/profiler/query/profiler-cpu-query.ts index 6900bf211..b669f76ab 100644 --- a/packages/tool-server/src/tools/profiler/query/profiler-cpu-query.ts +++ b/packages/tool-server/src/tools/profiler/query/profiler-cpu-query.ts @@ -12,13 +12,22 @@ import { isArgentProfilerFunction, type CpuSampleIndex, } from "../../../utils/react-profiler/pipeline/00-cpu-correlate"; +import type { CpuWindowResult } from "../../../utils/react-profiler/pipeline/00-cpu-correlate"; import type { HermesProfileNode } from "../../../utils/react-profiler/types/input"; import { readCpuProfile, readCommitTree } from "../../../utils/react-profiler/debug/dump"; import { promises as fs } from "fs"; const timeWindowSchema = z.object({ - start: z.coerce.number().describe("Start of window in ms (performance.now clock)"), - end: z.coerce.number().describe("End of window in ms (performance.now clock)"), + start: z.coerce + .number() + .describe( + "Start of window in ms since profiling started — the same clock profiler-commit-query prints" + ), + end: z.coerce + .number() + .describe( + "End of window in ms since profiling started — the same clock profiler-commit-query prints" + ), }); const zodSchema = z.object({ @@ -36,7 +45,9 @@ const zodSchema = z.object({ ), time_window_ms: timeWindowSchema .optional() - .describe("Time window filter for time_window mode (ms, performance.now clock)"), + .describe( + "Time window filter for time_window mode (ms since profiling started — the same clock profiler-commit-query prints)" + ), component_name: z.string().optional().describe("Component name for component_cpu mode"), function_name: z.string().optional().describe("Function name for call_tree mode"), top_n: z.coerce @@ -93,14 +104,85 @@ async function getIndex(sessionPaths: ProfilerSessionPaths): Promise<{ // Slow path: build index from raw CPU profile const cpuProfile = await readCpuProfile(sessionPaths.cpuProfilePath); let commitTree = null; - let firstCommitTs: number | null = null; if (sessionPaths.commitsPath) { const onDisk = await readCommitTree(sessionPaths.commitsPath); commitTree = { commits: onDisk.commits }; - firstCommitTs = onDisk.commits[0]?.timestamp ?? null; } - return { index: buildCpuSampleIndex(cpuProfile, firstCommitTs), commitTree }; + return { index: buildCpuSampleIndex(cpuProfile), commitTree }; +} + +/** + * Explain a window that produced no ranked functions. + * + * "No CPU hotspots found" was indistinguishable from "this commit was cheap", + * which is what made the documented drill-down a dead end (#619). Each way of + * finding nothing has a different meaning and a different next step, so each + * says so — in particular a window that IS covered by samples but contains only + * idle frames, which on real Hermes data is the common case (99% of samples in + * the reported session were idle). + */ +function explainEmptyWindow(res: CpuWindowResult, startMs: number, endMs: number): string { + const range = `${res.sampleRangeMs.start.toFixed(1)}–${res.sampleRangeMs.end.toFixed(1)}ms`; + const window = `${startMs.toFixed(1)}–${endMs.toFixed(1)}ms`; + + if (res.sampleRangeMs.end === 0 && res.samplesInWindow === 0) { + return ( + "_The CPU profile contains no samples. Sampling produced no data for this session — " + + "that is a capture failure, not a measurement of idleness._" + ); + } + + if (endMs < res.sampleRangeMs.start || startMs > res.sampleRangeMs.end) { + return ( + `_No CPU samples exist in ${window} — that is outside the recorded sample range ` + + `(${range}). This is a coverage gap, not a measurement: nothing can be concluded about CPU ` + + `cost here. Sample times are ms since profiling started, the same clock ` + + "`profiler-commit-query` prints._" + ); + } + + if (res.samplesInWindow > 0) { + // Covered, but nothing was running: the honest and useful answer. + return ( + `_${res.samplesInWindow} sample(s) covering ${res.coveredMs.toFixed(1)}ms fell inside ` + + `${window}, and all of them were idle — the JS thread was not executing during this window. ` + + "Native or UI-thread work would not appear here; use `native-profiler-start` for that._" + ); + } + + return ( + `_No CPU samples fell inside ${window} (${(endMs - startMs).toFixed(1)}ms wide), although it ` + + `lies within the recorded range (${range}). The sampler runs roughly every ` + + `${res.medianIntervalMs > 0 ? res.medianIntervalMs.toFixed(1) : "13"}ms, so a window this ` + + "narrow can contain none at all. **Absence of samples is not evidence that this commit was " + + "cheap.** Widen the window, or use `mode=component_cpu`._" + ); +} + +/** Coverage line: what the numbers below are actually a measurement of. */ +function coverageNote(res: CpuWindowResult, startMs: number, endMs: number): string { + const widthMs = endMs - startMs; + const lines = [ + `**Window:** ${startMs.toFixed(1)}ms → ${endMs.toFixed(1)}ms (${widthMs.toFixed(1)}ms)`, + `**Samples:** ${res.samplesInWindow} covering ${res.coveredMs.toFixed(1)}ms` + + (res.idleMs > 0 ? `, of which ${res.idleMs.toFixed(1)}ms idle` : "") + + ` — sampling interval ~${res.medianIntervalMs.toFixed(1)}ms. Self-times sum to sampled` + + " coverage, not to the window width.", + ]; + if (widthMs > 0 && widthMs < 3 * res.medianIntervalMs) { + lines.push( + `> This window is narrower than ~3 sampling intervals, so every figure carries ±1 sample` + + ` (≈${res.medianIntervalMs.toFixed(1)}ms).` + ); + } + if (res.maxIntervalMs > 50 && res.maxIntervalMs > 5 * res.medianIntervalMs) { + lines.push( + `> The sampler stalled for ${res.maxIntervalMs.toFixed(1)}ms inside this window; that whole` + + " gap is attributed to whichever function was caught by the sample that ended it." + ); + } + return lines.join("\n\n"); } function renderTopFunctions( @@ -109,25 +191,22 @@ function renderTopFunctions( startMs?: number, endMs?: number ): string { - const windowStart = startMs ?? index.timestampsMs[0]!; - const windowEnd = endMs ?? index.timestampsMs[index.timestampsMs.length - 1]!; - const hotspots = queryCpuWindow(index, windowStart, windowEnd, topN); + const windowStart = startMs ?? index.intervalStartsMs[0] ?? 0; + const windowEnd = endMs ?? index.timestampsMs[index.timestampsMs.length - 1] ?? 0; + const res = queryCpuWindow(index, windowStart, windowEnd, topN); - if (hotspots.length === 0) return "_No CPU hotspots found in the specified range._"; + if (res.hotspots.length === 0) return explainEmptyWindow(res, windowStart, windowEnd); const header = "| Function | Self (ms) | Total (ms) | Location |"; const sep = "|---|---|---|---|"; - const rows = hotspots.map((hs) => { + const rows = res.hotspots.map((hs) => { const loc = hs.url ? `${shortenUrl(hs.url)}${hs.lineNumber != null ? `:${hs.lineNumber}` : ""}` : "—"; return `| \`${hs.name}\` | ${hs.selfMs} | ${hs.totalMs} | ${loc} |`; }); - const rangeNote = - startMs != null ? `**Window:** ${startMs.toFixed(1)}ms → ${endMs!.toFixed(1)}ms\n\n` : ""; - - return `## CPU Hotspots\n\n${rangeNote}${header}\n${sep}\n${rows.join("\n")}`; + return `## CPU Hotspots\n\n${coverageNote(res, windowStart, windowEnd)}\n\n${header}\n${sep}\n${rows.join("\n")}`; } function renderCallTree( @@ -293,7 +372,7 @@ function renderComponentCpu( >(); for (const window of commitWindows.values()) { - const hotspots = queryCpuWindow(index, window.start, window.end, 50); + const { hotspots } = queryCpuWindow(index, window.start, window.end, 50); for (const hs of hotspots) { const existing = aggregated.get(hs.name); if (existing) { @@ -354,6 +433,10 @@ Requires react-profiler-stop (and ideally react-profiler-analyze) to have been c Modes: - top_functions: Global CPU hotspots ranked by self-time. Optional time_window_ms to filter. - time_window: CPU breakdown for a specific time range (e.g. during a slow commit or hang). + +Self-times are the summed sampling intervals of the samples that landed in the window, so they +measure sampled coverage rather than the window's width and do not change if you widen the query. +Every table states how many samples it covers and how much of that was idle. - call_tree: For a given function_name, show its callees and optionally callers. - component_cpu: For a given component_name, aggregate CPU activity across all its commits. Use when investigating JS CPU hotspots or correlating CPU cost with specific components. diff --git a/packages/tool-server/src/utils/react-profiler/pipeline/00-cpu-correlate.ts b/packages/tool-server/src/utils/react-profiler/pipeline/00-cpu-correlate.ts index 437b21fea..22f27c18b 100644 --- a/packages/tool-server/src/utils/react-profiler/pipeline/00-cpu-correlate.ts +++ b/packages/tool-server/src/utils/react-profiler/pipeline/00-cpu-correlate.ts @@ -24,24 +24,25 @@ export function isArgentProfilerFunction(name: string): boolean { } export interface CpuSampleIndex { - /** Absolute timestamp in ms for each sample (aligned to performance.now clock). */ + /** End of each sample's interval, in ms since profiling started. */ timestampsMs: Float64Array; + /** Start of each sample's interval — `timestampsMs[i] - timeDeltas[i]`. */ + intervalStartsMs: Float64Array; /** Node ID for each sample. */ sampleNodeIds: number[]; /** Map from node ID to its HermesProfileNode. */ nodeMap: Map; /** Total recording duration in ms. */ durationMs: number; + /** Parent lookup, built once — queryCpuWindow runs per commit window. */ + childToParent?: Map; } /** * Build a pre-computed index of CPU sample timestamps for efficient windowed queries. * Aligns CPU profile microsecond clock to React commit performance.now() clock. */ -export function buildCpuSampleIndex( - cpuProfile: HermesCpuProfile, - firstCommitTimestampMs: number | null -): CpuSampleIndex { +export function buildCpuSampleIndex(cpuProfile: HermesCpuProfile): CpuSampleIndex { const { nodes, samples, timeDeltas, startTime, endTime } = cpuProfile; const nodeMap = new Map(); @@ -49,33 +50,39 @@ export function buildCpuSampleIndex( nodeMap.set(node.id, node); } - const cpuStartMs = startTime / 1000; - - // Compute clock offset: if we have commit data, align CPU clock to commit clock. - // Both are monotonic from the same Hermes runtime, but may have different epochs. - // The offset is typically near zero but can drift on some Hermes versions. - let clockOffsetMs = 0; - if (firstCommitTimestampMs !== null && firstCommitTimestampMs > 0) { - // The first commit typically happens shortly after profiling starts. - // If the first commit timestamp is vastly different from cpuStartMs, - // they use different epoch bases and we need to offset. - const diff = firstCommitTimestampMs - cpuStartMs; - // Only apply offset if clocks are clearly on different bases (>1s apart) - if (Math.abs(diff) > 1000) { - clockOffsetMs = diff; - } - } - - // Build absolute timestamps for each sample + // Sample times are expressed as ms since profiling started, which is the same + // frame React commit timestamps use: React DevTools reports every commit as + // `performance.now() - profilingStartTime`, never an absolute clock. + // + // The previous code instead inferred an offset by assuming the first commit + // coincided with the start of the CPU profile, and applied it whenever the two + // numbers differed by more than a second. `startTime` is a since-boot + // monotonic value (~1.28e12 µs on a device up two weeks), so that condition was + // always true and the offset was always the first hot commit's timestamp — + // displacing every sample by it. A session whose first hot commit landed 12.3s + // in had its whole sample set shifted 12.3s later, which is why windows taken + // from commit timestamps found nothing and a late window returned touch work + // from much earlier (#619). const timestampsMs = new Float64Array(samples.length); - let accumulatedUs = startTime; + // Per-sample weights: `timeDeltas[i]` is the time that elapsed *before* sample + // i, so sample i stands for the interval (t[i-1], t[i]]. Keeping the real + // deltas rather than an average matters because the sampler is not + // isochronous — on a real Hermes profile they range from 0 to 36.6ms around a + // 13.1ms median. + const intervalStartsMs = new Float64Array(samples.length); + let accumulatedUs = 0; for (let i = 0; i < samples.length; i++) { - accumulatedUs += timeDeltas[i] ?? 0; - timestampsMs[i] = accumulatedUs / 1000 + clockOffsetMs; + const raw = timeDeltas[i]; + const delta = Number.isFinite(raw) && (raw ?? 0) >= 0 ? (raw as number) : 0; + intervalStartsMs[i] = accumulatedUs / 1000; + accumulatedUs += delta; + timestampsMs[i] = accumulatedUs / 1000; } return { + childToParent: buildChildToParent(nodeMap), timestampsMs, + intervalStartsMs, sampleNodeIds: samples, nodeMap, durationMs: (endTime - startTime) / 1000, @@ -86,90 +93,162 @@ export function buildCpuSampleIndex( * For a given time window [startMs, endMs], collect CPU samples and aggregate * into a ranked list of hot functions. */ +export interface CpuWindowResult { + /** Named hotspots, ranked by self-time. Empty when nothing was executing. */ + hotspots: CpuCommitHotspot[]; + /** Samples whose interval overlapped the window at all. */ + samplesInWindow: number; + /** How much of the window is covered by sampled intervals, in ms. */ + coveredMs: number; + /** Covered time that belonged to idle/runtime frames rather than JS. */ + idleMs: number; + /** Sampled span of the whole profile, for explaining an out-of-range window. */ + sampleRangeMs: { start: number; end: number }; + /** Typical gap between samples — the resolution any answer here is limited to. */ + medianIntervalMs: number; + /** Longest single interval overlapping the window, when the sampler stalled. */ + maxIntervalMs: number; +} + +const IDLE_FRAME_NAMES = new Set(["(idle)", "(program)", "(root)", "[idle]", "[root]"]); + +function isIdleFrame(name: string | undefined): boolean { + return !name || IDLE_FRAME_NAMES.has(name); +} + +/** + * CPU cost inside [startMs, endMs], attributed by integrating each sample's own + * interval over the window. + * + * Each sample stands for the interval (t[i-1], t[i]], and a sample contributes + * only the part of that interval lying inside the window. That is what makes the + * numbers mean something: they are additive across adjoining windows, they never + * exceed the window's own width, and — crucially — they do not change when the + * caller widens the query. + * + * The previous implementation divided the REQUESTED window width by the number + * of samples in it (`avgIntervalMs = (endMs - startMs) / totalSamples`), so + * self-time was the window's duration apportioned by hit share. Asking about a + * range twice as wide doubled every number without the sample data changing at + * all (#619). + */ export function queryCpuWindow( index: CpuSampleIndex, startMs: number, endMs: number, topN: number = 5 -): CpuCommitHotspot[] { - const { timestampsMs, sampleNodeIds, nodeMap } = index; +): CpuWindowResult { + const { timestampsMs, intervalStartsMs, sampleNodeIds, nodeMap } = index; + const n = timestampsMs.length; + const sampleRangeMs = { + start: n > 0 ? intervalStartsMs[0]! : 0, + end: n > 0 ? timestampsMs[n - 1]! : 0, + }; + const empty: CpuWindowResult = { + hotspots: [], + samplesInWindow: 0, + coveredMs: 0, + idleMs: 0, + sampleRangeMs, + medianIntervalMs: 0, + maxIntervalMs: 0, + }; + if (n === 0) return empty; - // Binary search for the first sample >= startMs + // First sample whose interval could reach the window. Intervals are ordered + // and non-overlapping, so a binary search on their end points is enough. let lo = 0; - let hi = timestampsMs.length; + let hi = n; while (lo < hi) { const mid = (lo + hi) >>> 1; if (timestampsMs[mid]! < startMs) lo = mid + 1; else hi = mid; } - // Accumulate self-time hits per node - const selfHits = new Map(); - let totalSamples = 0; - - for (let i = lo; i < timestampsMs.length; i++) { - if (timestampsMs[i]! > endMs) break; - const nodeId = sampleNodeIds[i]!; - selfHits.set(nodeId, (selfHits.get(nodeId) ?? 0) + 1); - totalSamples++; - } + const selfMsByNode = new Map(); + const intervals: number[] = []; + let samplesInWindow = 0; + let coveredMs = 0; + let idleMs = 0; + let maxIntervalMs = 0; - if (totalSamples === 0) return []; + for (let i = lo; i < n; i++) { + const from = intervalStartsMs[i]!; + if (from > endMs) break; + const overlap = Math.min(endMs, timestampsMs[i]!) - Math.max(startMs, from); + if (overlap <= 0) continue; - // Compute interval: average time between samples in this window - const windowDurationMs = endMs - startMs; - const avgIntervalMs = totalSamples > 1 ? windowDurationMs / totalSamples : 1; + samplesInWindow++; + coveredMs += overlap; + intervals.push(timestampsMs[i]! - from); + if (timestampsMs[i]! - from > maxIntervalMs) maxIntervalMs = timestampsMs[i]! - from; - // Build total-time by propagating hits up the call tree - const childToParent = new Map(); - for (const node of nodeMap.values()) { - for (const childId of node.children ?? []) { - childToParent.set(childId, node.id); + const nodeId = sampleNodeIds[i]!; + const node = nodeMap.get(nodeId); + // Idle time is measured but never ranked: a window can be fully covered and + // still contain no JS work, and saying so is the useful answer. + if (isIdleFrame(node?.callFrame.functionName)) { + idleMs += overlap; + continue; } + selfMsByNode.set(nodeId, (selfMsByNode.get(nodeId) ?? 0) + overlap); } - const totalHits = new Map(); - for (const [nodeId, hits] of selfHits) { - totalHits.set(nodeId, (totalHits.get(nodeId) ?? 0) + hits); + if (samplesInWindow === 0) return { ...empty, sampleRangeMs }; + + intervals.sort((a, b) => a - b); + const medianIntervalMs = intervals[Math.floor(intervals.length / 2)] ?? 0; + + // Total time = self time plus everything attributed to descendants. + const childToParent = index.childToParent ?? buildChildToParent(nodeMap); + const totalMsByNode = new Map(); + for (const [nodeId, ms] of selfMsByNode) { + totalMsByNode.set(nodeId, (totalMsByNode.get(nodeId) ?? 0) + ms); let current = nodeId; + const seen = new Set([current]); while (childToParent.has(current)) { const parent = childToParent.get(current)!; - totalHits.set(parent, (totalHits.get(parent) ?? 0) + hits); + if (seen.has(parent)) break; + seen.add(parent); + totalMsByNode.set(parent, (totalMsByNode.get(parent) ?? 0) + ms); current = parent; } } - // Build entries, filter out anonymous/idle nodes const entries: CpuCommitHotspot[] = []; - for (const [nodeId, hits] of selfHits) { + for (const [nodeId, ms] of selfMsByNode) { const node = nodeMap.get(nodeId); if (!node) continue; const name = node.callFrame.functionName; - if ( - !name || - name === "(idle)" || - name === "(program)" || - name === "(root)" || - name === "[idle]" || - name === "[root]" - ) - continue; if (isArgentProfilerFunction(name)) continue; - const selfMs = Math.round(hits * avgIntervalMs * 100) / 100; - const totalMs = Math.round((totalHits.get(nodeId) ?? hits) * avgIntervalMs * 100) / 100; - entries.push({ name, - selfMs, - totalMs, + selfMs: Math.round(ms * 100) / 100, + totalMs: Math.round((totalMsByNode.get(nodeId) ?? ms) * 100) / 100, url: node.callFrame.url || undefined, lineNumber: node.callFrame.lineNumber >= 0 ? node.callFrame.lineNumber : undefined, }); } - entries.sort((a, b) => b.selfMs - a.selfMs); - return entries.slice(0, topN); + + return { + hotspots: entries.slice(0, topN), + samplesInWindow, + coveredMs, + idleMs, + sampleRangeMs, + medianIntervalMs, + maxIntervalMs, + }; +} + +function buildChildToParent(nodeMap: Map): Map { + const childToParent = new Map(); + for (const node of nodeMap.values()) { + for (const childId of node.children ?? []) childToParent.set(childId, node.id); + } + return childToParent; } /** @@ -190,16 +269,25 @@ export function correlateCpuWithCommits< const startMs = summary.timestampMs; const endMs = summary.timestampMs + summary.totalRenderMs; - const hotspots = queryCpuWindow(index, startMs, endMs, topNPerCommit); + const { hotspots } = queryCpuWindow(index, startMs, endMs, topNPerCommit); if (hotspots.length === 0) return summary; return { ...summary, cpuHotspots: hotspots }; }); } -/** Serializable form of CpuSampleIndex for disk persistence. */ +/** + * Serializable form of CpuSampleIndex for disk persistence. + * + * Versioned since #619: a v1 index on disk holds timestamps displaced by the old + * clock heuristic and carries no interval starts, so reusing one would answer + * every query with the numbers the fix exists to remove. Readers reject anything + * that is not v2 and rebuild from the raw profile, which is always kept. + */ interface SerializedCpuSampleIndex { + version: 2; timestampsMs: number[]; + intervalStartsMs: number[]; sampleNodeIds: number[]; nodes: HermesProfileNode[]; durationMs: number; @@ -208,7 +296,9 @@ interface SerializedCpuSampleIndex { /** Convert a CpuSampleIndex to a plain object for JSON serialization. */ export function serializeCpuSampleIndex(index: CpuSampleIndex): SerializedCpuSampleIndex { return { + version: 2, timestampsMs: Array.from(index.timestampsMs), + intervalStartsMs: Array.from(index.intervalStartsMs), sampleNodeIds: index.sampleNodeIds, nodes: [...index.nodeMap.values()], durationMs: index.durationMs, @@ -217,14 +307,22 @@ export function serializeCpuSampleIndex(index: CpuSampleIndex): SerializedCpuSam /** Reconstruct a CpuSampleIndex from its serialized form. */ export function deserializeCpuSampleIndex(raw: SerializedCpuSampleIndex): CpuSampleIndex { + // Validate rather than coerce: `new Float64Array(undefined)` is a zero-length + // array, so a truncated or stale index would otherwise deserialize into a + // profile with no samples and answer every query with "no hotspots" forever. + if (raw?.version !== 2 || !Array.isArray(raw.timestampsMs) || !Array.isArray(raw.nodes)) { + throw new Error("unsupported CPU sample index format"); + } const nodeMap = new Map(); for (const node of raw.nodes) { nodeMap.set(node.id, node); } return { timestampsMs: new Float64Array(raw.timestampsMs), + intervalStartsMs: new Float64Array(raw.intervalStartsMs ?? []), sampleNodeIds: raw.sampleNodeIds, nodeMap, + childToParent: buildChildToParent(nodeMap), durationMs: raw.durationMs, }; } diff --git a/packages/tool-server/src/utils/react-profiler/pipeline/index.ts b/packages/tool-server/src/utils/react-profiler/pipeline/index.ts index 4abcddb03..7331a66bb 100644 --- a/packages/tool-server/src/utils/react-profiler/pipeline/index.ts +++ b/packages/tool-server/src/utils/react-profiler/pipeline/index.ts @@ -31,11 +31,11 @@ export async function runPipeline( input.sessionMeta.unattributedByCommit ); - // Stage 00-cpu-correlate: Map Hermes CPU samples to hot commit time windows - const firstCommitTs = preprocessed.length > 0 ? preprocessed[0]!.timestamp : null; - const cpuSampleIndex = input.flamegraph - ? buildCpuSampleIndex(input.flamegraph, firstCommitTs) - : null; + // Stage 00-cpu-correlate: Map Hermes CPU samples to hot commit time windows. + // Both sides count ms from the start of profiling, so no correlation input is + // needed — the index used to take the first commit's timestamp and align the + // samples to it, which displaced every one of them by that value (#619). + const cpuSampleIndex = input.flamegraph ? buildCpuSampleIndex(input.flamegraph) : null; const hotCommitSummaries = correlateCpuWithCommits(rawHotCommitSummaries, cpuSampleIndex); // Stage 1: Reduce — O(n) over React commits diff --git a/packages/tool-server/test/react-profiler/cpu-correlate.test.ts b/packages/tool-server/test/react-profiler/cpu-correlate.test.ts new file mode 100644 index 000000000..a423b4faa --- /dev/null +++ b/packages/tool-server/test/react-profiler/cpu-correlate.test.ts @@ -0,0 +1,235 @@ +import { describe, it, expect } from "vitest"; +import { + buildCpuSampleIndex, + queryCpuWindow, + serializeCpuSampleIndex, + deserializeCpuSampleIndex, +} from "../../src/utils/react-profiler/pipeline/00-cpu-correlate"; +import type { HermesCpuProfile } from "../../src/utils/react-profiler/types/input"; + +/** + * Issue #619. Two defects made `profiler-cpu-query` unusable for the workflow it + * documents ("read a slow commit, then query its window"): + * + * - self-time was `(endMs - startMs) / sampleCount × hits`, i.e. the REQUESTED + * window's duration apportioned by hit share, so asking about a wider range + * multiplied every number without the sample data changing; + * - sample timestamps were displaced by the first hot commit's timestamp, + * because the code assumed the profile began when that commit happened. + * + * Real Hermes profiles carry a since-boot `startTime` (~1.28e12 µs) and genuinely + * non-uniform `timeDeltas` (0–36.6ms around a 13.1ms median), so the fixtures + * here use a since-boot start time — any reintroduction of absolute timestamps + * fails loudly rather than subtly. + */ + +const SINCE_BOOT_START_US = 1_276_275_277_894; + +const NODES = [ + { id: 1, callFrame: { functionName: "(root)", url: "", lineNumber: -1 }, children: [2, 3] }, + { id: 2, callFrame: { functionName: "work", url: "app.js", lineNumber: 10 }, children: [] }, + { id: 3, callFrame: { functionName: "other", url: "app.js", lineNumber: 20 }, children: [] }, +]; + +function makeProfile(deltasUs: number[], nodeIds: number[]): HermesCpuProfile { + const total = deltasUs.reduce((a, b) => a + b, 0); + return { + nodes: NODES, + samples: nodeIds, + timeDeltas: deltasUs, + startTime: SINCE_BOOT_START_US, + endTime: SINCE_BOOT_START_US + total, + } as unknown as HermesCpuProfile; +} + +/** 1000 samples one millisecond apart, all doing `work`. Truth: 1000ms. */ +function uniformWorkProfile(): HermesCpuProfile { + // timeDeltas[0] = 0 matches every real Hermes profile inspected: `startTime` + // is the first sample's timestamp, so no time elapsed before it. + const deltas = [0, ...new Array(1000).fill(1000)]; + return makeProfile(deltas, new Array(1001).fill(2)); +} + +function selfOf(hotspots: { name: string; selfMs: number }[], name: string): number | undefined { + return hotspots.find((h) => h.name === name)?.selfMs; +} + +describe("queryCpuWindow — self-time describes the samples, not the question", () => { + it("returns the same self-time however wide the requested window is", () => { + // THE headline invariant. Pre-fix these returned 1000 / 2000 / 10000 / + // ~2000000 for identical sample data. + const index = buildCpuSampleIndex(uniformWorkProfile()); + + for (const [start, end] of [ + [0, 1000], + [0, 2000], + [0, 10_000], + [-1_000_000, 1_000_000], + ] as const) { + const res = queryCpuWindow(index, start, end, 5); + expect(selfOf(res.hotspots, "work")).toBe(1000); + } + }); + + it("partitions a window rather than scaling it", () => { + // Alternating work/other, 1ms each. Any sub-window splits 50/50 and the + // window's own width never appears in the output. + const ids = [2]; + const deltas = [0]; + for (let i = 0; i < 1000; i++) { + deltas.push(1000); + ids.push(i % 2 === 0 ? 3 : 2); + } + const index = buildCpuSampleIndex(makeProfile(deltas, ids)); + + const tenth = queryCpuWindow(index, 0, 100, 5); + expect(selfOf(tenth.hotspots, "work")).toBe(50); + expect(selfOf(tenth.hotspots, "other")).toBe(50); + + const whole = queryCpuWindow(index, 0, 1000, 5); + expect(selfOf(whole.hotspots, "work")).toBe(500); + expect(selfOf(whole.hotspots, "other")).toBe(500); + }); + + it("never reports more CPU than the window can physically contain", () => { + // A sample stands for the interval that ENDED at it, so a window cutting + // through one must count only the part inside. Without clipping, a 45ms + // commit could be credited with more than 45ms of work. + const index = buildCpuSampleIndex(makeProfile([0, 20_000, 20_000, 20_000], [2, 2, 2, 2])); + + const res = queryCpuWindow(index, 25, 35, 5); + + expect(res.coveredMs).toBeCloseTo(10, 6); + expect(selfOf(res.hotspots, "work")).toBeCloseTo(10, 2); + }); + + it("is additive: adjoining windows sum to their union", () => { + // Follows from clipping, and is what lets a caller trust a per-commit + // breakdown against a whole-session total. + const index = buildCpuSampleIndex(uniformWorkProfile()); + + const a = selfOf(queryCpuWindow(index, 0, 400, 5).hotspots, "work")!; + const b = selfOf(queryCpuWindow(index, 400, 1000, 5).hotspots, "work")!; + const whole = selfOf(queryCpuWindow(index, 0, 1000, 5).hotspots, "work")!; + + expect(a + b).toBeCloseTo(whole, 6); + }); + + it("weights each sample by its own interval, not by an average", () => { + // `slow` is caught twice across 20ms gaps, `fast` twice across 1ms gaps. + // An average would call them equal; they differ 20×. + const index = buildCpuSampleIndex( + makeProfile([0, 1000, 1000, 20_000, 20_000], [2, 2, 2, 3, 3]) + ); + + const res = queryCpuWindow(index, 0, 100_000, 5); + + expect(selfOf(res.hotspots, "work")).toBeCloseTo(2, 2); + expect(selfOf(res.hotspots, "other")).toBeCloseTo(40, 2); + }); +}); + +describe("buildCpuSampleIndex — sample times are ms since profiling started", () => { + it("rebases a since-boot start time to zero", () => { + // Pre-fix this depended on a commit timestamp and could be displaced by it. + const index = buildCpuSampleIndex(uniformWorkProfile()); + + expect(index.intervalStartsMs[0]).toBe(0); + expect(index.timestampsMs[0]).toBe(0); + expect(index.timestampsMs[index.timestampsMs.length - 1]).toBeCloseTo(1000, 6); + }); + + it("does not depend on commit data at all", () => { + // The displacement bug came from inferring an offset out of the first hot + // commit's timestamp — a value that can be many seconds into a session. The + // index no longer accepts one, so no such inference is possible. + expect(buildCpuSampleIndex.length).toBe(1); + }); + + it("covers the profile's own reported duration, to within one interval", () => { + // Σ timeDeltas is short of endTime - startTime by the final unsampled + // interval — 899µs on the reporter's real 25.1s profile. Exact equality + // would be wrong to assert. + const profile = uniformWorkProfile(); + const index = buildCpuSampleIndex(profile); + const res = queryCpuWindow(index, -1e9, 1e9, 50); + const reportedMs = (profile.endTime - profile.startTime) / 1000; + + expect(res.coveredMs).toBeLessThanOrEqual(reportedMs); + expect(reportedMs - res.coveredMs).toBeLessThanOrEqual(1); + }); + + it("treats missing, negative and non-finite deltas as zero", () => { + const profile = makeProfile([0, 1000, -5000, Number.NaN, 1000], [2, 2, 2, 2, 2]); + const index = buildCpuSampleIndex(profile); + + const res = queryCpuWindow(index, -1e9, 1e9, 5); + + expect(Number.isFinite(res.coveredMs)).toBe(true); + expect(selfOf(res.hotspots, "work")).toBeCloseTo(2, 6); + }); +}); + +describe("queryCpuWindow — the different ways of finding nothing", () => { + it("reports idle coverage rather than pretending the window was empty", () => { + // The dominant real case: on the reported session 99% of samples were + // idle, so a window can be fully covered and still rank nothing. Saying + // "no samples" there would be false, and would read as "this was cheap". + const index = buildCpuSampleIndex(makeProfile([0, 10_000, 10_000], [1, 1, 1])); + + const res = queryCpuWindow(index, 0, 20, 5); + + expect(res.hotspots).toHaveLength(0); + expect(res.samplesInWindow).toBe(2); + expect(res.coveredMs).toBeCloseTo(20, 6); + expect(res.idleMs).toBeCloseTo(20, 6); + }); + + it("distinguishes a window outside the recorded range", () => { + const index = buildCpuSampleIndex(uniformWorkProfile()); + + const res = queryCpuWindow(index, 50_000, 60_000, 5); + + expect(res.samplesInWindow).toBe(0); + expect(res.coveredMs).toBe(0); + expect(res.sampleRangeMs.end).toBeCloseTo(1000, 6); + }); + + it("reports an empty profile as having no sampled range at all", () => { + const res = queryCpuWindow(buildCpuSampleIndex(makeProfile([], [])), 0, 1000, 5); + + expect(res.samplesInWindow).toBe(0); + expect(res.sampleRangeMs).toEqual({ start: 0, end: 0 }); + }); +}); + +describe("serialized index", () => { + it("round-trips to identical query results", () => { + const index = buildCpuSampleIndex(uniformWorkProfile()); + const restored = deserializeCpuSampleIndex( + JSON.parse(JSON.stringify(serializeCpuSampleIndex(index))) + ); + + expect(queryCpuWindow(restored, 0, 500, 5)).toEqual(queryCpuWindow(index, 0, 500, 5)); + }); + + it("rejects a pre-fix index instead of answering from displaced timestamps", () => { + // A v1 file on disk holds timestamps shifted by the old clock heuristic and + // no interval starts. Reusing one would reproduce the bug from cache; the + // caller catches this and rebuilds from the raw profile, which is retained. + const legacy = { + timestampsMs: [1, 2, 3], + sampleNodeIds: [2, 2, 2], + nodes: NODES, + durationMs: 3, + }; + + expect(() => deserializeCpuSampleIndex(legacy as never)).toThrow(/unsupported/i); + }); + + it("rejects a truncated index rather than silently reading zero samples", () => { + // `new Float64Array(undefined)` is empty, so an unvalidated read would turn + // a corrupt file into "this session had no CPU activity", permanently. + expect(() => deserializeCpuSampleIndex({ version: 2 } as never)).toThrow(/unsupported/i); + }); +});