From c05d194dd46a75381a012de5eb98089833fb9880 Mon Sep 17 00:00:00 2001 From: Sawyer Cutler Date: Tue, 4 Aug 2026 04:45:08 -0700 Subject: [PATCH 1/2] Add PerfTrace latency eval harness with phase assertions Eval helpers assert phase presence, nesting, and turn inference+tools regressions against a golden multi-tool fixture and the reactor observer pipeline. --- src/perf/assert-spans.test.ts | 189 +++++++++++++++++++++++++++ src/perf/assert-spans.ts | 114 ++++++++++++++++ src/perf/fixtures/multi-tool-turn.ts | 106 +++++++++++++++ 3 files changed, 409 insertions(+) create mode 100644 src/perf/assert-spans.test.ts create mode 100644 src/perf/assert-spans.ts create mode 100644 src/perf/fixtures/multi-tool-turn.ts diff --git a/src/perf/assert-spans.test.ts b/src/perf/assert-spans.test.ts new file mode 100644 index 000000000..c225e62f1 --- /dev/null +++ b/src/perf/assert-spans.test.ts @@ -0,0 +1,189 @@ +/** + * Latency eval harness: assert on PerfTrace phase presence and relative magnitudes. + * + * Covers CL-5174 outcomes: + * - phase presence + nesting helpers + * - regression: turn has inference + tools when tools ran + * - golden multi-tool fixture rollup + * - full observer pipeline → snapshot → rollup → assertions + */ + +import { afterEach, describe, expect, test } from "bun:test"; +import type { ReactorEmittedEvent } from "@intx/inference"; +import { + assertLessThan, + assertNesting, + assertPhasePresent, + assertPhaseSummary, + assertTurnHasInferenceAndTools, +} from "./assert-spans.js"; +import { + MULTI_TOOL_TURN_GOLDEN, + multiToolTurnFixture, +} from "./fixtures/multi-tool-turn.js"; +import { ALLOWED_TAG_KEYS, clear, snapshot, type PerfSpan } from "./index.js"; +import { createPerfReactorObserver } from "./reactor-spans.js"; +import { rollupByPhase, rollupByTurn, sessionTotals } from "./rollup.js"; + +afterEach(() => { + clear(); +}); + +const ALLOWED_TAG_KEY_SET: ReadonlySet = new Set(ALLOWED_TAG_KEYS); + +function event(type: string, data: unknown = {}): ReactorEmittedEvent { + return { type, seq: 1, data } as ReactorEmittedEvent; +} + +const emptyUsage = { input: 10, output: 5, cacheRead: 0, cacheWrite: 0, thinking: 0 }; +const source = { provider: "test-provider", model: "test-model" }; + +function inferenceDone(content: unknown[] = [{ type: "text", text: "hi" }]): ReactorEmittedEvent { + return event("inference.done", { + turn: { role: "assistant", content, model: "test-model", timestamp: 0 }, + usage: emptyUsage, + source, + }); +} + +function completed(spans: PerfSpan[]): PerfSpan[] { + return spans.filter((s) => s.endNs !== undefined); +} + +describe("assertPhasePresent / assertNesting", () => { + test("assertPhasePresent finds phases on the golden fixture", () => { + const spans = multiToolTurnFixture(); + assertPhasePresent(spans, "turn"); + assertPhasePresent(spans, "inference"); + assertPhasePresent(spans, "inference.ttft"); + assertPhasePresent(spans, "inference.stream"); + assertPhasePresent(spans, "tool"); + assertPhasePresent(spans, "permission.wait"); + }); + + test("assertPhasePresent throws when phase is missing", () => { + expect(() => assertPhasePresent(multiToolTurnFixture(), "subagent")).toThrow( + /expected phase "subagent"/, + ); + }); + + test("assertNesting verifies parent-child links", () => { + const spans = multiToolTurnFixture(); + assertNesting(spans, "inference", "turn"); + assertNesting(spans, "inference.ttft", "inference"); + assertNesting(spans, "inference.stream", "inference"); + assertNesting(spans, "tool", "turn"); + assertNesting(spans, "permission.wait", "turn"); + }); + + test("assertNesting throws when link is absent", () => { + expect(() => assertNesting(multiToolTurnFixture(), "tool", "inference")).toThrow( + /expected nesting inference → tool/, + ); + }); +}); + +describe("golden multi-tool turn fixture", () => { + test("rollupByTurn matches locked golden values", () => { + const turns = rollupByTurn(multiToolTurnFixture()); + expect(turns).toHaveLength(1); + expect(turns[0]).toEqual({ ...MULTI_TOOL_TURN_GOLDEN }); + }); + + test("fixture tags are privacy-safe (allowlisted keys only)", () => { + for (const span of multiToolTurnFixture()) { + if (span.tags === undefined) continue; + for (const key of Object.keys(span.tags)) { + expect(ALLOWED_TAG_KEY_SET.has(key)).toBe(true); + } + } + }); + + test("phase rollup reports expected counts and totals", () => { + const phases = rollupByPhase(multiToolTurnFixture()); + assertPhaseSummary(phases, "turn", { minCount: 1, minTotalNs: 5000 }); + assertPhaseSummary(phases, "inference", { minCount: 1, minTotalNs: 2000 }); + assertPhaseSummary(phases, "tool", { minCount: 2, minTotalNs: 1200 }); + assertPhaseSummary(phases, "permission.wait", { minCount: 1, minTotalNs: 400 }); + }); +}); + +describe("regression: turn has inference + tools when tools ran", () => { + test("assertTurnHasInferenceAndTools passes on multi-tool golden rollup", () => { + const turns = rollupByTurn(multiToolTurnFixture()); + assertTurnHasInferenceAndTools(turns[0]!); + }); + + test("assertTurnHasInferenceAndTools fails when tools did not run", () => { + const spans: PerfSpan[] = multiToolTurnFixture().filter((s) => s.name !== "tool"); + const turns = rollupByTurn(spans); + expect(() => assertTurnHasInferenceAndTools(turns[0]!)).toThrow(/toolCount/); + }); + + test("TTFT is less than stream on the golden fixture", () => { + const turn = rollupByTurn(multiToolTurnFixture())[0]!; + assertLessThan(turn.ttftNs, turn.streamNs, "ttft vs stream"); + expect(turn.ttftNs).toBe(400); + expect(turn.streamNs).toBe(1600); + }); + + test("session totals include tool and inference cost", () => { + const totals = sessionTotals(multiToolTurnFixture()); + expect(totals.turnCount).toBe(1); + expect(totals.totalInferenceNs).toBe(2000); + expect(totals.totalToolNs).toBe(1200); + expect(totals.totalToolCount).toBe(2); + expect(totals.ttftShare).toBeCloseTo(0.2, 5); + expect(totals.streamShare).toBeCloseTo(0.8, 5); + }); +}); + +describe("observer pipeline → snapshot → rollup → assertions", () => { + test("multi-tool reactor events produce assertable turn rollup", () => { + const obs = createPerfReactorObserver(); + + obs.observe(event("inference.start", { model: "test-model" })); + obs.observe(event("inference.text.delta", { token: "x", partial: { text: "x" } })); + obs.observe( + inferenceDone([ + { type: "tool_call", id: "call-a", name: "read_file", arguments: {} }, + { type: "tool_call", id: "call-b", name: "edit_file", arguments: {} }, + ]), + ); + obs.observe(event("tool.start", { call: { id: "call-a", name: "read_file", arguments: {} } })); + obs.observe(event("tool.done", { result: { callId: "call-a", content: "ok" } })); + obs.observe(event("tool.start", { call: { id: "call-b", name: "edit_file", arguments: {} } })); + obs.observe(event("tool.done", { result: { callId: "call-b", content: "ok" } })); + + const spans = completed(snapshot()); + + assertPhasePresent(spans, "turn"); + assertPhasePresent(spans, "inference"); + assertPhasePresent(spans, "inference.ttft"); + assertPhasePresent(spans, "inference.stream"); + assertPhasePresent(spans, "tool"); + + assertNesting(spans, "inference", "turn"); + assertNesting(spans, "inference.ttft", "inference"); + assertNesting(spans, "inference.stream", "inference"); + assertNesting(spans, "tool", "turn"); + + const turns = rollupByTurn(spans); + expect(turns).toHaveLength(1); + assertTurnHasInferenceAndTools(turns[0]!); + expect(turns[0]!.toolCount).toBe(2); + + // Live clock: TTFT ends at/before stream starts, so ttftNs should be <= streamNs + // only when both are positive; with real hrtime, stream wall is typically longer. + if (turns[0]!.ttftNs > 0 && turns[0]!.streamNs > 0) { + // Relative magnitude: first-token wait should not dominate a multi-token stream + // in the happy path (stream duration is from first token to done). + expect(turns[0]!.streamNs).toBeGreaterThanOrEqual(0); + expect(turns[0]!.ttftNs).toBeGreaterThanOrEqual(0); + } + + const phases = rollupByPhase(spans); + assertPhaseSummary(phases, "tool", { minCount: 2 }); + assertPhaseSummary(phases, "inference", { minCount: 1 }); + }); +}); diff --git a/src/perf/assert-spans.ts b/src/perf/assert-spans.ts new file mode 100644 index 000000000..08fa7c8cf --- /dev/null +++ b/src/perf/assert-spans.ts @@ -0,0 +1,114 @@ +/** + * Eval / test harness assertions over PerfTrace snapshots and rollups. + * + * Pure helpers: throw Error with a clear message on failure (no bun:test import). + * Use from unit tests, capability evals, or ad-hoc scripts after snapshot()/rollup. + */ + +import type { PerfSpan, SpanName } from "./index.js"; +import type { PhaseSummary, TurnSummary } from "./rollup.js"; +import { spanDurationNs } from "./rollup.js"; + +/** Verify at least one span with the given phase name exists. */ +export function assertPhasePresent( + spans: readonly PerfSpan[], + phaseName: SpanName | string, +): void { + const found = spans.some((s) => s.name === phaseName); + if (!found) { + const names = [...new Set(spans.map((s) => s.name))].sort().join(", "); + throw new Error( + `expected phase "${phaseName}" in snapshot; present phases: [${names || "none"}]`, + ); + } +} + +/** + * Verify at least one span named `childName` is nested under a span named + * `parentName` (via parentId → id). + */ +export function assertNesting( + spans: readonly PerfSpan[], + childName: SpanName | string, + parentName: SpanName | string, +): void { + const byId = new Map(spans.map((s) => [s.id, s])); + const ok = spans.some((child) => { + if (child.name !== childName || child.parentId === undefined) return false; + const parent = byId.get(child.parentId); + return parent !== undefined && parent.name === parentName; + }); + if (!ok) { + throw new Error( + `expected nesting ${parentName} → ${childName}; no matching parentId link found`, + ); + } +} + +/** + * Regression: a turn that ran tools must report positive inference and tool cost. + * Accepts a single TurnSummary (from rollupByTurn). + */ +export function assertTurnHasInferenceAndTools(turn: TurnSummary): void { + if (turn.inferenceNs <= 0) { + throw new Error( + `turn ${turn.turnId}: expected inferenceNs > 0, got ${turn.inferenceNs}`, + ); + } + if (turn.toolCount <= 0) { + throw new Error( + `turn ${turn.turnId}: expected toolCount > 0 when tools ran, got ${turn.toolCount}`, + ); + } + if (turn.toolNs <= 0) { + throw new Error( + `turn ${turn.turnId}: expected toolNs > 0 when tools ran, got ${turn.toolNs}`, + ); + } +} + +/** + * Assert a < b for relative magnitude checks (e.g. TTFT < stream wall). + * Values are plain numbers (typically nanoseconds from rollup). + */ +export function assertLessThan( + left: number, + right: number, + label = "magnitude", +): void { + if (!(left < right)) { + throw new Error(`${label}: expected ${left} < ${right}`); + } +} + +/** + * Assert a phase summary exists in a rollupByPhase result and has count >= minCount. + */ +export function assertPhaseSummary( + phases: readonly PhaseSummary[], + phaseName: SpanName | string, + opts?: { minCount?: number; minTotalNs?: number }, +): PhaseSummary { + const phase = phases.find((p) => p.name === phaseName); + if (phase === undefined) { + const names = phases.map((p) => p.name).join(", "); + throw new Error( + `expected phase summary "${phaseName}"; present: [${names || "none"}]`, + ); + } + const minCount = opts?.minCount ?? 1; + if (phase.count < minCount) { + throw new Error( + `phase "${phaseName}": expected count >= ${minCount}, got ${phase.count}`, + ); + } + if (opts?.minTotalNs !== undefined && phase.totalNs < opts.minTotalNs) { + throw new Error( + `phase "${phaseName}": expected totalNs >= ${opts.minTotalNs}, got ${phase.totalNs}`, + ); + } + return phase; +} + +/** Span duration helper re-export for eval scripts that only import assertions. */ +export { spanDurationNs }; diff --git a/src/perf/fixtures/multi-tool-turn.ts b/src/perf/fixtures/multi-tool-turn.ts new file mode 100644 index 000000000..4fdd3cc7c --- /dev/null +++ b/src/perf/fixtures/multi-tool-turn.ts @@ -0,0 +1,106 @@ +/** + * Golden fixture: one multi-tool turn with nested inference and permission wait. + * + * Privacy-safe: only allowlisted tags (tool_id, model_id, provider_id, tokens). + * Fixed nanosecond times — no live clock. Durations: + * + * turn t1 0 → 5000 + * inference i1 100 → 2100 (2000ns) + * inference.ttft 100 → 500 ( 400ns) + * inference.stream 500 → 2100 (1600ns) + * permission.wait 2100 → 2500 ( 400ns) + * tool k1 2500 → 3200 ( 700ns) tool_id=read_file + * tool k2 3300 → 3800 ( 500ns) tool_id=edit_file + * + * TTFT (400) < stream (1600). Two tools under the turn. + */ + +import type { PerfSpan } from "../index.js"; + +function span(partial: { + id: string; + name: PerfSpan["name"]; + parentId?: string; + startNs: bigint; + endNs?: bigint; + tags?: PerfSpan["tags"]; +}): PerfSpan { + const s: PerfSpan = { + id: partial.id, + name: partial.name, + startNs: partial.startNs, + }; + if (partial.parentId !== undefined) s.parentId = partial.parentId; + if (partial.endNs !== undefined) s.endNs = partial.endNs; + if (partial.tags !== undefined) s.tags = partial.tags; + return s; +} + +/** Synthetic multi-tool turn tree for rollup / assertion regression tests. */ +export function multiToolTurnFixture(): PerfSpan[] { + return [ + span({ id: "t1", name: "turn", startNs: 0n, endNs: 5000n, tags: { turn_id: "turn-1" } }), + span({ + id: "i1", + name: "inference", + parentId: "t1", + startNs: 100n, + endNs: 2100n, + tags: { + provider_id: "test-provider", + model_id: "test-model", + input_tokens: 120, + output_tokens: 40, + }, + }), + span({ + id: "ttft1", + name: "inference.ttft", + parentId: "i1", + startNs: 100n, + endNs: 500n, + }), + span({ + id: "stream1", + name: "inference.stream", + parentId: "i1", + startNs: 500n, + endNs: 2100n, + }), + span({ + id: "pw1", + name: "permission.wait", + parentId: "t1", + startNs: 2100n, + endNs: 2500n, + }), + span({ + id: "k1", + name: "tool", + parentId: "t1", + startNs: 2500n, + endNs: 3200n, + tags: { tool_id: "read_file" }, + }), + span({ + id: "k2", + name: "tool", + parentId: "t1", + startNs: 3300n, + endNs: 3800n, + tags: { tool_id: "edit_file" }, + }), + ]; +} + +/** Expected turn rollup for multiToolTurnFixture (locked golden values). */ +export const MULTI_TOOL_TURN_GOLDEN = { + turnId: "t1", + turnNs: 5000, + open: false, + inferenceNs: 2000, + toolNs: 1200, + ttftNs: 400, + streamNs: 1600, + toolCount: 2, +} as const; From a72f16a56a5289b93e40277a476eb260b16f1aaa Mon Sep 17 00:00:00 2001 From: Sawyer Cutler Date: Tue, 4 Aug 2026 09:07:32 -0700 Subject: [PATCH 2/2] Harden PerfTrace eval harness asserts and negative coverage Replace the live no-op relative-magnitude check with real wall ordering, add fail-path tests for assert helpers, drop pure rollup arithmetic re-tests, and document assert layer ownership vs rollup.test.ts. --- src/perf/assert-spans.test.ts | 163 +++++++++++++++++++++++++--------- src/perf/assert-spans.ts | 19 +++- 2 files changed, 135 insertions(+), 47 deletions(-) diff --git a/src/perf/assert-spans.test.ts b/src/perf/assert-spans.test.ts index c225e62f1..1ca284142 100644 --- a/src/perf/assert-spans.test.ts +++ b/src/perf/assert-spans.test.ts @@ -1,5 +1,13 @@ /** - * Latency eval harness: assert on PerfTrace phase presence and relative magnitudes. + * Latency eval harness: assert helpers over PerfTrace snapshots and rollups. + * + * This layer owns: + * - assert API behavior (pass paths + negative branches) + * - golden multi-tool fixture equality (locked TurnSummary) + * - one end-to-end smoke: reactor observer → snapshot → rollup → asserts + * + * Rollup arithmetic (phase totals, sessionTotals, percentiles) lives in + * rollup.test.ts — do not re-test pure rollup math here. * * Covers CL-5174 outcomes: * - phase presence + nesting helpers @@ -23,7 +31,7 @@ import { } from "./fixtures/multi-tool-turn.js"; import { ALLOWED_TAG_KEYS, clear, snapshot, type PerfSpan } from "./index.js"; import { createPerfReactorObserver } from "./reactor-spans.js"; -import { rollupByPhase, rollupByTurn, sessionTotals } from "./rollup.js"; +import { rollupByPhase, rollupByTurn, type TurnSummary } from "./rollup.js"; afterEach(() => { clear(); @@ -50,6 +58,19 @@ function completed(spans: PerfSpan[]): PerfSpan[] { return spans.filter((s) => s.endNs !== undefined); } +function turnSummary(partial: Partial & Pick): TurnSummary { + return { + turnNs: 1000, + open: false, + inferenceNs: 500, + toolNs: 200, + ttftNs: 100, + streamNs: 400, + toolCount: 1, + ...partial, + }; +} + describe("assertPhasePresent / assertNesting", () => { test("assertPhasePresent finds phases on the golden fixture", () => { const spans = multiToolTurnFixture(); @@ -67,8 +88,9 @@ describe("assertPhasePresent / assertNesting", () => { ); }); - test("assertNesting verifies parent-child links", () => { + test("assertNesting verifies parent-child links (child, parent arg order)", () => { const spans = multiToolTurnFixture(); + // child first, then expected parent assertNesting(spans, "inference", "turn"); assertNesting(spans, "inference.ttft", "inference"); assertNesting(spans, "inference.stream", "inference"); @@ -83,58 +105,109 @@ describe("assertPhasePresent / assertNesting", () => { }); }); -describe("golden multi-tool turn fixture", () => { - test("rollupByTurn matches locked golden values", () => { - const turns = rollupByTurn(multiToolTurnFixture()); - expect(turns).toHaveLength(1); - expect(turns[0]).toEqual({ ...MULTI_TOOL_TURN_GOLDEN }); - }); - - test("fixture tags are privacy-safe (allowlisted keys only)", () => { - for (const span of multiToolTurnFixture()) { - if (span.tags === undefined) continue; - for (const key of Object.keys(span.tags)) { - expect(ALLOWED_TAG_KEY_SET.has(key)).toBe(true); - } - } - }); - - test("phase rollup reports expected counts and totals", () => { +describe("assertPhaseSummary", () => { + test("passes on golden phase rollup with minCount and minTotalNs", () => { const phases = rollupByPhase(multiToolTurnFixture()); assertPhaseSummary(phases, "turn", { minCount: 1, minTotalNs: 5000 }); assertPhaseSummary(phases, "inference", { minCount: 1, minTotalNs: 2000 }); assertPhaseSummary(phases, "tool", { minCount: 2, minTotalNs: 1200 }); assertPhaseSummary(phases, "permission.wait", { minCount: 1, minTotalNs: 400 }); }); + + test("throws when phase summary is missing", () => { + const phases = rollupByPhase(multiToolTurnFixture()); + expect(() => assertPhaseSummary(phases, "subagent")).toThrow( + /expected phase summary "subagent"/, + ); + }); + + test("throws when count is below minCount", () => { + const phases = rollupByPhase(multiToolTurnFixture()); + expect(() => assertPhaseSummary(phases, "tool", { minCount: 3 })).toThrow( + /phase "tool": expected count >= 3/, + ); + }); + + test("throws when totalNs is below minTotalNs", () => { + const phases = rollupByPhase(multiToolTurnFixture()); + expect(() => + assertPhaseSummary(phases, "inference", { minTotalNs: 999_999 }), + ).toThrow(/phase "inference": expected totalNs >= 999999/); + }); +}); + +describe("assertLessThan", () => { + test("passes when left < right", () => { + assertLessThan(400, 1600, "ttft vs stream"); + }); + + test("throws when left >= right", () => { + expect(() => assertLessThan(1600, 400, "ttft vs stream")).toThrow( + /ttft vs stream: expected 1600 < 400/, + ); + expect(() => assertLessThan(5, 5, "eq")).toThrow(/eq: expected 5 < 5/); + }); }); -describe("regression: turn has inference + tools when tools ran", () => { - test("assertTurnHasInferenceAndTools passes on multi-tool golden rollup", () => { +describe("assertTurnHasInferenceAndTools", () => { + test("passes on multi-tool golden rollup", () => { const turns = rollupByTurn(multiToolTurnFixture()); assertTurnHasInferenceAndTools(turns[0]!); + assertTurnHasInferenceAndTools(turns[0]!, { minToolCount: 2 }); }); - test("assertTurnHasInferenceAndTools fails when tools did not run", () => { + test("throws when inferenceNs is not positive", () => { + expect(() => + assertTurnHasInferenceAndTools(turnSummary({ turnId: "t-no-inf", inferenceNs: 0 })), + ).toThrow(/turn t-no-inf: expected inferenceNs > 0/); + }); + + test("throws when toolCount is below minimum", () => { + const noTools = turnSummary({ turnId: "t-no-tools", toolCount: 0, toolNs: 0 }); + expect(() => assertTurnHasInferenceAndTools(noTools)).toThrow( + /turn t-no-tools: expected toolCount >= 1/, + ); + + const oneTool = turnSummary({ turnId: "t-one", toolCount: 1, toolNs: 100 }); + expect(() => assertTurnHasInferenceAndTools(oneTool, { minToolCount: 2 })).toThrow( + /turn t-one: expected toolCount >= 2/, + ); + }); + + test("throws when toolNs is not positive despite toolCount", () => { + expect(() => + assertTurnHasInferenceAndTools( + turnSummary({ turnId: "t-zero-tool-ns", toolCount: 1, toolNs: 0 }), + ), + ).toThrow(/turn t-zero-tool-ns: expected toolNs > 0/); + }); + + test("fails when tools are filtered out of the golden fixture", () => { const spans: PerfSpan[] = multiToolTurnFixture().filter((s) => s.name !== "tool"); const turns = rollupByTurn(spans); expect(() => assertTurnHasInferenceAndTools(turns[0]!)).toThrow(/toolCount/); }); +}); - test("TTFT is less than stream on the golden fixture", () => { - const turn = rollupByTurn(multiToolTurnFixture())[0]!; - assertLessThan(turn.ttftNs, turn.streamNs, "ttft vs stream"); - expect(turn.ttftNs).toBe(400); - expect(turn.streamNs).toBe(1600); +describe("golden multi-tool turn fixture", () => { + test("rollupByTurn matches locked golden values", () => { + const turns = rollupByTurn(multiToolTurnFixture()); + expect(turns).toHaveLength(1); + expect(turns[0]).toEqual({ ...MULTI_TOOL_TURN_GOLDEN }); + }); + + test("fixture tags are privacy-safe (allowlisted keys only)", () => { + for (const span of multiToolTurnFixture()) { + if (span.tags === undefined) continue; + for (const key of Object.keys(span.tags)) { + expect(ALLOWED_TAG_KEY_SET.has(key)).toBe(true); + } + } }); - test("session totals include tool and inference cost", () => { - const totals = sessionTotals(multiToolTurnFixture()); - expect(totals.turnCount).toBe(1); - expect(totals.totalInferenceNs).toBe(2000); - expect(totals.totalToolNs).toBe(1200); - expect(totals.totalToolCount).toBe(2); - expect(totals.ttftShare).toBeCloseTo(0.2, 5); - expect(totals.streamShare).toBeCloseTo(0.8, 5); + test("TTFT is strictly less than stream on the golden fixture", () => { + const turn = rollupByTurn(multiToolTurnFixture())[0]!; + assertLessThan(turn.ttftNs, turn.streamNs, "ttft vs stream"); }); }); @@ -170,16 +243,18 @@ describe("observer pipeline → snapshot → rollup → assertions", () => { const turns = rollupByTurn(spans); expect(turns).toHaveLength(1); - assertTurnHasInferenceAndTools(turns[0]!); + assertTurnHasInferenceAndTools(turns[0]!, { minToolCount: 2 }); expect(turns[0]!.toolCount).toBe(2); - // Live clock: TTFT ends at/before stream starts, so ttftNs should be <= streamNs - // only when both are positive; with real hrtime, stream wall is typically longer. - if (turns[0]!.ttftNs > 0 && turns[0]!.streamNs > 0) { - // Relative magnitude: first-token wait should not dominate a multi-token stream - // in the happy path (stream duration is from first token to done). - expect(turns[0]!.streamNs).toBeGreaterThanOrEqual(0); - expect(turns[0]!.ttftNs).toBeGreaterThanOrEqual(0); + // Live clock: duration magnitudes are non-deterministic under sync hrtime + // (ttftNs can exceed streamNs). Assert wall ordering instead of a no-op + // `>= 0` check: TTFT must end at or before stream starts when both exist. + const ttft = spans.find((s) => s.name === "inference.ttft"); + const stream = spans.find((s) => s.name === "inference.stream"); + expect(ttft?.endNs).toBeDefined(); + expect(stream?.startNs).toBeDefined(); + if (ttft!.endNs !== undefined && stream !== undefined) { + expect(ttft!.endNs <= stream.startNs).toBe(true); } const phases = rollupByPhase(spans); diff --git a/src/perf/assert-spans.ts b/src/perf/assert-spans.ts index 08fa7c8cf..91949c968 100644 --- a/src/perf/assert-spans.ts +++ b/src/perf/assert-spans.ts @@ -26,6 +26,10 @@ export function assertPhasePresent( /** * Verify at least one span named `childName` is nested under a span named * `parentName` (via parentId → id). + * + * Arg order: (spans, child, parent) — the nested phase first, then its expected + * parent. Example: `assertNesting(spans, "inference", "turn")` means an + * inference span has parentId pointing at a turn span. */ export function assertNesting( spans: readonly PerfSpan[], @@ -45,19 +49,28 @@ export function assertNesting( } } +export type TurnInferenceToolsOpts = { + /** Minimum tool invocations required (default 1). */ + minToolCount?: number; +}; + /** * Regression: a turn that ran tools must report positive inference and tool cost. * Accepts a single TurnSummary (from rollupByTurn). */ -export function assertTurnHasInferenceAndTools(turn: TurnSummary): void { +export function assertTurnHasInferenceAndTools( + turn: TurnSummary, + opts?: TurnInferenceToolsOpts, +): void { + const minToolCount = opts?.minToolCount ?? 1; if (turn.inferenceNs <= 0) { throw new Error( `turn ${turn.turnId}: expected inferenceNs > 0, got ${turn.inferenceNs}`, ); } - if (turn.toolCount <= 0) { + if (turn.toolCount < minToolCount) { throw new Error( - `turn ${turn.turnId}: expected toolCount > 0 when tools ran, got ${turn.toolCount}`, + `turn ${turn.turnId}: expected toolCount >= ${minToolCount} when tools ran, got ${turn.toolCount}`, ); } if (turn.toolNs <= 0) {