Skip to content

Commit 1f55d03

Browse files
committed
Fix open-turn attribution wall for mid-stall dumps
1 parent 34839bb commit 1f55d03

3 files changed

Lines changed: 223 additions & 67 deletions

File tree

docs/perftrace-attribution-guide.md

Lines changed: 17 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -18,9 +18,12 @@ When a session feels slow, the first question is **where the wall time went**:
1818
| `subagent` | Child agent lifetimes (fanout cost). |
1919
| `other` | Turn wall not covered by the above — scheduling, TUI, un-instrumented work, gaps between phases. |
2020

21-
Shares are **exclusive** over completed turn wall. Nested TTFT/stream and
22-
`adapter.transport` are diagnostic splits (they are not added on top of
23-
`inference` in the exclusive table).
21+
Shares are **exclusive** over turn wall. For **completed** turns, wall is
22+
`end − start`. For **open** (still-running) turns — including mid-stall dumps —
23+
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).
26+
2427

2528
## Capture a real slow session
2629

@@ -66,22 +69,23 @@ Golden multi-tool demo (no dump file needed — uses
6669
bun scripts/perf-report.ts --fixture
6770
```
6871

69-
Example fixture output (nanosecond fixture times print as `ns` / sub-ms):
72+
Example fixture output (fixture ns values are tiny — formatter prints sub-ms):
7073

7174
```
7275
PerfTrace attribution report
73-
============================
74-
Session wall (completed turns): 5000ns turns=1 completed=1
75-
76-
Exclusive phase shares (of session wall)
77-
inference 40.0% 2000ns
78-
tools 24.0% 1200ns n=2
79-
permission.wait 8.0% 400ns
80-
subagent 0.0% 0ms
81-
other 28.0% 1400ns
76+
───────────────────────────
77+
Session wall: 0.005ms turns=1 (completed=1)
78+
79+
Exclusive phase shares (of session wall):
80+
inference 40.0% 0.002ms n=1
81+
tools 24.0% 0.001ms n=2
82+
permission.wait 8.0% 0.000ms
83+
subagent 0.0% 0ms
84+
other 28.0% 0.001ms
8285
...
8386
```
8487

88+
8589
## How to read the report
8690

8791
1. **Session exclusive shares** — which bucket ate the turn wall. A large

src/perf/attribution-report.test.ts

Lines changed: 137 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -151,6 +151,143 @@ describe("attributionFromSpans — subagent + transport", () => {
151151
});
152152
});
153153

154+
describe("attributionFromSpans — open (stall) turns", () => {
155+
test("open turn wall is max completed-descendant end minus turn start", () => {
156+
// Mid-stall dump: turn still open; inference + tool completed; stream still open.
157+
const spans: PerfSpan[] = [
158+
span({ id: "t1", name: "turn", startNs: 100n }), // open
159+
span({
160+
id: "i1",
161+
name: "inference",
162+
parentId: "t1",
163+
startNs: 100n,
164+
endNs: 2100n, // 2000ns
165+
}),
166+
span({
167+
id: "ttft1",
168+
name: "inference.ttft",
169+
parentId: "i1",
170+
startNs: 100n,
171+
endNs: 500n,
172+
}),
173+
span({
174+
id: "stream1",
175+
name: "inference.stream",
176+
parentId: "i1",
177+
startNs: 500n, // still open — contributes 0 to streamNs
178+
}),
179+
span({
180+
id: "k1",
181+
name: "tool",
182+
parentId: "t1",
183+
startNs: 2100n,
184+
endNs: 3100n, // 1000ns; max end → wall = 3100 - 100 = 3000
185+
}),
186+
];
187+
188+
const report = attributionFromSpans(spans);
189+
expect(report.session.completedTurnCount).toBe(0);
190+
expect(report.session.turnCount).toBe(1);
191+
// wall = maxEnd(3100) - start(100) = 3000
192+
expect(report.session.wallNs).toBe(3000);
193+
expect(report.turns[0]!.open).toBe(true);
194+
expect(report.turns[0]!.turnNs).toBe(3000);
195+
196+
expect(categoryShare(report.session.categories, "inference").ns).toBe(2000);
197+
expect(categoryShare(report.session.categories, "tools").ns).toBe(1000);
198+
// other = 3000 - 2000 - 1000 = 0
199+
expect(categoryShare(report.session.categories, "other").ns).toBe(0);
200+
201+
const shareSum = report.session.categories.reduce((a, c) => a + c.share, 0);
202+
expect(shareSum).toBeCloseTo(1, 10);
203+
204+
const turnShareSum = report.turns[0]!.categories.reduce((a, c) => a + c.share, 0);
205+
expect(turnShareSum).toBeCloseTo(1, 10);
206+
});
207+
208+
test("mixed completed + open turns: session shares sum to ~1", () => {
209+
const spans: PerfSpan[] = [
210+
// completed turn: wall 5000
211+
span({ id: "t0", name: "turn", startNs: 0n, endNs: 5000n }),
212+
span({
213+
id: "i0",
214+
name: "inference",
215+
parentId: "t0",
216+
startNs: 0n,
217+
endNs: 3000n,
218+
}),
219+
span({
220+
id: "k0",
221+
name: "tool",
222+
parentId: "t0",
223+
startNs: 3000n,
224+
endNs: 4000n,
225+
}),
226+
// open stall turn: estimated wall 2000 (max end 7000 - start 5000)
227+
span({ id: "t1", name: "turn", startNs: 5000n }),
228+
span({
229+
id: "i1",
230+
name: "inference",
231+
parentId: "t1",
232+
startNs: 5000n,
233+
endNs: 6500n, // 1500
234+
}),
235+
span({
236+
id: "k1",
237+
name: "tool",
238+
parentId: "t1",
239+
startNs: 6500n,
240+
endNs: 7000n, // 500; max end → wall 2000
241+
}),
242+
span({
243+
id: "stream1",
244+
name: "inference.stream",
245+
parentId: "i1",
246+
startNs: 5500n, // open child — 0 duration
247+
}),
248+
];
249+
250+
const report = attributionFromSpans(spans);
251+
expect(report.session.completedTurnCount).toBe(1);
252+
expect(report.session.turnCount).toBe(2);
253+
// wall = 5000 + 2000 = 7000
254+
expect(report.session.wallNs).toBe(7000);
255+
// inference 3000+1500=4500; tools 1000+500=1500; other = 7000-6000=1000
256+
expect(categoryShare(report.session.categories, "inference").ns).toBe(4500);
257+
expect(categoryShare(report.session.categories, "tools").ns).toBe(1500);
258+
expect(categoryShare(report.session.categories, "other").ns).toBe(1000);
259+
260+
const shareSum = report.session.categories.reduce((a, c) => a + c.share, 0);
261+
expect(shareSum).toBeCloseTo(1, 10);
262+
263+
const openTurn = report.turns.find((t) => t.turnId === "t1")!;
264+
expect(openTurn.open).toBe(true);
265+
expect(openTurn.turnNs).toBe(2000);
266+
const openShareSum = openTurn.categories.reduce((a, c) => a + c.share, 0);
267+
expect(openShareSum).toBeCloseTo(1, 10);
268+
});
269+
270+
test("open turn with no completed descendants has zero wall and zero shares", () => {
271+
const spans: PerfSpan[] = [
272+
span({ id: "t1", name: "turn", startNs: 0n }),
273+
span({
274+
id: "i1",
275+
name: "inference",
276+
parentId: "t1",
277+
startNs: 0n, // still open
278+
}),
279+
];
280+
const report = attributionFromSpans(spans);
281+
expect(report.session.wallNs).toBe(0);
282+
expect(report.turns[0]!.open).toBe(true);
283+
expect(report.turns[0]!.turnNs).toBe(0);
284+
for (const c of report.session.categories) {
285+
expect(c.share).toBe(0);
286+
expect(c.ns).toBe(0);
287+
}
288+
});
289+
});
290+
154291
describe("dump round-trip", () => {
155292
test("attributionFromDump matches live spans", () => {
156293
const spans = multiToolTurnFixture();

0 commit comments

Comments
 (0)