diff --git a/docs/PERFTRACE.md b/docs/PERFTRACE.md index bb10d18e3..40af03637 100644 --- a/docs/PERFTRACE.md +++ b/docs/PERFTRACE.md @@ -13,9 +13,12 @@ PostHog usage events. - Offline dumps: `dumpSpans` + `rollupByPhase` / `rollupByTurn` / `sessionTotals` (`src/perf/dump.ts`, `src/perf/rollup.ts`) — same tag allowlist; never include OTEL auth headers +- Attribution report: `bun scripts/perf-report.ts ` — see + [`perftrace-attribution-guide.md`](./perftrace-attribution-guide.md) Local measurement does not require any settings or env vars. + ## OTEL export (opt-in) Export is **off** until an OTLP endpoint is configured. When enabled, traces go diff --git a/docs/perftrace-attribution-guide.md b/docs/perftrace-attribution-guide.md new file mode 100644 index 000000000..f42bade0b --- /dev/null +++ b/docs/perftrace-attribution-guide.md @@ -0,0 +1,189 @@ +# PerfTrace attribution guide + +How to capture a slow session, dump local spans, and run the offline attribution +report. No OTEL collector, no PostHog, no network. + +See also: [`PERFTRACE.md`](./PERFTRACE.md) for the span model, dump schema, and +`jq` recipes. + +## Why this exists + +When a session feels slow, the first question is **where the wall time went**: + +| Category | Meaning | +|---|---| +| `inference` | Model call wall (`inference` spans). Nested `inference.ttft` vs `inference.stream` show wait-for-first-token vs rest of stream. | +| `tools` | Tool invocations under the turn. | +| `permission.wait` | Ask-gate / approval idle time (when instrumented). | +| `subagent` | Child agent lifetimes (fanout cost). | +| `other` | Turn wall not covered by the above — scheduling, TUI, un-instrumented work, gaps between phases. | + +Shares are **exclusive** over turn wall. For **completed** turns, wall is +`end − start`. For **open** (still-running) turns — including mid-stall dumps — +wall is estimated as `max(completed-descendant endNs) − turn.startNs` so shares +stay meaningful, and the report lists **open phase names** (e.g. +`inference.stream`, `turn`) so completed-only shares are not read as a full +stall diagnosis. + +Nested exclusive children under an exclusive parent (e.g. `tool` / +`inference` under `subagent`) count only toward the parent exclusive bucket — +they are not double-counted. Nested TTFT/stream and `adapter.transport` are +diagnostic splits (they are not added on top of `inference` in the exclusive +table). TTFT/stream shares use **(ttft + stream)** as the denominator, not +inference wall. + + +## Capture a real slow session + +1. Prefer a repro that exercises the pain: high reasoning, several tools, and + (if relevant) subagents or permission prompts. +2. Run Corbits Code normally. PerfTrace is always-on in-process; there is no + settings toggle. +3. When the session stalls or finishes slowly, dump the ring next to session + artifacts. + +```ts +import { snapshot } from "../src/perf/index.js"; +import { dumpSpans } from "../src/perf/dump.js"; + +const path = await dumpSpans(snapshot(), { + dir: ".agent-state/", + sessionId: "", +}); +// → .agent-state//perftrace-.json +``` + +The dump is privacy-strict (allowlisted tags only). Safe to keep offline or +share with teammates without prompts/paths. + +## Run the attribution report + +From a local dump file alone: + +```bash +bun scripts/perf-report.ts .agent-state//perftrace-.json +``` + +Machine-readable JSON: + +```bash +bun scripts/perf-report.ts --json .agent-state//perftrace-.json +``` + +Golden multi-tool demo (no dump file needed — uses +`src/perf/fixtures/multi-tool-turn.ts`): + +```bash +bun scripts/perf-report.ts --fixture +``` + +Example fixture output (fixture ns values are tiny — formatter prints sub-ms): + +``` +PerfTrace attribution report +─────────────────────────── +Session wall: 0.005ms turns=1 (completed=1) + +Exclusive phase shares (of session wall): + inference 40.0% 0.002ms n=1 + tools 24.0% 0.001ms n=2 + permission.wait 8.0% 0.000ms + subagent 0.0% 0ms + other 28.0% 0.001ms +... +``` + + +## How to read the report + +1. **Session exclusive shares** — which bucket ate the turn wall. A large + `inference` share with high `ttft` points at model queueing / cold start. A + large `tools` share with high `n=` points at tool work. A large + `permission.wait` share is human/ask-gate idle, not model or tool code. +2. **Open / incomplete** — if the report says `Open (incomplete)` and lists + still-running phases, exclusive shares only cover completed descendants. + Treat open phase names as the hang candidates; do not conclude from the + exclusive table alone. +3. **`other` large** — either real un-instrumented cost (TUI, scheduling) or + gaps between instrumented phases. If `other` dominates a pain session, add + spans before optimizing transport. +4. **TTFT vs stream** — of `ttft + stream` only (not inference wall). High TTFT + share → time-to-first-token problem. High stream share → long generation or + slow token delivery. +5. **Transport signal** — `adapter.transport / inference`. When transport is a + large fraction of inference wall, prioritize transport work (WebSocket / + incremental input). When it is small, transport is not the bottleneck. +6. **Per-turn rows** — find the outlier turn when the session average looks fine + but one turn felt stuck. Open turns print `open phases:` explicitly. +7. **Subagent count + share** — fanout cost. High subagent share means child + agents as a whole (nested tools/inference under the subagent are inside that + bucket, not double-counted as parent tools/inference). + +### What “large transport share” looks like + +| transportShareOfInference | Reading | +|---|---| +| ≈ 0 or missing | Adapter did not emit `adapter.transport`, or transport was negligible. Do not prioritize WebSocket/incremental input on this evidence alone. | +| Low (e.g. < 10–15%) | Most inference wall is model/server time, not client transport. Prefer model/TTFT or tool work. | +| High (e.g. > 25–30% of inference, sustained across turns) | Client transport is a meaningful slice of inference wall — candidate for WebSocket / incremental input priority. | + +Always pair with absolute ms: a 40% share of a 50ms inference is noise; 40% of a +8s inference is a product decision. + +## Decision note template (transport prioritization) + +Copy into a Linear issue or PR when a pain dump suggests transport investment. + +```markdown +## Decision: WebSocket / incremental input priority? + +**Session / dump:** +**Report command:** `bun scripts/perf-report.ts ` + +### Evidence +- Session wall: +- Exclusive shares: inference <%> · tools <%> · permission.wait <%> · subagent <%> · other <%> +- TTFT share of (ttft+stream): <%> +- Stream share of (ttft+stream): <%> +- `adapter.transport` ns: · share of inference: <%> +- Turns examined: ; outlier turn id: + +### Reading +- [ ] Transport share is **high** and absolute transport ms is user-visible + → prioritize WebSocket / incremental input (or adapter transport work). +- [ ] Transport share is **low / missing**; inference TTFT or tools dominate + → do **not** prioritize transport; focus on . +- [ ] `other` or missing instrumentation dominates + → instrument first; decide after a second dump. + +### Decision +- Priority: transport work this cycle +- Owner: +- Follow-up: +``` + +## API (programmatic) + +```ts +import { + attributionFromSpans, + attributionFromDump, + formatAttributionReport, +} from "../src/perf/attribution-report.js"; +import { snapshot } from "../src/perf/index.js"; + +const report = attributionFromSpans(snapshot()); +console.log(formatAttributionReport(report)); +// or: attributionFromDump(JSON.parse(await readFile(path, "utf8"))) +``` + +Pure functions — safe in tests and evals. The multi-tool golden fixture locks +expected ns values in `src/perf/fixtures/multi-tool-turn.ts` and +`src/perf/attribution-report.test.ts`. + +## Related + +- `src/perf/rollup.ts` — phase / turn / session totals +- `src/perf/dump.ts` — `dumpSpans` / `buildDump` +- `src/perf/attribution-report.ts` — exclusive shares + formatter +- `scripts/perf-report.ts` — CLI entrypoint diff --git a/scripts/perf-report.ts b/scripts/perf-report.ts new file mode 100644 index 000000000..a9b670d6f --- /dev/null +++ b/scripts/perf-report.ts @@ -0,0 +1,94 @@ +#!/usr/bin/env bun +/** + * Offline PerfTrace attribution report. + * + * Reads a dump JSON written by dumpSpans() (or a bare spans array) and prints + * exclusive phase shares: inference / tools / permission.wait / subagent / other. + * No network, no OTEL, no PostHog. + * + * Usage: + * bun scripts/perf-report.ts + * bun scripts/perf-report.ts --json + * bun scripts/perf-report.ts --fixture # golden multi-tool demo + */ + +import { readFile } from "node:fs/promises"; +import { resolve } from "node:path"; +import { + attributionFromDump, + attributionFromSpans, + formatAttributionReport, + type AttributionReport, +} from "../src/perf/attribution-report.js"; +import { multiToolTurnFixture } from "../src/perf/fixtures/multi-tool-turn.js"; + +function printUsage(): void { + console.error(`Usage: + bun scripts/perf-report.ts + bun scripts/perf-report.ts --json # machine-readable AttributionReport + bun scripts/perf-report.ts --fixture # demo on multi-tool golden fixture +`); +} + +function emit(report: AttributionReport, asJson: boolean): void { + if (asJson) { + console.log(JSON.stringify(report, null, 2)); + } else { + process.stdout.write(formatAttributionReport(report)); + } +} + +async function main(argv: string[]): Promise { + const args = argv.slice(2); + if (args.length === 0 || args.includes("-h") || args.includes("--help")) { + printUsage(); + return args.length === 0 ? 1 : 0; + } + + const asJson = args.includes("--json"); + const useFixture = args.includes("--fixture"); + const pathArg = args.find((a) => !a.startsWith("-")); + + if (useFixture) { + const report = attributionFromSpans(multiToolTurnFixture()); + emit(report, asJson); + return 0; + } + + if (pathArg === undefined) { + printUsage(); + return 1; + } + + const filePath = resolve(pathArg); + let rawText: string; + try { + rawText = await readFile(filePath, "utf8"); + } catch (err) { + const msg = err instanceof Error ? err.message : String(err); + console.error(`perf-report: failed to read ${filePath}: ${msg}`); + return 1; + } + + let parsed: unknown; + try { + parsed = JSON.parse(rawText); + } catch (err) { + const msg = err instanceof Error ? err.message : String(err); + console.error(`perf-report: invalid JSON in ${filePath}: ${msg}`); + return 1; + } + + try { + const report = attributionFromDump(parsed); + emit(report, asJson); + return 0; + } catch (err) { + const msg = err instanceof Error ? err.message : String(err); + console.error(`perf-report: ${msg}`); + return 1; + } +} + +const code = await main(process.argv); +process.exit(code); diff --git a/src/perf/attribution-report.test.ts b/src/perf/attribution-report.test.ts new file mode 100644 index 000000000..fd70d3817 --- /dev/null +++ b/src/perf/attribution-report.test.ts @@ -0,0 +1,486 @@ +import { describe, expect, test } from "bun:test"; +import { + attributionFromDump, + attributionFromSpans, + categoryShare, + deserializeDumpSpan, + formatAttributionReport, + spansFromDumpJson, +} from "./attribution-report.js"; +import { DUMP_VERSION, buildDump, serializeSpan } from "./dump.js"; +import { + MULTI_TOOL_TURN_GOLDEN, + multiToolTurnFixture, +} from "./fixtures/multi-tool-turn.js"; +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; +} + +describe("attributionFromSpans — multi-tool golden fixture", () => { + test("exclusive shares match locked fixture durations", () => { + const report = attributionFromSpans(multiToolTurnFixture()); + const g = MULTI_TOOL_TURN_GOLDEN; + + expect(report.session.turnCount).toBe(1); + expect(report.session.completedTurnCount).toBe(1); + expect(report.session.wallNs).toBe(g.turnNs); + expect(report.session.toolCount).toBe(g.toolCount); + + const inf = categoryShare(report.session.categories, "inference"); + const tools = categoryShare(report.session.categories, "tools"); + const perm = categoryShare(report.session.categories, "permission.wait"); + const sub = categoryShare(report.session.categories, "subagent"); + const other = categoryShare(report.session.categories, "other"); + + // turn 5000; inference 2000; tools 1200; permission 400 → other 1400 + expect(inf.ns).toBe(g.inferenceNs); + expect(tools.ns).toBe(g.toolNs); + expect(perm.ns).toBe(400); + expect(sub.ns).toBe(0); + expect(other.ns).toBe(1400); + + expect(inf.share).toBeCloseTo(2000 / 5000, 10); + expect(tools.share).toBeCloseTo(1200 / 5000, 10); + expect(perm.share).toBeCloseTo(400 / 5000, 10); + expect(other.share).toBeCloseTo(1400 / 5000, 10); + + const shareSum = report.session.categories.reduce((a, c) => a + c.share, 0); + expect(shareSum).toBeCloseTo(1, 10); + }); + + test("ttft vs stream split matches golden", () => { + const report = attributionFromSpans(multiToolTurnFixture()); + const g = MULTI_TOOL_TURN_GOLDEN; + expect(report.session.inference.ttftNs).toBe(g.ttftNs); + expect(report.session.inference.streamNs).toBe(g.streamNs); + expect(report.session.inference.ttftShare).toBeCloseTo(400 / 2000, 10); + expect(report.session.inference.streamShare).toBeCloseTo(1600 / 2000, 10); + }); + + test("per-turn row mirrors session for single-turn fixture", () => { + const report = attributionFromSpans(multiToolTurnFixture()); + expect(report.turns).toHaveLength(1); + const t = report.turns[0]!; + expect(t.turnId).toBe("t1"); + expect(t.turnNs).toBe(5000); + expect(t.open).toBe(false); + expect(categoryShare(t.categories, "inference").ns).toBe(2000); + expect(categoryShare(t.categories, "tools").ns).toBe(1200); + expect(categoryShare(t.categories, "permission.wait").ns).toBe(400); + expect(categoryShare(t.categories, "other").ns).toBe(1400); + expect(t.toolCount).toBe(2); + expect(t.subagentCount).toBe(0); + }); +}); + +describe("attributionFromSpans — subagent + transport", () => { + test("attributes subagent fanout and transport share of inference", () => { + const spans: PerfSpan[] = [ + span({ id: "t1", name: "turn", startNs: 0n, endNs: 10_000n }), + span({ + id: "i1", + name: "inference", + parentId: "t1", + startNs: 0n, + endNs: 4000n, + }), + span({ + id: "ttft1", + name: "inference.ttft", + parentId: "i1", + startNs: 0n, + endNs: 1000n, + }), + span({ + id: "stream1", + name: "inference.stream", + parentId: "i1", + startNs: 1000n, + endNs: 4000n, + }), + span({ + id: "tr1", + name: "adapter.transport", + parentId: "i1", + startNs: 0n, + endNs: 800n, + tags: { transport: "http_sse" }, + }), + span({ + id: "sa1", + name: "subagent", + parentId: "t1", + startNs: 4000n, + endNs: 7000n, + }), + span({ + id: "k1", + name: "tool", + parentId: "t1", + startNs: 7000n, + endNs: 8000n, + }), + ]; + + const report = attributionFromSpans(spans); + expect(categoryShare(report.session.categories, "inference").ns).toBe(4000); + expect(categoryShare(report.session.categories, "subagent").ns).toBe(3000); + expect(categoryShare(report.session.categories, "tools").ns).toBe(1000); + // other = 10000 - 4000 - 1000 - 0 - 3000 = 2000 + expect(categoryShare(report.session.categories, "other").ns).toBe(2000); + expect(report.session.subagentCount).toBe(1); + expect(report.session.transportNs).toBe(800); + expect(report.session.transportShareOfInference).toBeCloseTo(800 / 4000, 10); + expect(report.session.open).toBe(false); + expect(report.session.openPhases).toEqual([]); + }); + + test("nested exclusive under subagent does not double-count (share sum ≈ 1)", () => { + // turn 10_000 + // inference 2000 (top-level exclusive) + // subagent 6000 containing nested inference 2500 + tools 1500 + // tool 1000 (sibling exclusive) + // Exclusive: inference=2000, subagent=6000, tools=1000, other=1000 + // Nested under subagent must NOT add 2500+1500 into exclusive buckets. + const spans: PerfSpan[] = [ + span({ id: "t1", name: "turn", startNs: 0n, endNs: 10_000n }), + span({ + id: "i1", + name: "inference", + parentId: "t1", + startNs: 0n, + endNs: 2000n, + }), + span({ + id: "ttft1", + name: "inference.ttft", + parentId: "i1", + startNs: 0n, + endNs: 400n, + }), + span({ + id: "stream1", + name: "inference.stream", + parentId: "i1", + startNs: 400n, + endNs: 2000n, + }), + span({ + id: "sa1", + name: "subagent", + parentId: "t1", + startNs: 2000n, + endNs: 8000n, + }), + span({ + id: "sa_i1", + name: "inference", + parentId: "sa1", + startNs: 2000n, + endNs: 4500n, + }), + span({ + id: "sa_ttft", + name: "inference.ttft", + parentId: "sa_i1", + startNs: 2000n, + endNs: 2500n, + }), + span({ + id: "sa_stream", + name: "inference.stream", + parentId: "sa_i1", + startNs: 2500n, + endNs: 4500n, + }), + span({ + id: "sa_k1", + name: "tool", + parentId: "sa1", + startNs: 4500n, + endNs: 6000n, + }), + span({ + id: "k1", + name: "tool", + parentId: "t1", + startNs: 8000n, + endNs: 9000n, + }), + ]; + + const report = attributionFromSpans(spans); + const inf = categoryShare(report.session.categories, "inference"); + const tools = categoryShare(report.session.categories, "tools"); + const sub = categoryShare(report.session.categories, "subagent"); + const other = categoryShare(report.session.categories, "other"); + + expect(inf.ns).toBe(2000); + expect(sub.ns).toBe(6000); + expect(tools.ns).toBe(1000); // only the top-level tool, not sa_k1 + expect(other.ns).toBe(1000); // 10000 - 2000 - 6000 - 1000 + expect(inf.count).toBe(1); // nested inference under subagent not counted + expect(sub.count).toBe(1); + // toolCount still sees nested tools for visibility + expect(report.session.toolCount).toBe(2); + expect(report.session.subagentCount).toBe(1); + + const shareSum = report.session.categories.reduce((a, c) => a + c.share, 0); + expect(shareSum).toBeCloseTo(1, 10); + + // Nested diagnostics still roll up (parent + subagent ttft/stream) + expect(report.session.inference.ttftNs).toBe(400 + 500); + expect(report.session.inference.streamNs).toBe(1600 + 2000); + + const turnShareSum = report.turns[0]!.categories.reduce( + (a, c) => a + c.share, + 0, + ); + expect(turnShareSum).toBeCloseTo(1, 10); + }); +}); + +describe("attributionFromSpans — open (stall) turns", () => { + test("open turn wall is max completed-descendant end minus turn start", () => { + // Mid-stall dump: turn still open; inference + tool completed; stream still open. + const spans: PerfSpan[] = [ + span({ id: "t1", name: "turn", startNs: 100n }), // open + span({ + id: "i1", + name: "inference", + parentId: "t1", + startNs: 100n, + endNs: 2100n, // 2000ns + }), + span({ + id: "ttft1", + name: "inference.ttft", + parentId: "i1", + startNs: 100n, + endNs: 500n, + }), + span({ + id: "stream1", + name: "inference.stream", + parentId: "i1", + startNs: 500n, // still open — contributes 0 to streamNs + }), + span({ + id: "k1", + name: "tool", + parentId: "t1", + startNs: 2100n, + endNs: 3100n, // 1000ns; max end → wall = 3100 - 100 = 3000 + }), + ]; + + const report = attributionFromSpans(spans); + expect(report.session.completedTurnCount).toBe(0); + expect(report.session.turnCount).toBe(1); + // wall = maxEnd(3100) - start(100) = 3000 + expect(report.session.wallNs).toBe(3000); + expect(report.turns[0]!.open).toBe(true); + expect(report.turns[0]!.turnNs).toBe(3000); + expect(report.session.open).toBe(true); + // Still-running: turn + open stream (completed inference/tool are not listed) + expect(report.session.openPhases).toEqual(["inference.stream", "turn"]); + expect(report.turns[0]!.openPhases).toEqual(["inference.stream", "turn"]); + + expect(categoryShare(report.session.categories, "inference").ns).toBe(2000); + expect(categoryShare(report.session.categories, "tools").ns).toBe(1000); + // other = 3000 - 2000 - 1000 = 0 + expect(categoryShare(report.session.categories, "other").ns).toBe(0); + + const shareSum = report.session.categories.reduce((a, c) => a + c.share, 0); + expect(shareSum).toBeCloseTo(1, 10); + + const turnShareSum = report.turns[0]!.categories.reduce((a, c) => a + c.share, 0); + expect(turnShareSum).toBeCloseTo(1, 10); + }); + + test("mixed completed + open turns: session shares sum to ~1", () => { + const spans: PerfSpan[] = [ + // completed turn: wall 5000 + span({ id: "t0", name: "turn", startNs: 0n, endNs: 5000n }), + span({ + id: "i0", + name: "inference", + parentId: "t0", + startNs: 0n, + endNs: 3000n, + }), + span({ + id: "k0", + name: "tool", + parentId: "t0", + startNs: 3000n, + endNs: 4000n, + }), + // open stall turn: estimated wall 2000 (max end 7000 - start 5000) + span({ id: "t1", name: "turn", startNs: 5000n }), + span({ + id: "i1", + name: "inference", + parentId: "t1", + startNs: 5000n, + endNs: 6500n, // 1500 + }), + span({ + id: "k1", + name: "tool", + parentId: "t1", + startNs: 6500n, + endNs: 7000n, // 500; max end → wall 2000 + }), + span({ + id: "stream1", + name: "inference.stream", + parentId: "i1", + startNs: 5500n, // open child — 0 duration + }), + ]; + + const report = attributionFromSpans(spans); + expect(report.session.completedTurnCount).toBe(1); + expect(report.session.turnCount).toBe(2); + // wall = 5000 + 2000 = 7000 + expect(report.session.wallNs).toBe(7000); + // inference 3000+1500=4500; tools 1000+500=1500; other = 7000-6000=1000 + expect(categoryShare(report.session.categories, "inference").ns).toBe(4500); + expect(categoryShare(report.session.categories, "tools").ns).toBe(1500); + expect(categoryShare(report.session.categories, "other").ns).toBe(1000); + + const shareSum = report.session.categories.reduce((a, c) => a + c.share, 0); + expect(shareSum).toBeCloseTo(1, 10); + + const openTurn = report.turns.find((t) => t.turnId === "t1")!; + expect(openTurn.open).toBe(true); + expect(openTurn.turnNs).toBe(2000); + const openShareSum = openTurn.categories.reduce((a, c) => a + c.share, 0); + expect(openShareSum).toBeCloseTo(1, 10); + }); + + test("open turn with no completed descendants has zero wall and zero shares", () => { + const spans: PerfSpan[] = [ + span({ id: "t1", name: "turn", startNs: 0n }), + span({ + id: "i1", + name: "inference", + parentId: "t1", + startNs: 0n, // still open + }), + ]; + const report = attributionFromSpans(spans); + expect(report.session.wallNs).toBe(0); + expect(report.turns[0]!.open).toBe(true); + expect(report.turns[0]!.turnNs).toBe(0); + expect(report.session.open).toBe(true); + expect(report.session.openPhases).toEqual(["inference", "turn"]); + expect(report.turns[0]!.openPhases).toEqual(["inference", "turn"]); + for (const c of report.session.categories) { + expect(c.share).toBe(0); + expect(c.ns).toBe(0); + } + }); +}); + +describe("dump round-trip", () => { + test("attributionFromDump matches live spans", () => { + const spans = multiToolTurnFixture(); + const dump = buildDump(spans, "fixture-multi", "2026-04-08T00:00:00.000Z"); + const fromDump = attributionFromDump(dump); + const live = attributionFromSpans(spans); + + expect(fromDump.session.wallNs).toBe(live.session.wallNs); + expect(fromDump.session.categories).toEqual(live.session.categories); + expect(fromDump.session.inference).toEqual(live.session.inference); + expect(fromDump.turns).toEqual(live.turns); + }); + + test("spansFromDumpJson accepts bare span arrays", () => { + const serialized = multiToolTurnFixture().map(serializeSpan); + const spans = spansFromDumpJson(serialized); + expect(spans).toHaveLength(7); + expect(spans[0]!.startNs).toBe(0n); + expect(deserializeDumpSpan(serialized[0]!).id).toBe("t1"); + }); + + test("attributionFromDump rejects unsupported DUMP_VERSION", () => { + const dump = buildDump( + multiToolTurnFixture(), + "fixture-multi", + "2026-04-08T00:00:00.000Z", + ); + expect(() => + attributionFromDump({ ...dump, version: DUMP_VERSION + 1 }), + ).toThrow(/unsupported dump version/); + }); +}); + +describe("formatAttributionReport", () => { + test("prints category labels and percentages for the golden fixture", () => { + const text = formatAttributionReport( + attributionFromSpans(multiToolTurnFixture()), + ); + expect(text).toContain("PerfTrace attribution report"); + expect(text).toContain("inference"); + expect(text).toContain("tools"); + expect(text).toContain("permission.wait"); + expect(text).toContain("subagent"); + expect(text).toContain("other"); + expect(text).toContain("40.0%"); // inference 2000/5000 + expect(text).toContain("24.0%"); // tools 1200/5000 + expect(text).toContain("turn t1"); + expect(text).toContain("Inference split (of ttft+stream)"); + expect(text).not.toContain("Open (incomplete)"); + }); + + test("surfaces open phases for mid-stall dumps", () => { + const spans: PerfSpan[] = [ + span({ id: "t1", name: "turn", startNs: 0n }), + span({ + id: "i1", + name: "inference", + parentId: "t1", + startNs: 0n, + endNs: 1000n, + }), + span({ + id: "stream1", + name: "inference.stream", + parentId: "i1", + startNs: 200n, + }), + span({ + id: "k1", + name: "tool", + parentId: "t1", + startNs: 1000n, + endNs: 1500n, + }), + ]; + const text = formatAttributionReport(attributionFromSpans(spans)); + expect(text).toContain("Open (incomplete)"); + expect(text).toContain("inference.stream"); + expect(text).toContain("open phases:"); + expect(text).toContain("shares incomplete"); + expect(text).toContain("not a full stall diagnosis"); + }); +}); diff --git a/src/perf/attribution-report.ts b/src/perf/attribution-report.ts new file mode 100644 index 000000000..bd94f31f8 --- /dev/null +++ b/src/perf/attribution-report.ts @@ -0,0 +1,643 @@ +/** + * Offline attribution report over PerfSpan snapshots or PerfDump JSON. + * + * Pure functions: no I/O, no module state, no OTEL. Categories partition turn + * wall time into exclusive buckets so shares sum to ~1 (remainder → other). + * + * Exclusive buckets do not double-count nested exclusive children (e.g. tools + * under a subagent count only toward `subagent`, not also toward `tools`). + * + * Open (still-running) turns use an estimated wall: max completed-descendant + * endNs − turn.startNs. That keeps mid-stall dumps usable for share %, but + * open phase names are reported so completed-only shares are not mistaken for + * a complete stall diagnosis. + */ + +import type { PerfSpan, SpanName } from "./index.js"; +import type { DumpSpan, PerfDump } from "./dump.js"; +import { DUMP_VERSION } from "./dump.js"; +import { childrenOf, spanDurationNs, walkDescendants } from "./rollup.js"; + +/** Exclusive wall-time buckets used for session / turn share %. */ +export const ATTRIBUTION_CATEGORIES = [ + "inference", + "tools", + "permission.wait", + "subagent", + "other", +] as const; + +export type AttributionCategory = (typeof ATTRIBUTION_CATEGORIES)[number]; + +/** Span names that form the exclusive partition (not nested diagnostics). */ +const EXCLUSIVE_SPAN_NAMES: ReadonlySet = new Set([ + "inference", + "tool", + "permission.wait", + "subagent", +]); + +/** One exclusive category and its share of a denominator wall. */ +export type CategoryShare = { + category: AttributionCategory; + /** Total nanoseconds attributed to this category. */ + ns: number; + /** Share of denominator wall in [0, 1]. 0 when denominator is 0. */ + share: number; + /** Span count contributing to this category (0 for synthetic "other"). */ + count: number; +}; + +/** + * TTFT vs stream split. Shares use (ttft + stream) as the denominator — + * not inference wall (gaps / un-instrumented inference time are excluded). + */ +export type InferenceSplit = { + ttftNs: number; + streamNs: number; + /** Share of (ttft + stream). 0 when both are zero. */ + ttftShare: number; + streamShare: number; +}; + +/** Per-turn exclusive attribution. */ +export type TurnAttribution = { + turnId: string; + turnNs: number; + open: boolean; + /** + * Distinct phase names still open under this turn (and the turn itself when + * open). Empty for completed turns. Surfaces mid-stall hangs so exclusive + * shares of completed children are not read as a full diagnosis. + */ + openPhases: SpanName[]; + categories: CategoryShare[]; + inference: InferenceSplit; + toolCount: number; + subagentCount: number; + /** + * Sum of `adapter.transport` under this turn (when instrumented). + * Compared to inference wall for the transport prioritization decision. + */ + transportNs: number; + /** transportNs / inferenceNs, or 0 when inference is 0. */ + transportShareOfInference: number; +}; + +/** Session-level attribution report. */ +export type AttributionReport = { + session: { + /** + * Denominator for shares: sum of turn walls (completed turns use end−start; + * open turns use estimated wall from max completed-descendant end). + */ + wallNs: number; + /** True when any turn is still open (stall / mid-dump). */ + open: boolean; + /** + * Distinct open phase names across the session (union of per-turn openPhases). + * Empty when every turn is completed. + */ + openPhases: SpanName[]; + categories: CategoryShare[]; + inference: InferenceSplit; + toolCount: number; + subagentCount: number; + turnCount: number; + completedTurnCount: number; + transportNs: number; + transportShareOfInference: number; + }; + turns: TurnAttribution[]; +}; + +type ExclusiveBucket = { + inferenceNs: number; + toolNs: number; + permissionWaitNs: number; + subagentNs: number; + toolCount: number; + subagentCount: number; + ttftNs: number; + streamNs: number; + transportNs: number; +}; + +function emptyBucket(): ExclusiveBucket { + return { + inferenceNs: 0, + toolNs: 0, + permissionWaitNs: 0, + subagentNs: 0, + toolCount: 0, + subagentCount: 0, + ttftNs: 0, + streamNs: 0, + transportNs: 0, + }; +} + +function spanById(spans: readonly PerfSpan[]): Map { + const map = new Map(); + for (const span of spans) map.set(span.id, span); + return map; +} + +/** + * True when any ancestor of `span` is an exclusive-category span. + * Nested exclusive children (e.g. tool under subagent) must not also fill the + * exclusive tools bucket — their wall is already inside the parent exclusive. + */ +function hasExclusiveAncestor( + span: PerfSpan, + byId: Map, +): boolean { + let parentId = span.parentId; + while (parentId !== undefined) { + const parent = byId.get(parentId); + if (parent === undefined) return false; + if (EXCLUSIVE_SPAN_NAMES.has(parent.name)) return true; + parentId = parent.parentId; + } + return false; +} + +/** + * Wall for a turn span. Completed → end−start. Open → max completed-descendant + * end − turn.start (stall-dump estimate so shares stay meaningful mid-turn). + */ +export function turnWallNs( + turn: PerfSpan, + byParent: Map, +): { wallNs: number; open: boolean } { + const completed = spanDurationNs(turn); + if (completed !== undefined) { + return { wallNs: completed, open: false }; + } + + let maxEnd: bigint | undefined; + walkDescendants(turn.id, byParent, (child) => { + if (child.endNs === undefined) return; + if (maxEnd === undefined || child.endNs > maxEnd) maxEnd = child.endNs; + }); + if (maxEnd === undefined) { + return { wallNs: 0, open: true }; + } + const d = maxEnd - turn.startNs; + return { wallNs: d <= 0n ? 0 : Number(d), open: true }; +} + +/** + * Distinct open phase names under `rootId` (descendants only). Stable SPAN_NAMES + * order when known, then any remaining by name. + */ +function openPhasesUnder( + rootId: string, + byParent: Map, + includeRoot?: PerfSpan, +): SpanName[] { + const found = new Set(); + if (includeRoot !== undefined && includeRoot.endNs === undefined) { + found.add(includeRoot.name); + } + walkDescendants(rootId, byParent, (child) => { + if (child.endNs === undefined) found.add(child.name); + }); + if (found.size === 0) return []; + return [...found].sort((a, b) => a.localeCompare(b)); +} + +/** + * Accumulate metrics from a descendant span. + * + * Exclusive categories (inference / tool / permission.wait / subagent) only + * contribute ns when the span is not under another exclusive parent — so a + * nested tool under subagent does not double-count against turn wall. + * Nested diagnostics (ttft / stream / transport) and counts always accumulate. + */ +function accumulate( + bucket: ExclusiveBucket, + span: PerfSpan, + skipExclusiveNs: boolean, +): void { + const dur = spanDurationNs(span) ?? 0; + switch (span.name as SpanName) { + case "inference": + if (!skipExclusiveNs) bucket.inferenceNs += dur; + break; + case "tool": + if (!skipExclusiveNs) bucket.toolNs += dur; + bucket.toolCount += 1; + break; + case "permission.wait": + if (!skipExclusiveNs) bucket.permissionWaitNs += dur; + break; + case "subagent": + if (!skipExclusiveNs) bucket.subagentNs += dur; + bucket.subagentCount += 1; + break; + case "inference.ttft": + bucket.ttftNs += dur; + break; + case "inference.stream": + bucket.streamNs += dur; + break; + case "adapter.transport": + bucket.transportNs += dur; + break; + default: + break; + } +} + +function accumulateTree( + rootId: string, + byParent: Map, + byId: Map, + bucket: ExclusiveBucket, +): void { + walkDescendants(rootId, byParent, (child) => { + accumulate(bucket, child, hasExclusiveAncestor(child, byId)); + }); +} + +function inferenceSplit(ttftNs: number, streamNs: number): InferenceSplit { + const split = ttftNs + streamNs; + return { + ttftNs, + streamNs, + ttftShare: split === 0 ? 0 : ttftNs / split, + streamShare: split === 0 ? 0 : streamNs / split, + }; +} + +function shareOf(ns: number, wallNs: number): number { + return wallNs === 0 ? 0 : ns / wallNs; +} + +/** + * Build exclusive category shares. `other` absorbs gaps and un-instrumented wall + * (scheduling, TUI, etc.) so shares sum to 1 when wallNs > 0 and attributed ≤ wall. + * + * When attributed exceeds wall (rare parallel overlap), other is 0 and category + * shares still use wall as denominator (sum may exceed 1 — caller can detect). + */ +function categorySharesFromBucket( + bucket: ExclusiveBucket, + wallNs: number, + inferenceCount: number, + permissionWaitCount: number, +): CategoryShare[] { + const attributed = + bucket.inferenceNs + + bucket.toolNs + + bucket.permissionWaitNs + + bucket.subagentNs; + const otherNs = wallNs > 0 ? Math.max(0, wallNs - attributed) : 0; + + return [ + { + category: "inference", + ns: bucket.inferenceNs, + share: shareOf(bucket.inferenceNs, wallNs), + count: inferenceCount, + }, + { + category: "tools", + ns: bucket.toolNs, + share: shareOf(bucket.toolNs, wallNs), + count: bucket.toolCount, + }, + { + category: "permission.wait", + ns: bucket.permissionWaitNs, + share: shareOf(bucket.permissionWaitNs, wallNs), + count: permissionWaitCount, + }, + { + category: "subagent", + ns: bucket.subagentNs, + share: shareOf(bucket.subagentNs, wallNs), + count: bucket.subagentCount, + }, + { + category: "other", + ns: otherNs, + share: shareOf(otherNs, wallNs), + count: 0, + }, + ]; +} + +/** + * Count exclusive-category spans under root that are not nested under another + * exclusive parent (top-level exclusive only — matches exclusive ns accounting). + */ +function countTopExclusiveUnder( + rootId: string, + byParent: Map, + byId: Map, + name: SpanName, +): number { + let n = 0; + walkDescendants(rootId, byParent, (s) => { + if (s.name !== name) return; + if (hasExclusiveAncestor(s, byId)) return; + n += 1; + }); + return n; +} + +/** + * Attribute a PerfSpan snapshot into exclusive phase shares per turn and session. + * + * Exclusive categories (do not nest-double-count): + * inference | tools | permission.wait | subagent | other + * + * Nested exclusive children under an exclusive parent (e.g. inference/tool under + * subagent) contribute only to the parent exclusive bucket. + * + * Nested diagnostics (not exclusive): + * inference.ttft / inference.stream shares of (ttft + stream) + * adapter.transport share of inference (transport prioritization signal) + * + * Open turns: wall estimated from max completed-descendant end so mid-stall + * dumps still produce usable share percentages; openPhases lists still-running + * phases so the report is not read as a complete hang diagnosis. + */ +export function attributionFromSpans(spans: readonly PerfSpan[]): AttributionReport { + const byParent = childrenOf(spans); + const byId = spanById(spans); + const turnSpans = spans + .filter((s) => s.name === "turn") + .slice() + .sort((a, b) => (a.startNs < b.startNs ? -1 : a.startNs > b.startNs ? 1 : 0)); + + const turns: TurnAttribution[] = turnSpans.map((turn) => { + const bucket = emptyBucket(); + accumulateTree(turn.id, byParent, byId, bucket); + + const { wallNs: turnNs, open } = turnWallNs(turn, byParent); + const openPhases = open + ? openPhasesUnder(turn.id, byParent, turn) + : []; + const inferenceCount = countTopExclusiveUnder( + turn.id, + byParent, + byId, + "inference", + ); + const permissionWaitCount = countTopExclusiveUnder( + turn.id, + byParent, + byId, + "permission.wait", + ); + + return { + turnId: turn.id, + turnNs, + open, + openPhases, + categories: categorySharesFromBucket( + bucket, + turnNs, + inferenceCount, + permissionWaitCount, + ), + inference: inferenceSplit(bucket.ttftNs, bucket.streamNs), + toolCount: bucket.toolCount, + subagentCount: bucket.subagentCount, + transportNs: bucket.transportNs, + transportShareOfInference: + bucket.inferenceNs === 0 ? 0 : bucket.transportNs / bucket.inferenceNs, + }; + }); + + // Session wall includes open-turn estimates so stall dumps keep shares ~1. + // Category ns use exclusive (non-nested) accounting; open children contribute 0 duration. + const sessionBucket = emptyBucket(); + let wallNs = 0; + let completedTurnCount = 0; + let inferenceCount = 0; + let permissionWaitCount = 0; + const sessionOpenPhases = new Set(); + + for (const turn of turnSpans) { + const { wallNs: turnNs, open } = turnWallNs(turn, byParent); + wallNs += turnNs; + if (!open) { + completedTurnCount += 1; + } else { + for (const p of openPhasesUnder(turn.id, byParent, turn)) { + sessionOpenPhases.add(p); + } + } + accumulateTree(turn.id, byParent, byId, sessionBucket); + inferenceCount += countTopExclusiveUnder( + turn.id, + byParent, + byId, + "inference", + ); + permissionWaitCount += countTopExclusiveUnder( + turn.id, + byParent, + byId, + "permission.wait", + ); + } + + // No turn roots (partial / orphan snapshot): fall back to flat exclusive sums + // (still skip exclusive ns under exclusive ancestors) and use attributed total + // as the wall denominator. + if (turnSpans.length === 0) { + for (const span of spans) { + accumulate(sessionBucket, span, hasExclusiveAncestor(span, byId)); + if (span.name === "inference" && !hasExclusiveAncestor(span, byId)) { + inferenceCount += 1; + } + if ( + span.name === "permission.wait" && + !hasExclusiveAncestor(span, byId) + ) { + permissionWaitCount += 1; + } + if (span.endNs === undefined) sessionOpenPhases.add(span.name); + } + wallNs = + sessionBucket.inferenceNs + + sessionBucket.toolNs + + sessionBucket.permissionWaitNs + + sessionBucket.subagentNs; + } + + const openPhases = [...sessionOpenPhases].sort((a, b) => + a.localeCompare(b), + ); + + return { + session: { + wallNs, + open: openPhases.length > 0 || completedTurnCount < turnSpans.length, + openPhases, + categories: categorySharesFromBucket( + sessionBucket, + wallNs, + inferenceCount, + permissionWaitCount, + ), + inference: inferenceSplit(sessionBucket.ttftNs, sessionBucket.streamNs), + toolCount: sessionBucket.toolCount, + subagentCount: sessionBucket.subagentCount, + turnCount: turnSpans.length, + completedTurnCount, + transportNs: sessionBucket.transportNs, + transportShareOfInference: + sessionBucket.inferenceNs === 0 + ? 0 + : sessionBucket.transportNs / sessionBucket.inferenceNs, + }, + turns, + }; +} + +/** Convert a dump span (string ns) back to an in-memory PerfSpan. */ +export function deserializeDumpSpan(span: DumpSpan): PerfSpan { + const out: PerfSpan = { + id: span.id, + name: span.name, + startNs: BigInt(span.startNs), + }; + if (span.parentId !== undefined) out.parentId = span.parentId; + if (span.endNs !== undefined) out.endNs = BigInt(span.endNs); + if (span.tags !== undefined) out.tags = span.tags; + return out; +} + +/** + * Parse a JSON value as PerfDump and return live spans. + * Accepts either a full dump document or a bare `{ spans: DumpSpan[] }` / array. + */ +export function spansFromDumpJson(raw: unknown): PerfSpan[] { + if (Array.isArray(raw)) { + return raw.map((s) => deserializeDumpSpan(s as DumpSpan)); + } + if (raw !== null && typeof raw === "object") { + const obj = raw as Record; + if (Array.isArray(obj.spans)) { + return (obj.spans as DumpSpan[]).map(deserializeDumpSpan); + } + } + throw new Error( + "attribution report: expected a PerfDump object with .spans, or a DumpSpan[] array", + ); +} + +/** Attribute a parsed PerfDump (or dump-like JSON) offline. */ +export function attributionFromDump(raw: unknown): AttributionReport { + if (raw !== null && typeof raw === "object" && !Array.isArray(raw)) { + const obj = raw as Partial; + if (obj.version !== undefined && obj.version !== DUMP_VERSION) { + throw new Error( + `attribution report: unsupported dump version ${String(obj.version)} (expected ${DUMP_VERSION})`, + ); + } + } + return attributionFromSpans(spansFromDumpJson(raw)); +} + +function pct(share: number): string { + return `${(share * 100).toFixed(1)}%`; +} + +function ms(ns: number): string { + if (ns === 0) return "0ms"; + const m = ns / 1e6; + if (m < 0.001) return `${ns}ns`; + if (m < 1) return `${m.toFixed(3)}ms`; + if (m < 1000) return `${m.toFixed(1)}ms`; + return `${(m / 1000).toFixed(2)}s`; +} + +function categoryLine(c: CategoryShare): string { + const count = + c.count > 0 && c.category !== "other" ? ` n=${c.count}` : ""; + return ` ${c.category.padEnd(18)} ${pct(c.share).padStart(6)} ${ms(c.ns)}${count}`; +} + +function formatOpenPhases(phases: readonly SpanName[]): string { + return phases.length === 0 ? "(none)" : phases.join(", "); +} + +/** Human-readable multi-line report for CLI / docs. */ +export function formatAttributionReport(report: AttributionReport): string { + const lines: string[] = []; + const s = report.session; + + lines.push("PerfTrace attribution report"); + lines.push("───────────────────────────"); + lines.push( + `Session wall: ${ms(s.wallNs)} turns=${s.turnCount} (completed=${s.completedTurnCount})`, + ); + if (s.open) { + lines.push( + `Open (incomplete): still-running phases: ${formatOpenPhases(s.openPhases)}`, + ); + lines.push( + " Exclusive shares below use completed descendants only — not a full stall diagnosis.", + ); + } + lines.push(""); + lines.push( + s.open + ? "Exclusive phase shares (of estimated session wall; incomplete while open):" + : "Exclusive phase shares (of session wall):", + ); + for (const c of s.categories) { + lines.push(categoryLine(c)); + } + lines.push(""); + lines.push( + `Inference split (of ttft+stream): ttft=${pct(s.inference.ttftShare)} (${ms(s.inference.ttftNs)}) stream=${pct(s.inference.streamShare)} (${ms(s.inference.streamNs)})`, + ); + if (s.transportNs > 0 || s.transportShareOfInference > 0) { + lines.push( + `Transport: ${ms(s.transportNs)} (${pct(s.transportShareOfInference)} of inference)`, + ); + } + lines.push(`Tools: n=${s.toolCount} Subagents: n=${s.subagentCount}`); + + if (report.turns.length > 0) { + lines.push(""); + lines.push("Per-turn:"); + for (const t of report.turns) { + const openTag = t.open ? " [open]" : ""; + lines.push( + ` turn ${t.turnId}${openTag} wall=${ms(t.turnNs)} tools=${t.toolCount} subagents=${t.subagentCount}`, + ); + if (t.open) { + lines.push( + ` open phases: ${formatOpenPhases(t.openPhases)} (shares incomplete)`, + ); + } + for (const c of t.categories) { + lines.push(` ${c.category.padEnd(16)} ${pct(c.share).padStart(6)} ${ms(c.ns)}`); + } + } + } + + return lines.join("\n"); +} + +/** Lookup a category share row (throws if missing — categories are always complete). */ +export function categoryShare( + categories: readonly CategoryShare[], + category: AttributionCategory, +): CategoryShare { + const row = categories.find((c) => c.category === category); + if (row === undefined) { + throw new Error(`attribution report: missing category ${category}`); + } + return row; +} diff --git a/src/perf/rollup.ts b/src/perf/rollup.ts index 929cab8d2..d51cec92f 100644 --- a/src/perf/rollup.ts +++ b/src/perf/rollup.ts @@ -116,8 +116,9 @@ export function rollupByPhase(spans: readonly PerfSpan[]): PhaseSummary[] { /** * Build parent → children index. Orphans (parent missing after ring eviction) * still appear as roots for by-phase; by-turn only lists actual turn spans. + * Shared with attribution-report (exclusive shares walk the same tree). */ -function childrenOf(spans: readonly PerfSpan[]): Map { +export function childrenOf(spans: readonly PerfSpan[]): Map { const byParent = new Map(); for (const span of spans) { if (span.parentId === undefined) continue; @@ -132,7 +133,7 @@ function childrenOf(spans: readonly PerfSpan[]): Map { } /** Depth-first walk of the subtree rooted at `rootId` (excluding the root). */ -function walkDescendants( +export function walkDescendants( rootId: string, byParent: Map, visit: (span: PerfSpan) => void,