Skip to content

fix(profiler): measure CPU windows from the samples, not from the question - #685

Open
filip131311 wants to merge 1 commit into
mainfrom
filip/cpu-window-interval
Open

fix(profiler): measure CPU windows from the samples, not from the question#685
filip131311 wants to merge 1 commit into
mainfrom
filip/cpu-window-interval

Conversation

@filip131311

Copy link
Copy Markdown
Collaborator

Fixes #619.

Reproduced, then verified, on the reporter's own session

Their artifacts were still on disk (react-profiler-20260731-150333: 1873 samples, 25114.0 ms, one hot commit at t=12307.5 ms), so every number below is from the session in the issue rather than a fixture.

Two defects

Self-time was the question, not the answer. avgIntervalMs = (endMs - startMs) / totalSamples, so self-time = requested window width × share of hits. Same samples, three windows, three answers:

[0, 25114]  → createAnimatedNode 29.12   [0, 50000] → 2×   [0, 100000] → 4×

Samples were displaced by the first hot commit. clockOffsetMs = firstCommitTimestampMs - cpuStartMs, applied when |diff| > 1000. startTime is a since-boot monotonic value (1_276_275_277_894 µs ≈ 14.8 days), so that guard is always satisfied and the offset was always the first hot commit — 12307.5 ms here, which is exactly how far every sample moved.

Together they predict the reported 2×: displaced samples covered 25114.0 − 12307.5 = 12806.5 ms of a full-range query, so 25114.0 / 12806.5 = 1.961. The reporter measured completeRoot 52.87 vs 26.82 — a ratio of 1.971.

The fix

Clock: subtract, don't infer. React DevTools emits every commit as performance.now() - profilingStartTime, so commit timestamps are already ms-since-profiling-start. Sample times are now the same thing — (accumulatedUs - startTime) / 1000 — and buildCpuSampleIndex no longer accepts a commit timestamp at all, so the inference cannot come back.

Weights: each sample's own interval, clipped to the window. A sample stands for the interval that ended at it, so a window cutting through one counts only the part inside. That gives four properties the old formula had none of: independent of the requested bounds, additive across adjoining windows, bounded by the window (a 45 ms commit can no longer be credited with more than 45 ms), and summing to the profile's own duration.

Per-sample rather than averaged because the sampler is not isochronous — measured on the real profile, deltas run 0–36.6 ms around a 13.1 ms median. An average smears a stall evenly across every function in the window.

(A note on my own reasoning: I initially justified per-sample weighting with a synthetic fixture showing a 20× cost difference reported as a tie. That demonstrates the mechanism but overstates it — real Hermes sampling is roughly periodic, so the effect is a redistribution, not a rank inversion. The durable arguments are window-invariance and additivity.)

Finding nothing now says which kind of nothing. Outside the recorded range; inside it but unreached by any sample; a profile with no samples at all; and — the case that actually dominates — a window fully covered by samples that were all idle. 99% of samples in this session were idle, so a window can be completely covered and still rank nothing. Reporting that as "no CPU hotspots found" is what made a miss read as "this commit was cheap".

Every table now states what it measured: sample count, covered ms, idle ms, and the sampling interval — plus a warning when the window is narrower than ~3 intervals, or when a sampler stall lands wholly on one function.

The on-disk index is versioned. A file written before this change holds displaced timestamps and no interval starts; reusing one would answer from cache with exactly the numbers being removed. Readers reject it and rebuild from the raw profile, which is always retained. The same validation stops a truncated index deserializing into an empty profile that would answer "no hotspots" forever (new Float64Array(undefined) is silently empty).

The reporter's five queries, after

12300–12345  →  recordProfilingDurations 15.05ms, completeRoot 4.86ms   (was: nothing)
10000–15000  →  371 samples, real hotspots                              (was: nothing)
0–1000       →  71 samples, 1000.0ms covered, ALL IDLE — stated         (was: nothing)
24000–25114  →  85 samples, 1113.1ms covered, ALL IDLE — stated         (was: touch events from t≈12s)
0–25114      →  1872 samples, 25113.1ms covered, self-times correct     (was: 2×)

Two remain empty — correctly, and they now say why.

Tests

15 new cases in test/react-profiler/cpu-correlate.test.ts, all pure. There was no test at all for either file before, which is why this survived. Covered: window invariance across four widths, sub-window partitioning, boundedness by window width, additivity, per-interval weighting, rebasing a since-boot start time, coverage within one interval of the profile's reported duration, defensive deltas (missing/negative/NaN), the four empty-window shapes, and index round-trip plus v1/truncated rejection.

