Expose all repeated measure durations in span queries

.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.

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

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 */

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` */

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,
     });

src/model/span-timing.ts

@@ -4,17 +4,17 @@ 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 ||
     samples.some((value) => !Number.isFinite(value) || value < 0)
   )
     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),

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 } : {}),
     });

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,

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 } : {}),

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

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;
+}

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);
+});

test/unit/span-merge.test.mjs

@@ -18,14 +18,15 @@ 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
   const merged = mergeSpanOccurrences(walls.map((wall, at) => measure("work", wall, `s${at}`)));
   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);
 });

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);
+});