From feb9bf224caa5e09b2fbbc9167ac86fe85ee004c Mon Sep 17 00:00:00 2001 From: Jan Nicklas Date: Sun, 6 Sep 2026 14:18:05 +0200 Subject: [PATCH] Expose every repeated measure duration in span timing queries --- .changeset/measure-occurrence-timings.md | 8 ++ README.md | 17 ++++ src/model/query.ts | 8 +- src/model/recording.ts | 8 +- src/model/span-merge.ts | 8 +- src/model/span-timing.ts | 8 +- src/profile/gecko-breakdown.ts | 1 + src/record/breakdown-spans.ts | 1 + src/record/spans-build.ts | 1 + test/cli.e2e.test.mjs | 27 ++++++ test/fixtures/user-measure-occurrences.mjs | 11 +++ .../unit/measure-occurrences-storage.test.mjs | 85 +++++++++++++++++++ test/unit/span-merge.test.mjs | 26 +++++- test/unit/span-timing.test.mjs | 26 ++++++ 14 files changed, 224 insertions(+), 11 deletions(-) create mode 100644 .changeset/measure-occurrence-timings.md create mode 100644 test/fixtures/user-measure-occurrences.mjs create mode 100644 test/unit/measure-occurrences-storage.test.mjs diff --git a/.changeset/measure-occurrence-timings.md b/.changeset/measure-occurrence-timings.md new file mode 100644 index 0000000..b190bc5 --- /dev/null +++ b/.changeset/measure-occurrence-timings.md @@ -0,0 +1,8 @@ +--- +"@jantimon/web-performance-debugger": minor +--- + +Keep the timing series for repeated named measures in capture order and expose it +through `query span --format json|toon`. The timing block uses +`sampleUnit: "occurrence"`, since one iteration can produce several measures with the same name. +The profile bar keeps its actual lower-median occurrence; its slices are not averaged. diff --git a/README.md b/README.md index 1c99c4a..9de7e9f 100644 --- a/README.md +++ b/README.md @@ -1170,6 +1170,23 @@ profile bar covers. Keep `timing.stats.medianMs` distinct from `wallMs` and WPD does not combine samples from different captures. `query spans` stays a compact overview; drill into `query span` for the sample series. +Repeated named measures expose `timing.sampleUnit: "occurrence"` with a boundary of +`performance-measure`. Their `samplesMs` list contains every recorded occurrence +in capture order. A label can occur several times within one iteration, so this +sample count need not match `iterations`. For example: + +```bash +wpd query span latest measure:work --format json | jq '.timing' +``` + +The measure's profile bar describes the occurrence with the lower-median profiled +wall time. The timing samples use each measure's start and end; Firefox's sampled +profile window can differ from those bounds. `timing.stats.medianMs` also uses the +arithmetic midpoint for an even sample count, so it can differ from the bar's +`wallMs`. WPD does not average profile slices. A +measure without a stored occurrence series returns `timing: null`, including an +unrepeated measure; its individual wall remains available as `wallMs`. + Recordings are self-describing: `meta.schemaVersion` stamps the on-disk schema epoch (currently `"5"`), and a reader **rejects** any artifact from another epoch with a "recorded by an older wpd; re-record" message rather than mis-parsing it into silent nulls. Numbers are rounded to 4 decimals on diff --git a/src/model/query.ts b/src/model/query.ts index 7bfbc4b..93dbeb2 100644 --- a/src/model/query.ts +++ b/src/model/query.ts @@ -557,10 +557,10 @@ export interface SpanHotFunctions { /** Recorded timing samples and the scope each sample measures */ export interface SpanTiming { - /** Recorded call or step durations in capture order; unmeasured steps are omitted */ - sampleUnit: "iteration"; - /** Start/end scope of each sample; excludes work outside these calls or step marks */ - boundary: "run-call" | "driver-step"; + /** Recorded durations in capture order; unmeasured step repetitions are omitted */ + sampleUnit: "iteration" | "occurrence"; + /** Start/end scope of each sample: a run call, driver step, or named measure */ + boundary: "run-call" | "driver-step" | "performance-measure"; /** `page` denotes performance.now() in the page or Node runtime; null means unspecified */ clock: "page" | "trace" | null; /** Recorded durations in milliseconds; independent of the profiled bar window */ diff --git a/src/model/recording.ts b/src/model/recording.ts index cde1198..0d68f91 100644 --- a/src/model/recording.ts +++ b/src/model/recording.ts @@ -585,7 +585,7 @@ export interface Span { * - step: the MEDIAN of the step's per-iteration samples (`perIteration`/`stats` hold the spread), * priced on the clock `wallClock` names (the trace window between its marks, else the page's * performance.now delta). - * - measure: the merged occurrence's own window (a `performance.measure`, page clock). + * - measure: the merged occurrence's own window (a `performance.measure`, trace clock). * * Null only when there is genuinely no such wall (a driver run, or a step that navigated in a * no-trace capture). The trace-clock window a reconciling bar TILES is `breakdown.wallMs`, a distinct @@ -678,6 +678,8 @@ export interface Span { * unrepeated measure. When present (> 1), `aggregation` is `"median"` */ samples?: number; + /** Wall times (ms) of merged measure occurrences in capture order; absent on unrepeated spans */ + occurrenceWallMs?: number[]; /** wall (ms) of the shortest merged occurrence; disclosed with `samples` (`wallMinMs <= wallMs <= wallMaxMs`) */ wallMinMs?: number; /** wall (ms) of the longest merged occurrence; disclosed with `samples` */ @@ -718,6 +720,8 @@ export interface SpanBreakdown { kind: SpanKind; /** the seven-slice reconciling bar for this span */ breakdown: Breakdown; + /** Measure end minus start on the capture clock; assembly-only, independent of sampled bar width */ + occurrenceTimingMs?: number; /** * Off-thread compositor frame side track for this span (Chrome --breakdown only; absent * otherwise, and on spans whose window caught no frame). DISPLAY-ONLY: never summed into @@ -733,6 +737,8 @@ export interface SpanBreakdown { * `"median"` */ samples?: number; + /** Wall times (ms) of merged measure occurrences in capture order; absent on unrepeated spans */ + occurrenceWallMs?: number[]; /** wall (ms) of the shortest merged occurrence; disclosed with `samples`, so a reader sees the spread */ wallMinMs?: number; /** wall (ms) of the longest merged occurrence; disclosed with `samples` */ diff --git a/src/model/span-merge.ts b/src/model/span-merge.ts index 6a9c627..f684c00 100644 --- a/src/model/span-merge.ts +++ b/src/model/span-merge.ts @@ -19,7 +19,8 @@ function lowerMedianIndex(count: number): number { * occurrence whose `breakdown.wallMs` is the lower median across all occurrences -- a real sample, so * `Σ slices + idle = wall` holds byte-for-byte (averaging slices independently would fabricate a bar * that no occurrence ever produced). The merged entry discloses the merge: `samples` (occurrence - * count) and the wall spread (`wallMinMs`/`wallMaxMs`). + * count), each wall time in capture order (`occurrenceWallMs`), and the wall spread + * (`wallMinMs`/`wallMaxMs`). * * run/step spans and single-occurrence measures pass through UNCHANGED, with no disclosure fields, so * an unrepeated flow and old recordings stay byte-identical. Input order is preserved by first @@ -51,9 +52,14 @@ export function mergeSpanOccurrences(spans: SpanBreakdown[]): SpanBreakdown[] { } const byWall = [...group].sort((left, right) => left.breakdown.wallMs - right.breakdown.wallMs); const picked = byWall[lowerMedianIndex(byWall.length)]; + const timings = group.map((span) => span.occurrenceTimingMs); + const hasTimings = timings.every( + (value): value is number => value != null && Number.isFinite(value) && value >= 0, + ); merged.push({ ...picked, samples: group.length, + ...(hasTimings ? { occurrenceWallMs: timings } : {}), wallMinMs: byWall[0].breakdown.wallMs, wallMaxMs: byWall[byWall.length - 1].breakdown.wallMs, }); diff --git a/src/model/span-timing.ts b/src/model/span-timing.ts index 6a5dc3b..1f5bc6e 100644 --- a/src/model/span-timing.ts +++ b/src/model/span-timing.ts @@ -4,8 +4,8 @@ import { computeStats } from "../metrics/summarize.js"; /** Read measured samples without substituting a trace window or an aggregate wall */ export function spanTiming(span: Span): SpanTiming | null { - if (span.kind !== "run" && span.kind !== "step") return null; - const samples = span.perIteration; + const isMeasure = span.kind === "measure"; + const samples = isMeasure ? span.occurrenceWallMs : span.perIteration; if ( !Array.isArray(samples) || !samples.length || @@ -13,8 +13,8 @@ export function spanTiming(span: Span): SpanTiming | null { ) return null; return { - sampleUnit: "iteration", - boundary: span.kind === "run" ? "run-call" : "driver-step", + sampleUnit: isMeasure ? "occurrence" : "iteration", + boundary: isMeasure ? "performance-measure" : span.kind === "run" ? "run-call" : "driver-step", clock: span.wallClock ?? null, samplesMs: [...samples], stats: computeStats(samples), diff --git a/src/profile/gecko-breakdown.ts b/src/profile/gecko-breakdown.ts index 6d762d7..fe7b61b 100644 --- a/src/profile/gecko-breakdown.ts +++ b/src/profile/gecko-breakdown.ts @@ -242,6 +242,7 @@ export function buildGeckoSpanBreakdowns( spans.push({ label: measure.label, kind: "measure", + occurrenceTimingMs: usToMs(measure.endTs - measure.startTs), breakdown: spanBreakdown(raw, packageByNode, bounds.from, bounds.to), ...(scope ? { scope } : {}), }); diff --git a/src/record/breakdown-spans.ts b/src/record/breakdown-spans.ts index f5748fc..3f43d95 100644 --- a/src/record/breakdown-spans.ts +++ b/src/record/breakdown-spans.ts @@ -155,6 +155,7 @@ export async function buildBreakdowns( breakdowns.push({ label: span.label, kind: span.kind, + ...(span.kind === "measure" ? { occurrenceTimingMs: usToMs(span.endTs - span.startTs) } : {}), breakdown: computeSpanBreakdown(windowEvents, windowSamples, { startTs: span.startTs, endTs: span.endTs, diff --git a/src/record/spans-build.ts b/src/record/spans-build.ts index 8b72849..9727be2 100644 --- a/src/record/spans-build.ts +++ b/src/record/spans-build.ts @@ -174,6 +174,7 @@ export function buildRecordingSpans(input: SpansBuildInput): Span[] { breakdown: bar.breakdown, counts: notMeasuredSpanCounts(), ...(bar.samples != null ? { samples: bar.samples } : {}), + ...(bar.occurrenceWallMs ? { occurrenceWallMs: bar.occurrenceWallMs } : {}), ...(bar.wallMinMs != null ? { wallMinMs: bar.wallMinMs } : {}), ...(bar.wallMaxMs != null ? { wallMaxMs: bar.wallMaxMs } : {}), ...(bar.frames ? { frames: bar.frames } : {}), diff --git a/test/cli.e2e.test.mjs b/test/cli.e2e.test.mjs index c715af0..baeb481 100644 --- a/test/cli.e2e.test.mjs +++ b/test/cli.e2e.test.mjs @@ -2,6 +2,7 @@ import { test } from "node:test"; import assert from "node:assert/strict"; import { spawn, spawnSync } from "node:child_process"; import { + copyFileSync, existsSync, mkdtempSync, readdirSync, @@ -1395,6 +1396,32 @@ e2e("record --breakdown: a repeated performance.measure merges to a median bar ( assert.ok(measureSpan.breakdown.slices.js.ms > 0, "the measured JS work lands in the js slice"); }); +e2e("query span: repeated measure timing exposes every occurrence within each iteration", { timeout: TIMEOUT_MS }, () => { + const dir = mkdtempSync(path.join(tmpdir(), "wpd-occurrence-query-")); + const out = path.join(dir, "capture.json"); + const fixture = path.join(dir, "user-measure-occurrences.mjs"); + copyFileSync(path.join(repoRoot, "test", "fixtures", "user-measure-occurrences.mjs"), fixture); + runCli([ + "record", "./user-measure-occurrences.mjs", + "--bench", "--breakdown", "--iterations", "3", "--warmup", "0", "--out", out, + ], dir); + const result = JSON.parse(runCli(["query", "span", out, "measure:batch", "--format", "json"], dir)); + assert.equal(result.iterations, 3); + assert.equal(result.samples, 6); + assert.equal(result.timing.sampleUnit, "occurrence"); + assert.equal(result.timing.boundary, "performance-measure"); + assert.equal(result.timing.clock, "trace"); + const samples = result.timing.samplesMs; + assert.equal(samples.length, 6); + assert.ok(samples.every((value) => Number.isFinite(value) && value >= 0)); + const sorted = [...samples].sort((left, right) => left - right); + assert.equal(result.wallMs, sorted[2], "the bar keeps the actual lower-median occurrence"); + assert.equal(result.wallMinMs, sorted[0]); + assert.equal(result.wallMaxMs, sorted[5]); + assert.ok(Math.abs(result.timing.stats.medianMs - (sorted[2] + sorted[3]) / 2) < 0.0001); + assert.equal(result.timing.stats.samples, 6); +}); + // `query spans`: the unified per-span surface. On chrome --breakdown it sources the stored // seven-slice bars, so a consumer reads the run span AND the user measure with one shape and one // access path (spans[], keyed by label) -- the label-keyed join a matrix consumer performs diff --git a/test/fixtures/user-measure-occurrences.mjs b/test/fixtures/user-measure-occurrences.mjs new file mode 100644 index 0000000..fe4aa18 --- /dev/null +++ b/test/fixtures/user-measure-occurrences.mjs @@ -0,0 +1,11 @@ +/** Two named measures per run, so occurrence count differs from iteration count */ +export function run() { + let sum = 0; + for (let occurrence = 0; occurrence < 2; occurrence++) { + performance.mark("batch:start"); + for (let index = 0; index < 400000; index++) sum += Math.sqrt(index + occurrence + 1); + performance.mark("batch:end"); + performance.measure("batch", "batch:start", "batch:end"); + } + return sum; +} diff --git a/test/unit/measure-occurrences-storage.test.mjs b/test/unit/measure-occurrences-storage.test.mjs new file mode 100644 index 0000000..8c29a2e --- /dev/null +++ b/test/unit/measure-occurrences-storage.test.mjs @@ -0,0 +1,85 @@ +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { mergeSpanOccurrences } from "../../dist/model/span-merge.js"; +import { buildRecordingSpans } from "../../dist/record/spans-build.js"; +import { buildSummary, NO_RENDERING_CAPTURE } from "../../dist/metrics/summarize.js"; +import { buildGeckoSpanBreakdowns } from "../../dist/profile/gecko-breakdown.js"; +import { parseGecko, geckoToRawCpuProfile } from "../../dist/profile/gecko.js"; +import { spanTiming } from "../../dist/model/span-timing.js"; +import { syntheticGeckoDump } from "./helpers.mjs"; + +const measure = (wallMs) => ({ + label: "work", + kind: "measure", + occurrenceTimingMs: wallMs, + breakdown: { + wallMs, + slices: { + js: { ms: wallMs / 2, byPackage: { app: wallMs / 2 } }, + style: { ms: 0 }, + layout: { ms: 0 }, + paint: { ms: 0 }, + gc: { ms: 0 }, + other: { ms: 0 }, + idle: { ms: wallMs / 2 }, + }, + }, +}); + +function storedSpans(bars) { + return buildRecordingSpans({ + summary: buildSummary({ detailEvents: [], detailWindowStart: null }), + detailEvents: [], + capabilities: NO_RENDERING_CAPTURE, + bars, + runWindowEnd: null, + }); +} + +test("recording spans preserve measure samples through JSON storage", () => { + const bars = mergeSpanOccurrences([8, 2, 6, 4].map(measure)); + const spans = JSON.parse(JSON.stringify(storedSpans(bars))); + const work = spans.find((span) => span.kind === "measure"); + assert.deepEqual(work.occurrenceWallMs, [8, 2, 6, 4]); + assert.equal(work.samples, 4); + assert.equal(work.wallMs, 4, "the bar uses a real lower-median occurrence"); + assert.equal(work.wallMinMs, 2); + assert.equal(work.wallMaxMs, 8); + assert.equal(work.aggregation, "median"); + assert.deepEqual(work.breakdown, bars[0].breakdown); + assert.equal(Object.hasOwn(work, "occurrenceTimingMs"), false, "assembly timing does not leak into storage"); + assert.equal(work.perIteration, undefined, "occurrences do not imply one sample per iteration"); + assert.equal(spans[0].occurrenceWallMs, undefined, "run timings stay separate"); +}); + +test("recording spans omit occurrence samples when the bar has no series", () => { + for (const bar of [ + measure(4), + { ...measure(4), samples: 3, wallMinMs: 2, wallMaxMs: 8 }, + ]) { + const work = storedSpans([bar]).find((span) => span.kind === "measure"); + assert.equal(Object.hasOwn(work, "occurrenceWallMs"), false); + } +}); + +test("Firefox measure timings use marker bounds even when the sampled bar misses the work", () => { + const raw = geckoToRawCpuProfile(parseGecko(syntheticGeckoDump())); + const windows = [[100, 200], [950, 1050], [1100, 1900], [2900, 4100]].map(([start, end]) => ({ + label: "work", startTs: raw.startTime + start, endTs: raw.startTime + end, + })); + const bars = buildGeckoSpanBreakdowns(raw, new Map(), windows, { + startTs: raw.startTime, endTs: raw.startTime + 5000, + }, 1000); + const work = JSON.parse(JSON.stringify(storedSpans(bars))).find((span) => span.kind === "measure"); + assert.deepEqual(work.occurrenceWallMs, [0.1, 0.1, 0.8, 1.2]); + assert.equal(work.breakdown.wallMs, 0, "the lower-median profile window contains no sample"); + assert.equal(work.wallMinMs, 0); + assert.equal(work.wallMaxMs, 2, "profile spread still uses whole sampled deltas"); + const timing = spanTiming(work); + assert.equal(timing.clock, "trace"); + assert.equal(timing.boundary, "performance-measure"); + assert.deepEqual(timing.samplesMs, [0.1, 0.1, 0.8, 1.2]); + assert.equal(timing.stats.medianMs, 0.45); + assert.equal(timing.stats.minMs, 0.1); + assert.equal(timing.stats.maxMs, 1.2); +}); diff --git a/test/unit/span-merge.test.mjs b/test/unit/span-merge.test.mjs index 03b331e..612e30f 100644 --- a/test/unit/span-merge.test.mjs +++ b/test/unit/span-merge.test.mjs @@ -18,7 +18,7 @@ const bar = (wallMs, mark) => ({ }, mark, }); -const measure = (label, wallMs, mark) => ({ label, kind: "measure", breakdown: bar(wallMs, mark) }); +const measure = (label, wallMs, mark) => ({ label, kind: "measure", breakdown: bar(wallMs, mark), occurrenceTimingMs: wallMs }); test("mergeSpanOccurrences: odd count keeps the true-median-by-wall occurrence, verbatim", () => { const walls = [5, 1, 3]; // median wall is 3 @@ -26,6 +26,7 @@ test("mergeSpanOccurrences: odd count keeps the true-median-by-wall occurrence, assert.equal(merged.length, 1, "one bar per label"); const kept = merged[0]; assert.equal(kept.samples, 3, "samples counts real occurrences"); + assert.deepEqual(kept.occurrenceWallMs, walls, "wall samples retain capture order"); assert.equal(kept.breakdown.wallMs, 3, "the median-wall occurrence is picked"); assert.equal(kept.breakdown.mark, "s2", "the KEPT bar is that occurrence VERBATIM (its own mark survives)"); assert.equal(kept.wallMinMs, 1, "spread min is the shortest occurrence"); @@ -38,6 +39,7 @@ test("mergeSpanOccurrences: even count takes the LOWER median, so the bar stays const merged = mergeSpanOccurrences(walls.map((wall, at) => measure("work", wall, `s${at}`))); assert.equal(merged[0].breakdown.wallMs, 4, "the lower of the two middles (not their average of 5)"); assert.equal(merged[0].samples, 4); + assert.deepEqual(merged[0].occurrenceWallMs, walls); assert.equal(merged[0].wallMinMs, 2); assert.equal(merged[0].wallMaxMs, 8); }); @@ -55,6 +57,7 @@ test("mergeSpanOccurrences: a single occurrence passes through with NO disclosur assert.equal(merged.length, 1); assert.equal(merged[0], only, "the exact object passes through"); assert.equal(merged[0].samples, undefined, "no samples field on a single occurrence"); + assert.equal(merged[0].occurrenceWallMs, undefined); assert.equal(merged[0].wallMinMs, undefined); assert.equal(merged[0].wallMaxMs, undefined); }); @@ -121,7 +124,28 @@ test("mergeSpanOccurrences: distinct labels are merged independently, frames of // "a": walls 5,1 lower-median 1 -> frames.total 1 (the picked occurrence's own side track) assert.equal(spanA.breakdown.wallMs, 1); assert.equal(spanA.frames.total, 1, "the kept bar keeps ITS occurrence's frame side track"); + assert.deepEqual(spanA.occurrenceWallMs, [5, 1]); // "b": walls 2,4 lower-median 2 assert.equal(spanB.breakdown.wallMs, 2); assert.equal(spanB.frames.total, 2); + assert.deepEqual(spanB.occurrenceWallMs, [2, 4]); +}); + +test("mergeSpanOccurrences: zero and tied wall times retain every occurrence without changing input", () => { + const input = [measure("work", 3, "a"), measure("work", 0, "b"), measure("work", 3, "c")]; + const original = structuredClone(input); + const [merged] = mergeSpanOccurrences(input); + assert.deepEqual(merged.occurrenceWallMs, [3, 0, 3]); + assert.equal(merged.samples, 3); + assert.equal(merged.breakdown, input[0].breakdown, "ties retain the first matching real bar"); + assert.deepEqual(input, original); +}); + +test("mergeSpanOccurrences: missing measure bounds do not become sampled timing values", () => { + const first = measure("work", 3, "a"); + delete first.occurrenceTimingMs; + const [merged] = mergeSpanOccurrences([first, measure("work", 7, "b")]); + assert.equal(merged.occurrenceWallMs, undefined); + assert.equal(merged.samples, 2); + assert.equal(merged.breakdown.wallMs, 3); }); diff --git a/test/unit/span-timing.test.mjs b/test/unit/span-timing.test.mjs index 9904fb3..a742617 100644 --- a/test/unit/span-timing.test.mjs +++ b/test/unit/span-timing.test.mjs @@ -108,3 +108,29 @@ test("the Node record and query CLI return one timing sample per timed call", { assert.ok(result.timing.samplesMs.every((sample) => Number.isFinite(sample) && sample >= 0)); assert.equal(result.timing.stats.samples, 3); }); + + +test("measure timing keeps occurrence order and distinguishes its median from the profile bar", async () => { + const file = recording("measure.json", [span("measure", { + occurrenceWallMs: [8, 2, 6, 4], samples: 4, aggregation: "median", wallClock: "trace", + wallMs: 4, breakdown: bar(4), wallMinMs: 2, wallMaxMs: 8, + })]); + for (const format of ["json", "toon"]) { + const result = await query(file, "measure:work", format); + assert.equal(result.iterations, 3); + assert.equal(result.wallMs, 4); + assert.equal(result.samples, 4); + assert.deepEqual(result.timing, { + sampleUnit: "occurrence", boundary: "performance-measure", clock: "trace", + samplesMs: [8, 2, 6, 4], + stats: { samples: 4, minMs: 2, medianMs: 5, meanMs: 5, maxMs: 8 }, + }); + } +}); + +test("a measure without its recorded series does not invent samples from its median or spread", async () => { + const file = recording("measure-no-series.json", [span("measure", { + samples: 4, aggregation: "median", wallMs: 4, wallMinMs: 2, wallMaxMs: 8, breakdown: bar(4), + })]); + assert.equal((await query(file, "measure:work")).timing, null); +});