Mutation-verified: restoring the window-derived average fails 8 of 15.

Full tool-server suite green — 3101 passed / 298 files.

Behaviour change — worth calling out in the release notes

Numbers move in both directions. Windowed self-times fall by the ratio of the window to its sampled coverage; previously-empty windows now return data; and per-commit CPU blocks in every analyze report change wholesale, because they were reading a region of the profile the commit never occupied. Any before/after optimisation baseline recorded with the current build must be re-measured.

Not in scope

  • time-align.ts:50-58 has the same family of bugbuildReactAnchor sets monotonicStartMs from the since-boot cpuProfileStartTimeUs while commit timestamps are profile-relative, so commits are projected ~device-uptime into the past and no hang can ever correlate with a commit. It is invisible to the existing test because that test passes cpuProfilePath: null. Filing separately: fixing it makes buildReactAnchor's second parameter and a readCpuProfile call dead, so it is not the one-liner it looks like.
  • queryCpuWindow emits one row per node id, so a function reached via several call paths is listed repeatedly with its cost split. Real, and moves numbers again — separate issue.
  • component_cpu applies its top-50 cut per window before aggregating, truncating the long tail.
  • renderCallTree and react-profiler-cpu-summary still derive self-time their own ways; unifying them onto these weights is a follow-up.
  • Hermes ignores the requested sample_interval_us (100 µs requested, ~13.4 ms observed). Not argent's bug, but it is why no fix may derive an interval from the requested config.

…stion

Two defects made the documented drill-down — read a slow commit from
react-profiler-analyze, then query its window — return nothing.

Self-time was `(endMs - startMs) / sampleCount × hits`: the REQUESTED window's
duration apportioned by hit share. Asking about a wider range multiplied every
number while the sample data was identical. Verified against the reporter's own
session: the same samples queried over 0-25114, 0-50000 and 0-100000 gave three
different answers.

Sample timestamps were displaced by the first hot commit's timestamp. The code
inferred a clock offset by assuming the profile began when that commit happened,
applying it whenever the two numbers differed by more than a second. Since
`startTime` is a since-boot monotonic value (~1.28e12 microseconds on a device up
two weeks), that condition was always true, so the offset was always the first
hot commit — 12.3 seconds on the reported session, and that is how far every
sample moved. Windows taken from commit timestamps landed where nothing was, and
a late window returned touch work from much earlier. Together the two bugs
predict the reported 2x exactly: displaced samples covered 12806 of the 25114ms
queried, and 25114/12806 = 1.96.

Both are gone. Sample times are now ms since profiling started, which is already
the frame React reports commits in — DevTools emits every commit as
`performance.now() - profilingStartTime`, never an absolute clock — so the
mapping is a subtraction rather than an inference. And each sample is weighted by
its own interval, clipped to the window it is being counted in.

Clipping matters as much as the weights. A sample stands for the interval that
ended at it, so a window cutting through one must count only the part inside;
otherwise a 45ms commit can be credited with more than 45ms of CPU. The result is
additive across adjoining windows, bounded by the window, and unchanged when the
caller widens the query.

Per-sample intervals rather than an average because the sampler is not
isochronous: on a real profile the deltas run 0-36.6ms around a 13.1ms median.
An average smears a stall evenly across every function in the window.

Finding nothing now says which kind of nothing. A window outside the recorded
range, a window inside it that no sample reached, a profile with no samples, and
— the common case on real data, where 99% of samples were idle — a window fully
covered by samples that were all idle. That last one is why "no hotspots" read as
"this commit was cheap": on the reported session two of the five queries stay
empty after this fix, and both are honest answers that now explain themselves.

Every table also states what it measured: how many samples, how much of the
window they cover, how much of that was idle, and the sampling interval. A window
narrower than three intervals says so, and a sampler stall that lands wholly on
one function says that too.

The serialized index is versioned. A file written before this change holds
displaced timestamps and no interval starts, so reusing one would answer from
cache with the numbers being removed here; readers reject it and rebuild from the
raw profile, which is always kept. Validation also stops a truncated index
deserializing into an empty profile that answers "no hotspots" forever.

Numbers users have seen will change in both directions. Windowed self-times fall
by the ratio of the window to its sampled coverage; windows that were empty now
return data; and per-commit CPU blocks in every analyze report change wholesale,
because they were reading a region of the profile the commit never occupied. Any
before/after optimisation baseline recorded with the previous build has to be
re-measured.

Fixes #619
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

profiler-cpu-query mode=time_window: window clock doesn't line up with commit timestamps, and full-range self-times are double-counted 2×

1 participant