Skip to content

Commit 6fcd7b8

Browse files
committed
Make exclusive attribution skip nested exclusive children
Nested tool/inference under subagent no longer double-count toward turn wall; open phase names surface mid-stall incompleteness; dump version mismatch is rejected with a clear error.
1 parent 389e08c commit 6fcd7b8

5 files changed

Lines changed: 390 additions & 73 deletions

File tree

docs/PERFTRACE.md

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -144,8 +144,9 @@ Illustrative rollup section:
144144

145145
1. **`rollup.session`** — whole-run totals. Compare `totalInferenceNs` vs
146146
`totalToolNs`. `ttftShare` / `streamShare` split model wait (time to first
147-
token) from the rest of the stream; they sum to 1 when any TTFT/stream data
148-
exists.
147+
token) from the rest of the stream using **(ttft + stream)** as the
148+
denominator (not full inference wall); they sum to 1 when any TTFT/stream
149+
data exists.
149150
2. **`rollup.byPhase`** — p50/p95 per phase name. A high `tool` p95 with a low
150151
count points at one expensive tool; a high `inference.ttft` p50 points at
151152
cold model / queueing.

docs/perftrace-attribution-guide.md

Lines changed: 24 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -21,8 +21,16 @@ When a session feels slow, the first question is **where the wall time went**:
2121
Shares are **exclusive** over turn wall. For **completed** turns, wall is
2222
`end − start`. For **open** (still-running) turns — including mid-stall dumps —
2323
wall is estimated as `max(completed-descendant endNs) − turn.startNs` so shares
24-
stay meaningful. Nested TTFT/stream and `adapter.transport` are diagnostic
25-
splits (they are not added on top of `inference` in the exclusive table).
24+
stay meaningful, and the report lists **open phase names** (e.g.
25+
`inference.stream`, `turn`) so completed-only shares are not read as a full
26+
stall diagnosis.
27+
28+
Nested exclusive children under an exclusive parent (e.g. `tool` /
29+
`inference` under `subagent`) count only toward the parent exclusive bucket —
30+
they are not double-counted. Nested TTFT/stream and `adapter.transport` are
31+
diagnostic splits (they are not added on top of `inference` in the exclusive
32+
table). TTFT/stream shares use **(ttft + stream)** as the denominator, not
33+
inference wall.
2634

2735

2836
## Capture a real slow session
@@ -92,18 +100,24 @@ Exclusive phase shares (of session wall):
92100
`inference` share with high `ttft` points at model queueing / cold start. A
93101
large `tools` share with high `n=` points at tool work. A large
94102
`permission.wait` share is human/ask-gate idle, not model or tool code.
95-
2. **`other` large** — either real un-instrumented cost (TUI, scheduling) or
103+
2. **Open / incomplete** — if the report says `Open (incomplete)` and lists
104+
still-running phases, exclusive shares only cover completed descendants.
105+
Treat open phase names as the hang candidates; do not conclude from the
106+
exclusive table alone.
107+
3. **`other` large** — either real un-instrumented cost (TUI, scheduling) or
96108
gaps between instrumented phases. If `other` dominates a pain session, add
97109
spans before optimizing transport.
98-
3. **TTFT vs stream** — of `ttft + stream` only. High TTFT share → time-to-first-token
99-
problem. High stream share → long generation or slow token delivery.
100-
4. **Transport signal**`adapter.transport / inference`. When transport is a
110+
4. **TTFT vs stream** — of `ttft + stream` only (not inference wall). High TTFT
111+
share → time-to-first-token problem. High stream share → long generation or
112+
slow token delivery.
113+
5. **Transport signal**`adapter.transport / inference`. When transport is a
101114
large fraction of inference wall, prioritize transport work (WebSocket /
102115
incremental input). When it is small, transport is not the bottleneck.
103-
5. **Per-turn rows** — find the outlier turn when the session average looks fine
104-
but one turn felt stuck.
105-
6. **Subagent count + share** — fanout cost. High subagent share means child
106-
agents, not the parent inference path.
116+
6. **Per-turn rows** — find the outlier turn when the session average looks fine
117+
but one turn felt stuck. Open turns print `open phases:` explicitly.
118+
7. **Subagent count + share** — fanout cost. High subagent share means child
119+
agents as a whole (nested tools/inference under the subagent are inside that
120+
bucket, not double-counted as parent tools/inference).
107121

