Expose measured run and step samples in span queries

.changeset/span-timing-samples.md

@@ -0,0 +1,8 @@
+---
+"@jantimon/web-performance-debugger": minor
+---
+
+Expose run and driver-step timing samples through `query span --format json|toon`.
+The exported `SpanTiming` type names each sample's clock and boundary and keeps
+measured statistics separate from the profiled bar window. Run-group members carry
+their own timing blocks. Missing samples remain `null`.

README.md

@@ -1148,6 +1148,28 @@ split lives at `byPackage[]` (`key`/`selfMs`/`selfPct`, plus `siteRelation` on a
 For per-span numbers, `query spans --format json` gives one `UnifiedSlices` shape (`js.byPackage`,
 `style`, `layout`, …) across chrome/firefox/node — read that, never the multi-MB recording.
 
+Read a run or driver step's timing samples through `query span`:
+
+```bash
+wpd query span latest run --format json | jq '.timing'
+```
+
+`SpanAnatomy.timing` is a `SpanTiming` block with `samplesMs` in capture order,
+`stats` (min/median/mean/max), `sampleUnit: "iteration"`, a `boundary` of `run-call`
+or `driver-step`, and a `clock` of `page`, `trace`, or `null` when unspecified.
+The `page` clock uses `performance.now()` in a browser page or Node runtime.
+Unmeasured step repetitions are omitted, so the sample count can differ from the
+requested iteration count. Statistics use the stored samples and are `null` below
+two samples. The whole block
+is `null` when no valid sample series is stored; WPD does not infer samples from a
+profile window or an aggregate wall. Capture overhead still applies to these timings.
+
+These samples measure each call or step, independently of the window that the
+profile bar covers. Keep `timing.stats.medianMs` distinct from `wallMs` and
+`windowMs`. For a run-group, each `members[]` entry carries its own `timing` block;
+WPD does not combine samples from different captures. `query spans` stays a compact
+overview; drill into `query span` for the sample series.
+
 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

scripts/pack-smoke.mjs

@@ -110,6 +110,7 @@ try {
     "SpanEntry",
     "UnifiedSlices",
     "SpanAnatomy",
+    "SpanTiming",
     "CpuOverview",
     "FrameQueryResult",
     "BlameEntry",

src/commands/query.ts

@@ -39,6 +39,7 @@ import {
   blameRowLowConfidence,
 } from "../model/capture-mode.js";
 import { runSpan } from "../model/span.js";
+import { spanTiming } from "../model/span-timing.js";
 import { dim } from "../output/color.js";
 import { num, table, middleEllipsis, SOURCE_COL_MAX } from "../output/ascii.js";
 import { analyzeThrash } from "../trace/thrash.js";
@@ -382,6 +383,7 @@ function buildSpanAnatomy(
 
   return {
     recording: recordingPath,
+    timing: spanTiming(span),
     target,
     label: span.label,
     kind: span.kind,
@@ -619,6 +621,7 @@ async function buildGroupSpanStitch(
          */
         mode: member.mode as CaptureMode,
         ...(member.variant ? { variant: member.variant } : {}),
+        timing: anatomy.timing,
         wallMs: anatomy.wallMs,
         aggregation: anatomy.aggregation,
         iterations: anatomy.iterations,

src/index.ts

@@ -106,6 +106,7 @@ export type {
   SpanForced,
   SpanHotFunctions,
   SpanAnatomy,
+  SpanTiming,
   GroupSpanMember,
   GroupSpanSources,
   GroupSpanStitch,

src/model/query.ts

@@ -3,6 +3,7 @@
 // call sites can be annotated and the JSON contract cannot silently drift
 
 import type {
+  BenchStats,
   CpuBreakdown,
   CpuFunction,
   CpuGroupStat,
@@ -554,6 +555,20 @@ export interface SpanHotFunctions {
   functions?: (Omit<CpuFunction, "totalMs"> & { totalMs?: number })[];
 }
 
+/** 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";
+  /** `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 */
+  samplesMs: number[];
+  /** Statistics over these samples; null for fewer than two samples */
+  stats: BenchStats | null;
+}
+
 /**
  * `query span <label>` output: one span's full anatomy. `slices` is the reconciling bar's unified
  * shape when the capture mode built one, else null (capture-mode-honest, never fabricated). `counts` are Measured
@@ -565,6 +580,8 @@ export interface SpanHotFunctions {
  * silent join
  */
 export interface SpanAnatomy {
+  /** Timed samples and their boundaries; null when no valid sample series is stored */
+  timing: SpanTiming | null;
   /** absolute back-pointer to the recording this anatomy was read from */
   recording: string;
   /** the --target axis: chrome | firefox | node */
@@ -666,6 +683,8 @@ export interface SpanAnatomy {
 /** One member's own numbers for a stitched span, tagged by its capture mode. Walls are shown PER
  * member and never combined -- a group holds N captures of one workload, not one measurement */
 export interface GroupSpanMember {
+  /** This member's own timing samples; captures are never pooled */
+  timing: SpanTiming | null;
   mode: CaptureMode;
   variant?: string;
   wallMs: number | null;

src/model/span-timing.ts

@@ -0,0 +1,22 @@
+import type { Span } from "./recording.js";
+import type { SpanTiming } from "./query.js";
+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;
+  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",
+    clock: span.wallClock ?? null,
+    samplesMs: [...samples],
+    stats: computeStats(samples),
+  };
+}

test/unit/public-types.test.mjs

@@ -26,6 +26,7 @@ const DOCUMENTED_ROOT_TYPES = [
   "SpanEntry",
   "UnifiedSlices",
   "SpanAnatomy",
+  "SpanTiming",
   "CpuOverview",
   "FrameQueryResult",
   "BlameEntry",

test/unit/span-timing.test.mjs

@@ -0,0 +1,110 @@
+import { test } from "node:test";
+import assert from "node:assert/strict";
+import { mkdtempSync, writeFileSync } from "node:fs";
+import { tmpdir } from "node:os";
+import path from "node:path";
+import { execFileSync } from "node:child_process";
+import { decode } from "@toon-format/toon";
+import { querySpan } from "../../dist/commands/query.js";
+import { notMeasuredSpanCounts } from "../../dist/model/span.js";
+
+const directory = mkdtempSync(path.join(tmpdir(), "wpd-span-timing-"));
+const stats = { samples: 3, minMs: 1, medianMs: 3, meanMs: 4, maxMs: 8 };
+const bar = (wallMs) => ({
+  wallMs,
+  slices: {
+    js: { ms: 1, byPackage: { app: 1 } },
+    style: { ms: 0 }, layout: { ms: 0 }, paint: { ms: 0 },
+    gc: { ms: 0 }, other: { ms: 0 }, idle: { ms: wallMs - 1 },
+  },
+});
+const span = (kind, extra = {}) => ({
+  label: kind === "run" ? "run" : "work", kind,
+  aggregation: kind === "run" ? "sum" : "first",
+  wallMs: 12, wallClock: "page", counts: notMeasuredSpanCounts(), ...extra,
+});
+function recording(name, spans, capture = "breakdown") {
+  const file = path.join(directory, name);
+  writeFileSync(file, JSON.stringify({
+    meta: { schemaVersion: "5", target: "chrome", iterations: 3, capture },
+    window: { startTs: 0, endTs: 100000 }, events: [], spans,
+  }));
+  return file;
+}
+async function query(file, label, format = "json") {
+  const log = console.log;
+  let text = "";
+  console.log = (line) => { text += `${line}\n`; };
+  try { await querySpan(file, label, { format }); }
+  finally { console.log = log; }
+  return format === "json" ? JSON.parse(text) : decode(text);
+}
+
+test("run timing exposes captured samples rather than dividing the profile window", async () => {
+  const file = recording("run.json", [span("run", { perIteration: [8, 1, 3], breakdown: bar(100) })]);
+  for (const format of ["json", "toon"]) {
+    const result = await query(file, "run", format);
+    assert.equal(result.wallMs, 100);
+    assert.deepEqual(result.timing, {
+      sampleUnit: "iteration", boundary: "run-call", clock: "page", samplesMs: [8, 1, 3], stats,
+    });
+  }
+});
+
+test("step timing keeps its clock and sample order separate from the first profile window", async () => {
+  const file = recording("step.json", [span("step", { wallClock: "trace", perIteration: [8, 1, 3], wallMs: 3, breakdown: bar(8) })]);
+  const result = await query(file, "step:work");
+  assert.equal(result.wallMs, 3);
+  assert.equal(result.windowMs, 8);
+  assert.deepEqual(result.timing, {
+    sampleUnit: "iteration", boundary: "driver-step", clock: "trace", samplesMs: [8, 1, 3], stats,
+  });
+});
+
+test("zero is a measured sample; a single sample has no statistics", async () => {
+  const file = recording("zero.json", [span("run", { perIteration: [0] })], "deep");
+  const result = await query(file, "run");
+  assert.deepEqual(result.timing.samplesMs, [0]);
+  assert.equal(result.timing.stats, null);
+});
+
+test("missing clocks remain unknown and missing or invalid samples remain unavailable", async () => {
+  const unknown = recording("unknown.json", [span("run", { perIteration: [1], wallClock: undefined })], "deep");
+  assert.equal((await query(unknown, "run")).timing.clock, null);
+  for (const [index, samples] of [undefined, [], [1, -1], [null]].entries()) {
+    const file = recording(`unavailable-${index}.json`, [span("run", { perIteration: samples, breakdown: bar(100) })]);
+    assert.equal((await query(file, "run")).timing, null);
+  }
+});
+
+test("run-group samples remain attached to their capture member", async () => {
+  recording("member-breakdown.json", [span("run", { perIteration: [8, 1, 3], breakdown: bar(100) })]);
+  recording("member-deep.json", [span("run", { perIteration: [30, 20, 10] })], "deep");
+  const file = path.join(directory, "timings.group.json");
+  writeFileSync(file, JSON.stringify({
+    meta: { schemaVersion: "5", kind: "run-group", name: "timings" },
+    iterations: 3, warmup: 0, headless: true, notes: [],
+    members: ["breakdown", "deep"].map((mode) => ({ mode, recording: `member-${mode}.json`, createdAt: "", annotations: [] })),
+  }));
+  const result = await query(file, "run");
+  assert.equal(result.timing, undefined);
+  assert.deepEqual(result.members.map((member) => [member.mode, member.timing.samplesMs]), [
+    ["breakdown", [8, 1, 3]], ["deep", [30, 20, 10]],
+  ]);
+});
+
+test("the Node record and query CLI return one timing sample per timed call", { timeout: 30_000 }, () => {
+  const entry = path.join(directory, "work.mjs");
+  const file = path.join(directory, "node.json");
+  writeFileSync(entry, "export function run() { for (let i = 0; i < 1000; i++) Math.sqrt(i); }\n");
+  const cli = path.resolve("dist/cli.js");
+  const run = (args) => execFileSync(process.execPath, [cli, ...args], { cwd: directory, encoding: "utf8", timeout: 25_000, env: { ...process.env, XDG_STATE_HOME: path.join(directory, "state") } });
+  run(["record", entry, "--target", "node", "--iterations", "3", "--warmup", "1", "--out", file]);
+  const result = JSON.parse(run(["query", "span", file, "run", "--format", "json"]));
+  assert.equal(result.timing.sampleUnit, "iteration");
+  assert.equal(result.timing.boundary, "run-call");
+  assert.equal(result.timing.clock, "page");
+  assert.equal(result.timing.samplesMs.length, 3);
+  assert.ok(result.timing.samplesMs.every((sample) => Number.isFinite(sample) && sample >= 0));
+  assert.equal(result.timing.stats.samples, 3);
+});