Skip to content

Commit 03bab5a

Browse files
PerfTrace core: span API, ring buffer, tag allowlist (CL-5160) (#303)
* Add local PerfTrace core with ring buffer and tag allowlist Always-on in-process span API (start/end/mark) using monotonic hrtime, a fixed 4096-span ring, and privacy-sanitized tags. No network or PostHog; snapshot/clear for tests. * Harden PerfTrace privacy fence, snapshot immutability, open-span cap Accept parentId only as opaque span ids (known open/ring or OPAQUE_ID_RE); return shallow snapshot copies; cap open spans with oldest-first eviction; mark() takes StartOptions; cover double-end, clear, and overflow paths.
1 parent f644088 commit 03bab5a

3 files changed

Lines changed: 718 additions & 0 deletions

File tree

src/perf/index.test.ts

Lines changed: 346 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,346 @@
1+
import { afterEach, describe, expect, test } from "bun:test";
2+
import {
3+
OPEN_SPAN_CAPACITY,
4+
RING_CAPACITY,
5+
clear,
6+
end,
7+
mark,
8+
sanitizeTags,
9+
snapshot,
10+
start,
11+
type PerfSpan,
12+
} from "./index.js";
13+
14+
afterEach(() => {
15+
clear();
16+
});
17+
18+
describe("start / end / mark", () => {
19+
test("records a completed span with monotonic times", () => {
20+
const id = start("inference");
21+
expect(id.length).toBeGreaterThan(0);
22+
end(id);
23+
24+
const spans = snapshot();
25+
expect(spans).toHaveLength(1);
26+
const span = spans[0]!;
27+
expect(span.name).toBe("inference");
28+
expect(span.endNs).toBeDefined();
29+
expect(span.endNs! >= span.startNs).toBe(true);
30+
});
31+
32+
test("nests via parentId", () => {
33+
const turnId = start("turn");
34+
const infId = start("inference", { parentId: turnId });
35+
end(infId);
36+
end(turnId);
37+
38+
const spans = snapshot();
39+
expect(spans).toHaveLength(2);
40+
const inference = spans.find((s) => s.name === "inference")!;
41+
const turn = spans.find((s) => s.name === "turn")!;
42+
expect(inference.parentId).toBe(turnId);
43+
expect(turn.parentId).toBeUndefined();
44+
});
45+
46+
test("mark is a completed point-in-time span", () => {
47+
const id = mark("adapter.transport", { tags: { transport: "http_sse" } });
48+
expect(id.length).toBeGreaterThan(0);
49+
50+
const spans = snapshot();
51+
expect(spans).toHaveLength(1);
52+
expect(spans[0]!.startNs).toBe(spans[0]!.endNs!);
53+
expect(spans[0]!.tags).toEqual({ transport: "http_sse" });
54+
});
55+
56+
test("mark accepts optional parentId like start", () => {
57+
const turnId = start("turn");
58+
mark("adapter.transport", { parentId: turnId, tags: { transport: "ws" } });
59+
end(turnId);
60+
61+
const spans = snapshot();
62+
const marked = spans.find((s) => s.name === "adapter.transport")!;
63+
expect(marked.parentId).toBe(turnId);
64+
expect(marked.tags).toEqual({ transport: "ws" });
65+
});
66+
67+
test("open spans appear in snapshot without endNs", () => {
68+
const id = start("session");
69+
const spans = snapshot();
70+
expect(spans).toHaveLength(1);
71+
expect(spans[0]!.id).toBe(id);
72+
expect(spans[0]!.endNs).toBeUndefined();
73+
});
74+
75+
test("unknown span names are ignored", () => {
76+
expect(start("not.a.phase")).toBe("");
77+
expect(mark("also.bad")).toBe("");
78+
expect(snapshot()).toHaveLength(0);
79+
});
80+
81+
test("end of unknown id is a no-op", () => {
82+
end("nope");
83+
end("");
84+
expect(snapshot()).toHaveLength(0);
85+
});
86+
87+
test("double-end is a no-op", () => {
88+
const id = start("tool");
89+
end(id);
90+
end(id);
91+
expect(snapshot()).toHaveLength(1);
92+
});
93+
94+
test("end after clear is a no-op", () => {
95+
const id = start("tool");
96+
clear();
97+
end(id, { count: 1 });
98+
expect(snapshot()).toHaveLength(0);
99+
});
100+
101+
test("end merges sanitized tags onto the span", () => {
102+
const id = start("tool", { tags: { tool_id: "t1" } });
103+
end(id, { count: 3, prompt: "secret" });
104+
const span = snapshot()[0]!;
105+
expect(span.tags).toEqual({ tool_id: "t1", count: 3 });
106+
});
107+
});
108+
109+
describe("parentId privacy fence", () => {
110+
test("strips path-like parentId", () => {
111+
const id = start("inference", { parentId: "/Users/me/secret/repo/src/main.ts" });
112+
end(id);
113+
expect(snapshot()[0]!.parentId).toBeUndefined();
114+
});
115+
116+
test("strips free-text and path-separator parentIds", () => {
117+
const a = start("tool", { parentId: "has spaces and free text" });
118+
end(a);
119+
const b = start("tool", { parentId: "../../etc/passwd" });
120+
end(b);
121+
const c = start("tool", { parentId: "C:\\Windows\\System32" });
122+
end(c);
123+
124+
for (const span of snapshot()) {
125+
expect(span.parentId).toBeUndefined();
126+
}
127+
});
128+
129+
test("accepts known open span ids and opaque ids", () => {
130+
const parent = start("turn");
131+
const child = start("inference", { parentId: parent });
132+
end(child);
133+
end(parent);
134+
135+
// Opaque id that matches OPAQUE_ID_RE but is not currently open/ring-known
136+
// after clear of only that id — still accepted when pattern matches.
137+
const orphan = start("tool", { parentId: "parent1" });
138+
end(orphan);
139+
140+
const spans = snapshot();
141+
expect(spans.find((s) => s.name === "inference")!.parentId).toBe(parent);
142+
expect(spans.find((s) => s.name === "tool")!.parentId).toBe("parent1");
143+
});
144+
145+
test("accepts parentId of a completed (ring) span", () => {
146+
const parent = start("turn");
147+
end(parent);
148+
const child = start("inference", { parentId: parent });
149+
end(child);
150+
expect(snapshot().find((s) => s.name === "inference")!.parentId).toBe(parent);
151+
});
152+
});
153+
154+
describe("snapshot immutability", () => {
155+
test("mutating a snapshot does not poison the next snapshot", () => {
156+
const id = start("tool", { tags: { tool_id: "t1", count: 1 } });
157+
end(id);
158+
159+
const first = snapshot();
160+
expect(first).toHaveLength(1);
161+
first[0]!.name = "session";
162+
first[0]!.tags!.tool_id = "POISON";
163+
first[0]!.tags!.count = 999;
164+
first[0]!.parentId = "injected";
165+
first.push({
166+
id: "fake",
167+
name: "session",
168+
startNs: 0n,
169+
endNs: 0n,
170+
});
171+
172+
const second = snapshot();
173+
expect(second).toHaveLength(1);
174+
expect(second[0]!.name).toBe("tool");
175+
expect(second[0]!.tags).toEqual({ tool_id: "t1", count: 1 });
176+
expect(second[0]!.parentId).toBeUndefined();
177+
});
178+
179+
test("mutating an open-span snapshot does not poison open state", () => {
180+
start("session", { tags: { provider_id: "openai" } });
181+
const first = snapshot();
182+
first[0]!.tags!.provider_id = "POISON";
183+
first[0]!.endNs = 1n;
184+
185+
const second = snapshot();
186+
expect(second[0]!.tags).toEqual({ provider_id: "openai" });
187+
expect(second[0]!.endNs).toBeUndefined();
188+
});
189+
});
190+
191+
describe("ring overflow", () => {
192+
test("drops oldest completed spans when capacity is exceeded", () => {
193+
// Fill past capacity with marks (cheap completed spans).
194+
for (let i = 0; i < RING_CAPACITY + 10; i += 1) {
195+
mark("tool", { tags: { count: i } });
196+
}
197+
198+
const spans = snapshot();
199+
expect(spans).toHaveLength(RING_CAPACITY);
200+
201+
// Oldest surviving should be count = 10 (0..9 dropped).
202+
const first = spans[0]!;
203+
const last = spans[spans.length - 1]!;
204+
expect(first.tags?.count).toBe(10);
205+
expect(last.tags?.count).toBe(RING_CAPACITY + 9);
206+
});
207+
208+
test("clear empties ring and open spans", () => {
209+
start("session");
210+
mark("turn");
211+
clear();
212+
expect(snapshot()).toHaveLength(0);
213+
});
214+
});
215+
216+
describe("open span capacity", () => {
217+
test("evicts oldest open span when over OPEN_SPAN_CAPACITY", () => {
218+
const ids: string[] = [];
219+
for (let i = 0; i < OPEN_SPAN_CAPACITY + 5; i += 1) {
220+
ids.push(start("tool", { tags: { count: i } }));
221+
}
222+
223+
const open = snapshot().filter((s) => s.endNs === undefined);
224+
expect(open).toHaveLength(OPEN_SPAN_CAPACITY);
225+
226+
// Oldest five (count 0..4) were evicted; survivors start at count 5.
227+
const counts = open.map((s) => s.tags?.count).sort((a, b) => (a ?? 0) - (b ?? 0));
228+
expect(counts[0]).toBe(5);
229+
expect(counts[counts.length - 1]).toBe(OPEN_SPAN_CAPACITY + 4);
230+
231+
// Ending an evicted id is a no-op; ending a survivor still works.
232+
end(ids[0]!);
233+
end(ids[ids.length - 1]!);
234+
const completed = snapshot().filter((s) => s.endNs !== undefined);
235+
expect(completed).toHaveLength(1);
236+
expect(completed[0]!.tags?.count).toBe(OPEN_SPAN_CAPACITY + 4);
237+
});
238+
});
239+
240+
describe("sanitizeTags", () => {
241+
test("keeps allowlisted enums, numbers, and opaque ids", () => {
242+
const tags = sanitizeTags({
243+
provider_id: "openai",
244+
model_id: "gpt-5.4",
245+
transport: "ws",
246+
duration_ms: 12.5,
247+
bytes: 1024,
248+
payload_bytes: 2048,
249+
count: 2,
250+
input_tokens: 100,
251+
output_tokens: 50,
252+
turn_id: "t1a2b3",
253+
subagent_id: "sa_9",
254+
tool_id: "call-01",
255+
});
256+
expect(tags).toEqual({
257+
provider_id: "openai",
258+
model_id: "gpt-5.4",
259+
transport: "ws",
260+
duration_ms: 12.5,
261+
bytes: 1024,
262+
payload_bytes: 2048,
263+
count: 2,
264+
input_tokens: 100,
265+
output_tokens: 50,
266+
turn_id: "t1a2b3",
267+
subagent_id: "sa_9",
268+
tool_id: "call-01",
269+
});
270+
});
271+
272+
test("strips free-text, paths, prompts, and unknown keys", () => {
273+
const tags = sanitizeTags({
274+
prompt: "system: you are a helpful assistant",
275+
path: "/Users/me/secret/repo/src/main.ts",
276+
error: "ENOENT: no such file or directory",
277+
message: "user said hello",
278+
stack: "Error\n at foo (/app/x.ts:1:1)",
279+
tool_args: JSON.stringify({ cmd: "rm -rf /" }),
280+
completion: "sure, here is the code",
281+
repo: "abklabs/corbits-code",
282+
unknown_key: "whatever",
283+
// also invalid values on allowed keys
284+
transport: "grpc",
285+
model_id: "has spaces and /path",
286+
provider_id: "a".repeat(100),
287+
duration_ms: Number.NaN,
288+
count: Infinity,
289+
bytes: "not-a-number",
290+
});
291+
expect(tags).toBeUndefined();
292+
});
293+
294+
test("returns undefined for null, undefined, or empty input", () => {
295+
expect(sanitizeTags(undefined)).toBeUndefined();
296+
expect(sanitizeTags(null)).toBeUndefined();
297+
expect(sanitizeTags({})).toBeUndefined();
298+
});
299+
300+
test("strips path-like opaque ids", () => {
301+
expect(sanitizeTags({ turn_id: "../../etc/passwd" })).toBeUndefined();
302+
expect(sanitizeTags({ model_id: "C:\\Windows\\System32" })).toBeUndefined();
303+
});
304+
});
305+
306+
describe("open/close budget", () => {
307+
test("start+end stays well under 50µs average", () => {
308+
// Warm up JIT / maps.
309+
for (let i = 0; i < 200; i += 1) {
310+
const id = start("inference");
311+
end(id);
312+
}
313+
clear();
314+
315+
const iterations = 5_000;
316+
const t0 = process.hrtime.bigint();
317+
for (let i = 0; i < iterations; i += 1) {
318+
const id = start("inference", { tags: { provider_id: "openai", model_id: "gpt-5.4" } });
319+
end(id, { duration_ms: 1 });
320+
}
321+
const t1 = process.hrtime.bigint();
322+
const avgNs = Number(t1 - t0) / iterations;
323+
// Budget: open/close on the order of microseconds. 50µs avg is a loose
324+
// ceiling that still fails if we regress into heavy work (I/O, crypto, etc.).
325+
expect(avgNs).toBeLessThan(50_000);
326+
});
327+
});
328+
329+
describe("snapshot shape", () => {
330+
test("completed spans retain only allowlisted fields", () => {
331+
const id = start("adapter.request_build", {
332+
parentId: "parent1",
333+
tags: {
334+
transport: "http_sse",
335+
payload_bytes: 4096,
336+
prompt: "DROP ME",
337+
},
338+
});
339+
end(id);
340+
341+
const span: PerfSpan = snapshot()[0]!;
342+
expect(Object.keys(span).sort()).toEqual(["endNs", "id", "name", "parentId", "startNs", "tags"].sort());
343+
expect(span.tags).toEqual({ transport: "http_sse", payload_bytes: 4096 });
344+
expect(span.parentId).toBe("parent1");
345+
});
346+
});

0 commit comments

Comments
 (0)