108122
### What “large transport share” looks like
109123

src/perf/attribution-report.test.ts

Lines changed: 159 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@ import {
77
formatAttributionReport,
88
spansFromDumpJson,
99
} from "./attribution-report.js";
10-
import { buildDump, serializeSpan } from "./dump.js";
10+
import { DUMP_VERSION, buildDump, serializeSpan } from "./dump.js";
1111
import {
1212
MULTI_TOOL_TURN_GOLDEN,
1313
multiToolTurnFixture,
@@ -148,6 +148,112 @@ describe("attributionFromSpans — subagent + transport", () => {
148148
expect(report.session.subagentCount).toBe(1);
149149
expect(report.session.transportNs).toBe(800);
150150
expect(report.session.transportShareOfInference).toBeCloseTo(800 / 4000, 10);
151+
expect(report.session.open).toBe(false);
152+
expect(report.session.openPhases).toEqual([]);
153+
});
154+
155+
test("nested exclusive under subagent does not double-count (share sum ≈ 1)", () => {
156+
// turn 10_000
157+
// inference 2000 (top-level exclusive)
158+
// subagent 6000 containing nested inference 2500 + tools 1500
159+
// tool 1000 (sibling exclusive)
160+
// Exclusive: inference=2000, subagent=6000, tools=1000, other=1000
161+
// Nested under subagent must NOT add 2500+1500 into exclusive buckets.
162+
const spans: PerfSpan[] = [
163+
span({ id: "t1", name: "turn", startNs: 0n, endNs: 10_000n }),
164+
span({
165+
id: "i1",
166+
name: "inference",
167+
parentId: "t1",
168+
startNs: 0n,
169+
endNs: 2000n,
170+
}),
171+
span({
172+
id: "ttft1",
173+
name: "inference.ttft",
174+
parentId: "i1",
175+
startNs: 0n,
176+
endNs: 400n,
177+
}),
178+
span({
179+
id: "stream1",
180+
name: "inference.stream",
181+
parentId: "i1",
182+
startNs: 400n,
183+
endNs: 2000n,
184+
}),
185+
span({
186+
id: "sa1",
187+
name: "subagent",
188+
parentId: "t1",
189+
startNs: 2000n,
190+
endNs: 8000n,
191+
}),
192+
span({
193+
id: "sa_i1",
194+
name: "inference",
195+
parentId: "sa1",
196+
startNs: 2000n,
197+
endNs: 4500n,
198+
}),
199+
span({
200+
id: "sa_ttft",
201+
name: "inference.ttft",
202+
parentId: "sa_i1",
203+
startNs: 2000n,
204+
endNs: 2500n,
205+
}),
206+
span({
207+
id: "sa_stream",
208+
name: "inference.stream",
209+
parentId: "sa_i1",
210+
startNs: 2500n,
211+
endNs: 4500n,
212+
}),
213+
span({
214+
id: "sa_k1",
215+
name: "tool",
216+
parentId: "sa1",
217+
startNs: 4500n,
218+
endNs: 6000n,
219+
}),
220+
span({
221+
id: "k1",
222+
name: "tool",
223+
parentId: "t1",
224+
startNs: 8000n,
225+
endNs: 9000n,
226+
}),
227+
];
228+
229+
const report = attributionFromSpans(spans);
230+
const inf = categoryShare(report.session.categories, "inference");
231+
const tools = categoryShare(report.session.categories, "tools");
232+
const sub = categoryShare(report.session.categories, "subagent");
233+
const other = categoryShare(report.session.categories, "other");
234+
235+
expect(inf.ns).toBe(2000);
236+
expect(sub.ns).toBe(6000);
237+
expect(tools.ns).toBe(1000); // only the top-level tool, not sa_k1
238+
expect(other.ns).toBe(1000); // 10000 - 2000 - 6000 - 1000
239+
expect(inf.count).toBe(1); // nested inference under subagent not counted
240+
expect(sub.count).toBe(1);
241+
// toolCount still sees nested tools for visibility
242+
expect(report.session.toolCount).toBe(2);
243+
expect(report.session.subagentCount).toBe(1);
244+
245+
const shareSum = report.session.categories.reduce((a, c) => a + c.share, 0);
246+
expect(shareSum).toBeCloseTo(1, 10);
247+
248+
// Nested diagnostics still roll up (parent + subagent ttft/stream)
249+
expect(report.session.inference.ttftNs).toBe(400 + 500);
250+
expect(report.session.inference.streamNs).toBe(1600 + 2000);
251+
252+
const turnShareSum = report.turns[0]!.categories.reduce(
253+
(a, c) => a + c.share,
254+
0,
255+
);
256+
expect(turnShareSum).toBeCloseTo(1, 10);
151257
});
152258
});
153259

