Skip to content

Commit 480fee5

Browse files
TheGreatAxiosTheGreatAxios
committed
Add local PerfTrace dump and rollup helpers
Pure rollup functions (by phase, by turn, session totals with TTFT vs stream split) over PerfSpan snapshots. dump.ts writes privacy-strict compact JSON beside session artifacts with a rollup section and re-sanitized tags. Fixture test asserts no non-allowlisted data leaks.
1 parent 978ca10 commit 480fee5

4 files changed

Lines changed: 1142 additions & 0 deletions

File tree

‎docs/PERFTRACE.md‎

Lines changed: 185 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,185 @@
1+
# PerfTrace
2+
3+
Always-on, local-only performance tracing for Corbits Code. Every session
4+
records a nested span tree in a fixed-size in-process ring so a slow run can be
5+
attributed offline — without PostHog, without OTEL, and without shipping
6+
prompts, paths, or free text.
7+
8+
Product analytics stay in [`TELEMETRY.md`](./TELEMETRY.md). PerfTrace is
9+
**measurement for operators and developers**, not product analytics.
10+
11+
## What it records
12+
13+
| Phase | Meaning |
14+
|---|---|
15+
| `session` | Whole run (when opened by a caller) |
16+
| `turn` | One user → assistant cycle |
17+
| `inference` | Full model call |
18+
| `inference.ttft` | Start → first content-bearing stream event |
19+
| `inference.stream` | First event → inference done |
20+
| `tool` | One tool invocation |
21+
| `permission.wait` | Ask-gate wait (when instrumented) |
22+
| `subagent` | Child agent lifetime (when instrumented) |
23+
| `adapter.request_build` | Adapter: serialize request body |
24+
| `adapter.first_byte` | Adapter: connect → first network byte |
25+
| `adapter.transport` | Adapter transport mark (`http_sse` \| `ws`) |
26+
27+
Nesting from the automatic reactor observer:
28+
29+
```
30+
turn
31+
inference
32+
inference.ttft
33+
inference.stream
34+
tool
35+
tool
36+
```
37+
38+
Tags on spans pass through a hard allowlist (`provider_id`, `model_id`,
39+
`transport`, token/byte/count numbers, short opaque ids). Everything else is
40+
stripped at write time — see `src/perf/sanitize.ts`.
41+
42+
## API surface
43+
44+
```ts
45+
import { start, end, mark, snapshot, clear } from "../src/perf/index.js";
46+
import { rollupByPhase, rollupByTurn, sessionTotals } from "../src/perf/rollup.js";
47+
import { dumpSpans } from "../src/perf/dump.js";
48+
```
49+
50+
- `start` / `end` / `mark` — open, close, or point-in-time spans
51+
- `snapshot()` — completed ring contents (oldest first) plus any still-open spans
52+
- `rollupByPhase` / `rollupByTurn` / `sessionTotals` — pure functions over a snapshot
53+
- `dumpSpans(spans, { dir, sessionId })` — write a privacy-strict JSON file
54+
55+
The ring holds `RING_CAPACITY` (4096) completed spans. Older entries are
56+
evicted; open spans are not stored in the ring until they end.
57+
58+
## Reading a dump after a slow run
59+
60+
When a session feels slow, dump the current snapshot next to the session
61+
artifacts (`.agent-state/<sessionId>/`):
62+
63+
```ts
64+
import { snapshot } from "../src/perf/index.js";
65+
import { dumpSpans } from "../src/perf/dump.js";
66+
67+
const path = await dumpSpans(snapshot(), {
68+
dir: ".agent-state/sess-abc",
69+
sessionId: "sess-abc",
70+
});
71+
// → .agent-state/sess-abc/perftrace-sess-abc.json
72+
```
73+
74+
Or, from a one-off script after a repro, import the same helpers and call
75+
`dumpSpans` on whatever snapshot you captured.
76+
77+
### File shape
78+
79+
Compact single-line JSON (pretty-print with `jq`):
80+
81+
```bash
82+
jq . .agent-state/sess-abc/perftrace-sess-abc.json
83+
jq '.rollup.session' .agent-state/sess-abc/perftrace-sess-abc.json
84+
jq '.rollup.byPhase[] | {name, totalNs, p50Ns, p95Ns, count}' \
85+
.agent-state/sess-abc/perftrace-sess-abc.json
86+
jq '.rollup.byTurn[]' .agent-state/sess-abc/perftrace-sess-abc.json
87+
```
88+
89+
Illustrative rollup section:
90+
91+
```json
92+
{
93+
"version": 1,
94+
"sessionId": "sess-abc",
95+
"writtenAt": "2026-04-08T12:00:00.000Z",
96+
"spanCount": 12,
97+
"openCount": 0,
98+
"rollup": {
99+
"byPhase": [
100+
{ "name": "inference", "count": 2, "openCount": 0, "totalNs": 4500000000, "p50Ns": 2000000000, "p95Ns": 2500000000 },
101+
{ "name": "inference.stream", "count": 2, "openCount": 0, "totalNs": 3600000000, "p50Ns": 1600000000, "p95Ns": 2000000000 },
102+
{ "name": "inference.ttft", "count": 2, "openCount": 0, "totalNs": 900000000, "p50Ns": 400000000, "p95Ns": 500000000 },
103+
{ "name": "tool", "count": 4, "openCount": 0, "totalNs": 800000000, "p50Ns": 150000000, "p95Ns": 400000000 },
104+
{ "name": "turn", "count": 2, "openCount": 0, "totalNs": 5500000000, "p50Ns": 2500000000, "p95Ns": 3000000000 }
105+
],
106+
"byTurn": [
107+
{
108+
"turnId": "a1",
109+
"turnNs": 2500000000,
110+
"open": false,
111+
"inferenceNs": 2000000000,
112+
"toolNs": 300000000,
113+
"ttftNs": 400000000,
114+
"streamNs": 1600000000,
115+
"toolCount": 2
116+
}
117+
],
118+
"session": {
119+
"turnCount": 2,
120+
"completedTurnCount": 2,
121+
"totalTurnNs": 5500000000,
122+
"totalInferenceNs": 4500000000,
123+
"totalToolNs": 800000000,
124+
"totalTtftNs": 900000000,
125+
"totalStreamNs": 3600000000,
126+
"totalToolCount": 4,
127+
"ttftShare": 0.2,
128+
"streamShare": 0.8
129+
}
130+
},
131+
"spans": [
132+
{
133+
"id": "a1",
134+
"name": "turn",
135+
"startNs": "1234567890",
136+
"endNs": "1234567890000",
137+
"tags": { "turn_id": "t-1" }
138+
}
139+
]
140+
}
141+
```
142+
143+
### How to read the numbers
144+
145+
1. **`rollup.session`** — whole-run totals. Compare `totalInferenceNs` vs
146+
`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.
149+
2. **`rollup.byPhase`** — p50/p95 per phase name. A high `tool` p95 with a low
150+
count points at one expensive tool; a high `inference.ttft` p50 points at
151+
cold model / queueing.
152+
3. **`rollup.byTurn`** — per-turn breakdown when one turn is the outlier.
153+
4. **`spans`** — full tree with `parentId` links if you need to reconstruct
154+
nesting. Absolute times are monotonic nanoseconds as decimal strings (not
155+
wall clock). Open spans omit `endNs` and set `"open": true`.
156+
157+
Durations are nanoseconds. Divide by `1e6` for milliseconds, `1e9` for seconds:
158+
159+
```bash
160+
jq '.rollup.session | {
161+
inference_ms: (.totalInferenceNs / 1e6),
162+
tool_ms: (.totalToolNs / 1e6),
163+
ttft_share: .ttftShare,
164+
stream_share: .streamShare
165+
}' .agent-state/sess-abc/perftrace-sess-abc.json
166+
```
167+
168+
### Privacy
169+
170+
The dump file is intentionally boring:
171+
172+
- Span objects only carry `id`, `name`, `parentId`, `startNs`, `endNs`, `open`, `tags`
173+
- Tag keys are restricted to the allowlist in `src/perf/sanitize.ts`
174+
- Tags are re-sanitized at dump time even if an in-memory span was constructed by hand
175+
- No prompts, completions, paths, tool args, stack traces, or free-text errors
176+
177+
A unit fixture in `src/perf/rollup.test.ts` asserts this on every change.
178+
179+
## What this is not
180+
181+
- **Not PostHog.** No new product-analytics events or fields.
182+
- **Not OTEL export.** Optional collector flush is a separate work item; this
183+
dump never opens a network connection.
184+
- **Not a settings UI.** Ring capacity is a code constant; the local sink is
185+
always on.

‎src/perf/dump.ts‎

Lines changed: 168 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,168 @@
1+
/**
2+
* Privacy-strict local dump of a PerfSpan snapshot.
3+
*
4+
* Writes compact JSON beside session artifacts. Re-sanitizes tags and strips
5+
* any non-allowlisted shape so the file is safe to share offline.
6+
* No network.
7+
*/
8+
9+
import { mkdir, writeFile } from "node:fs/promises";
10+
import { join } from "node:path";
11+
import {
12+
ALLOWED_TAG_KEYS,
13+
type PerfSpan,
14+
type PerfTags,
15+
type SpanName,
16+
sanitizeTags,
17+
} from "./index.js";
18+
import {
19+
rollupByPhase,
20+
rollupByTurn,
21+
sessionTotals,
22+
type PhaseSummary,
23+
type SessionTotals,
24+
type TurnSummary,
25+
} from "./rollup.js";
26+
27+
/** Dump schema version — bump when the on-disk shape changes incompatibly. */
28+
export const DUMP_VERSION = 1 as const;
29+
30+
/** Allowlisted keys that may appear on a serialized span object. */
31+
export const DUMP_SPAN_KEYS = [
32+
"id",
33+
"name",
34+
"parentId",
35+
"startNs",
36+
"endNs",
37+
"open",
38+
"tags",
39+
] as const;
40+
41+
export type DumpSpan = {
42+
id: string;
43+
name: SpanName;
44+
parentId?: string;
45+
/** Absolute monotonic ns as decimal string (preserves bigint precision). */
46+
startNs: string;
47+
endNs?: string;
48+
/** Present and true when the span was still open at dump time. */
49+
open?: true;
50+
tags?: PerfTags;
51+
};
52+
53+
export type PerfDump = {
54+
version: typeof DUMP_VERSION;
55+
sessionId: string;
56+
/** ISO-8601 wall clock when the dump was written (not span time). */
57+
writtenAt: string;
58+
spanCount: number;
59+
openCount: number;
60+
rollup: {
61+
byPhase: PhaseSummary[];
62+
byTurn: TurnSummary[];
63+
session: SessionTotals;
64+
};
65+
spans: DumpSpan[];
66+
};
67+
68+
export type DumpOptions = {
69+
/** Directory that already holds (or will hold) session artifacts. */
70+
dir: string;
71+
/** Opaque session id — used only in the filename and dump header. */
72+
sessionId: string;
73+
};
74+
75+
// Session ids in the product are opaque short strings; reject path traversal.
76+
const SAFE_SESSION_ID_RE = /^[A-Za-z0-9._:-]{1,128}$/;
77+
78+
const ALLOWED_TAG_KEY_SET: ReadonlySet<string> = new Set(ALLOWED_TAG_KEYS);
79+
80+
function assertSafeSessionId(sessionId: string): void {
81+
if (!SAFE_SESSION_ID_RE.test(sessionId)) {
82+
throw new Error(
83+
`dumpSpans: sessionId must be a short opaque id (got ${JSON.stringify(sessionId)})`,
84+
);
85+
}
86+
}
87+
88+
/**
89+
* Project a live PerfSpan onto the dump allowlist.
90+
* Bigints become decimal strings; tags are re-sanitized.
91+
*/
92+
export function serializeSpan(span: PerfSpan): DumpSpan {
93+
const out: DumpSpan = {
94+
id: span.id,
95+
name: span.name,
96+
startNs: span.startNs.toString(),
97+
};
98+
if (span.parentId !== undefined) {
99+
out.parentId = span.parentId;
100+
}
101+
if (span.endNs === undefined) {
102+
out.open = true;
103+
} else {
104+
out.endNs = span.endNs.toString();
105+
}
106+
// Defense in depth: re-run the privacy fence even if the in-memory span
107+
// somehow carried extra keys (e.g. test fixtures or future sinks).
108+
const tags = sanitizeTags(span.tags as Record<string, unknown> | undefined);
109+
if (tags !== undefined) {
110+
out.tags = tags;
111+
}
112+
return out;
113+
}
114+
115+
/** Build the dump document without touching the filesystem. */
116+
export function buildDump(spans: readonly PerfSpan[], sessionId: string, writtenAt: string): PerfDump {
117+
assertSafeSessionId(sessionId);
118+
const serialized = spans.map(serializeSpan);
119+
let openCount = 0;
120+
for (const s of serialized) {
121+
if (s.open === true) openCount += 1;
122+
}
123+
return {
124+
version: DUMP_VERSION,
125+
sessionId,
126+
writtenAt,
127+
spanCount: serialized.length,
128+
openCount,
129+
rollup: {
130+
byPhase: rollupByPhase(spans),
131+
byTurn: rollupByTurn(spans),
132+
session: sessionTotals(spans),
133+
},
134+
spans: serialized,
135+
};
136+
}
137+
138+
/**
139+
* Write `perftrace-{sessionId}.json` under `opts.dir`.
140+
* Returns the absolute-or-relative path written.
141+
*/
142+
export async function dumpSpans(
143+
spans: readonly PerfSpan[],
144+
opts: DumpOptions,
145+
): Promise<string> {
146+
assertSafeSessionId(opts.sessionId);
147+
const dump = buildDump(spans, opts.sessionId, new Date().toISOString());
148+
const filePath = join(opts.dir, `perftrace-${opts.sessionId}.json`);
149+
await mkdir(opts.dir, { recursive: true });
150+
// Compact single-line JSON keeps diffs and `jq` usage simple.
151+
await writeFile(filePath, `${JSON.stringify(dump)}\n`, "utf8");
152+
return filePath;
153+
}
154+
155+
/**
156+
* Walk a parsed dump and return every tag key that is not allowlisted.
157+
* Used by the privacy fixture test; also handy for operator scripts.
158+
*/
159+
export function collectNonAllowlistedTagKeys(dump: PerfDump): string[] {
160+
const bad: string[] = [];
161+
for (const span of dump.spans) {
162+
if (span.tags === undefined) continue;
163+
for (const key of Object.keys(span.tags)) {
164+
if (!ALLOWED_TAG_KEY_SET.has(key)) bad.push(key);
165+
}
166+
}
167+
return bad;
168+
}

0 commit comments

Comments
 (0)