@@ -192,6 +298,10 @@ describe("attributionFromSpans — open (stall) turns", () => {
192298
expect(report.session.wallNs).toBe(3000);
193299
expect(report.turns[0]!.open).toBe(true);
194300
expect(report.turns[0]!.turnNs).toBe(3000);
301+
expect(report.session.open).toBe(true);
302+
// Still-running: turn + open stream (completed inference/tool are not listed)
303+
expect(report.session.openPhases).toEqual(["inference.stream", "turn"]);
304+
expect(report.turns[0]!.openPhases).toEqual(["inference.stream", "turn"]);
195305

196306
expect(categoryShare(report.session.categories, "inference").ns).toBe(2000);
197307
expect(categoryShare(report.session.categories, "tools").ns).toBe(1000);
@@ -281,6 +391,9 @@ describe("attributionFromSpans — open (stall) turns", () => {
281391
expect(report.session.wallNs).toBe(0);
282392
expect(report.turns[0]!.open).toBe(true);
283393
expect(report.turns[0]!.turnNs).toBe(0);
394+
expect(report.session.open).toBe(true);
395+
expect(report.session.openPhases).toEqual(["inference", "turn"]);
396+
expect(report.turns[0]!.openPhases).toEqual(["inference", "turn"]);
284397
for (const c of report.session.categories) {
285398
expect(c.share).toBe(0);
286399
expect(c.ns).toBe(0);
@@ -308,6 +421,17 @@ describe("dump round-trip", () => {
308421
expect(spans[0]!.startNs).toBe(0n);
309422
expect(deserializeDumpSpan(serialized[0]!).id).toBe("t1");
310423
});
424+
425+
test("attributionFromDump rejects unsupported DUMP_VERSION", () => {
426+
const dump = buildDump(
427+
multiToolTurnFixture(),
428+
"fixture-multi",
429+
"2026-04-08T00:00:00.000Z",
430+
);
431+
expect(() =>
432+
attributionFromDump({ ...dump, version: DUMP_VERSION + 1 }),
433+
).toThrow(/unsupported dump version/);
434+
});
311435
});
312436

313437
describe("formatAttributionReport", () => {
@@ -324,5 +448,39 @@ describe("formatAttributionReport", () => {
324448
expect(text).toContain("40.0%"); // inference 2000/5000
325449
expect(text).toContain("24.0%"); // tools 1200/5000
326450
expect(text).toContain("turn t1");
451+
expect(text).toContain("Inference split (of ttft+stream)");
452+
expect(text).not.toContain("Open (incomplete)");
453+
});
454+
455+
test("surfaces open phases for mid-stall dumps", () => {
456+
const spans: PerfSpan[] = [
457+
span({ id: "t1", name: "turn", startNs: 0n }),
458+
span({
459+
id: "i1",
460+
name: "inference",
461+
parentId: "t1",
462+
startNs: 0n,
463+
endNs: 1000n,
464+
}),
465+
span({
466+
id: "stream1",
467+
name: "inference.stream",
468+
parentId: "i1",
469+
startNs: 200n,
470+
}),
471+
span({
472+
id: "k1",
473+
name: "tool",
474+
parentId: "t1",
475+
startNs: 1000n,
476+
endNs: 1500n,
477+
}),
478+
];
479+
const text = formatAttributionReport(attributionFromSpans(spans));
480+
expect(text).toContain("Open (incomplete)");
481+
expect(text).toContain("inference.stream");
482+
expect(text).toContain("open phases:");
483+
expect(text).toContain("shares incomplete");
484+
expect(text).toContain("not a full stall diagnosis");
327485
});
328486
});

0 commit comments

Comments
 (0)