diff --git a/src/plugin.ts b/src/plugin.ts index b1cf7ce..0d73687 100644 --- a/src/plugin.ts +++ b/src/plugin.ts @@ -1150,7 +1150,10 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: } log.debug("Proxy request (bun)", { method: req.method, path: url.pathname }); + const reqPerf = new RequestPerf(`bun-${Date.now()}`); const body: any = await req.json().catch(() => ({})); + reqPerf.mark("body-read"); + reqPerf.mark("body-parsed"); const messages: Array = Array.isArray(body?.messages) ? body.messages : []; const stream = body?.stream === true; const tools = Array.isArray(body?.tools) ? body.tools : []; @@ -1179,6 +1182,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const authHeader = req.headers.get("authorization"); const sdkApiKey = resolveRequestSdkApiKey(authHeader); const backend = resolveBackendForRequest(sdkApiKey); + reqPerf.mark("backend-resolved"); const { prompt, resumeChatId, @@ -1196,6 +1200,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: model, workspaceDirectory, }); + reqPerf.mark("prompt-built"); const sessionResumeKeyHash = sessionResumeKey ? sanitizeSessionKey(sessionResumeKey) : undefined; const resumeChatIdHash = resumeChatId ? sanitizeSessionKey(resumeChatId) : undefined; const msgSummaryBun = messages.map((m: any, i: number) => { @@ -1221,6 +1226,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: ); } + reqPerf.mark("child-create-start"); const child = createBunChildForBackend({ backend, sdkApiKey, @@ -1229,6 +1235,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: workspaceDirectory, resumeChatId, }); + reqPerf.mark("child-created"); if (!stream) { const [stdoutText, stderrText] = await Promise.all([ @@ -1341,18 +1348,27 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const encoder = new TextEncoder(); const id = `cursor-acp-${Date.now()}`; const created = Math.floor(Date.now() / 1000); - const perf = new RequestPerf(id); + const perf = reqPerf; const toolMapper = new ToolMapper(); const toolSessionId = id; const passThroughTracker = new PassThroughTracker(); - perf.mark("spawn"); + perf.mark("child-dispatched"); const sse = new ReadableStream({ async start(controller) { let streamTerminated = false; let firstTokenReceived = false; + let firstStdoutByteReceived = false; + let firstSseWritten = false; let sawSuccessfulStreamOutput = false; let usage: OpenAiUsage | undefined; + const enqueueSse = (payload: string) => { + if (!firstSseWritten) { + perf.mark("first-sse-write"); + firstSseWritten = true; + } + controller.enqueue(encoder.encode(payload)); + }; try { const reader = (child.stdout as ReadableStream).getReader(); const converter = new StreamToSseConverter(model, { id, created }); @@ -1368,9 +1384,9 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: boundary.createStreamToolCallChunks({ id, created, model }, toolCall), ); for (const chunk of streamChunks) { - controller.enqueue(encoder.encode(`data: ${JSON.stringify(chunk)}\n\n`)); + enqueueSse(`data: ${JSON.stringify(chunk)}\n\n`); } - controller.enqueue(encoder.encode(formatSseDone())); + enqueueSse(formatSseDone()); streamTerminated = true; try { child.kill(); @@ -1383,8 +1399,8 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: return; } const errChunk = createChatCompletionChunk(id, created, model, message, true); - controller.enqueue(encoder.encode(`data: ${JSON.stringify(errChunk)}\n\n`)); - controller.enqueue(encoder.encode(formatSseDone())); + enqueueSse(`data: ${JSON.stringify(errChunk)}\n\n`); + enqueueSse(formatSseDone()); streamTerminated = true; try { child.kill(); @@ -1398,6 +1414,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const { value, done } = await reader.read(); if (done) break; if (!value || value.length === 0) continue; + if (!firstStdoutByteReceived) { perf.mark("first-stdout-byte"); firstStdoutByteReceived = true; } if (!firstTokenReceived) { perf.mark("first-token"); firstTokenReceived = true; } for (const line of lineBuffer.push(value)) { @@ -1443,10 +1460,10 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: responseMeta: { id, created, model }, passThroughTracker, onToolUpdate: (update) => { - controller.enqueue(encoder.encode(formatToolUpdateEvent(update))); + enqueueSse(formatToolUpdateEvent(update)); }, onToolResult: (toolResult) => { - controller.enqueue(encoder.encode(`data: ${JSON.stringify(toolResult)}\n\n`)); + enqueueSse(`data: ${JSON.stringify(toolResult)}\n\n`); }, onInterceptedToolCall: (toolCall) => { emitToolCallAndTerminate(toolCall); @@ -1460,7 +1477,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: emitTerminalAssistantErrorAndTerminate(result.terminate.message); } else { // Silent termination: just end the stream without an error message - controller.enqueue(encoder.encode(formatSseDone())); + enqueueSse(formatSseDone()); streamTerminated = true; try { child.kill(); } catch { /* ignore */ } } @@ -1479,7 +1496,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: sawSuccessfulStreamOutput = true; } for (const sse of sseChunks) { - controller.enqueue(encoder.encode(sse)); + enqueueSse(sse); } } } @@ -1527,10 +1544,10 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: responseMeta: { id, created, model }, passThroughTracker, onToolUpdate: (update) => { - controller.enqueue(encoder.encode(formatToolUpdateEvent(update))); + enqueueSse(formatToolUpdateEvent(update)); }, onToolResult: (toolResult) => { - controller.enqueue(encoder.encode(`data: ${JSON.stringify(toolResult)}\n\n`)); + enqueueSse(`data: ${JSON.stringify(toolResult)}\n\n`); }, onInterceptedToolCall: (toolCall) => { emitToolCallAndTerminate(toolCall); @@ -1543,7 +1560,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: if (!result.terminate.silent) { emitTerminalAssistantErrorAndTerminate(result.terminate.message); } else { - controller.enqueue(encoder.encode(formatSseDone())); + enqueueSse(formatSseDone()); streamTerminated = true; try { child.kill(); } catch { /* ignore */ } } @@ -1561,7 +1578,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: sawSuccessfulStreamOutput = true; } for (const sse of sseChunks) { - controller.enqueue(encoder.encode(sse)); + enqueueSse(sse); } } if (streamTerminated) { @@ -1594,8 +1611,8 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: failureTextHash: hashForLog(parsed.message), }); const errChunk = createChatCompletionChunk(id, created, model, msg, true); - controller.enqueue(encoder.encode(`data: ${JSON.stringify(errChunk)}\n\n`)); - controller.enqueue(encoder.encode(formatSseDone())); + enqueueSse(`data: ${JSON.stringify(errChunk)}\n\n`); + enqueueSse(formatSseDone()); return; } } @@ -1622,12 +1639,12 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: } const doneChunk = createChatCompletionChunk(id, created, model, "", true); - controller.enqueue(encoder.encode(`data: ${JSON.stringify(doneChunk)}\n\n`)); + enqueueSse(`data: ${JSON.stringify(doneChunk)}\n\n`); if (usage) { const usageChunk = createChatCompletionUsageChunk(id, created, model, usage); - controller.enqueue(encoder.encode(`data: ${JSON.stringify(usageChunk)}\n\n`)); + enqueueSse(`data: ${JSON.stringify(usageChunk)}\n\n`); } - controller.enqueue(encoder.encode(formatSseDone())); + enqueueSse(formatSseDone()); } finally { perf.mark("request:done"); perf.summarize(); @@ -1712,13 +1729,16 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: } log.debug("Proxy request (node)", { method: req.method, path: url.pathname }); + const reqPerf = new RequestPerf(`node-${Date.now()}`); const bodyChunks: Buffer[] = []; for await (const chunk of req) { bodyChunks.push(Buffer.isBuffer(chunk) ? chunk : Buffer.from(chunk)); } + reqPerf.mark("body-read"); const body = Buffer.concat(bodyChunks).toString("utf8"); const bodyData: any = JSON.parse(body || "{}"); + reqPerf.mark("body-parsed"); const messages: Array = Array.isArray(bodyData?.messages) ? bodyData.messages : []; const stream = bodyData?.stream === true; const tools = Array.isArray(bodyData?.tools) ? bodyData.tools : []; @@ -1727,7 +1747,6 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const toolLoopGuard = createToolLoopGuard(messages, TOOL_LOOP_MAX_REPEAT); const boundaryContext = createBoundaryRuntimeContext("node-handler"); - const reqPerf = new RequestPerf(`node-${Date.now()}`); const subagentNames = readSubagentNames(); const model = boundaryContext.run("resolveRuntimeModel", (boundary) => boundary.resolveRuntimeModel(bodyData?.model, bodyData?.cursorModel), @@ -1735,6 +1754,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const authHeaderNode = req.headers["authorization"] as string | undefined; const sdkApiKeyNode = resolveRequestSdkApiKey(authHeaderNode); const backend = resolveBackendForRequest(sdkApiKeyNode); + reqPerf.mark("backend-resolved"); const { prompt, resumeChatId, @@ -1773,13 +1793,13 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: sessionResume: resumeChatId ? { chatIdHash: resumeChatIdHashNode, incremental: usedIncremental } : undefined, }); - reqPerf.mark("backend-resolved"); if (backend === "sdk" && !sdkApiKeyNode) { res.writeHead(401, { "Content-Type": "application/json" }); res.end(JSON.stringify({ error: "Cursor SDK backend requires a real Cursor API key. Set CURSOR_API_KEY or run `opencode auth login`; the legacy `cursor-agent` placeholder is not valid SDK auth." })); return; } + reqPerf.mark("child-create-start"); const child = createNodeChildForBackend({ backend, sdkApiKey: sdkApiKeyNode, @@ -1788,6 +1808,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: workspaceDirectory, resumeChatId, }); + reqPerf.mark("child-created"); if (!stream) { const stdoutChunks: Buffer[] = []; @@ -1915,7 +1936,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const id = `cursor-acp-${Date.now()}`; const created = Math.floor(Date.now() / 1000); const perf = reqPerf; - perf.mark("child-spawned"); + perf.mark("child-dispatched"); const converter = new StreamToSseConverter(model, { id, created }); const lineBuffer = new LineBuffer(); @@ -1925,8 +1946,17 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const stderrChunks: Buffer[] = []; let streamTerminated = false; let firstTokenReceived = false; + let firstStdoutByteReceived = false; + let firstSseWritten = false; let sawSuccessfulStreamOutput = false; let usage: OpenAiUsage | undefined; + const writeSse = (payload: string) => { + if (!firstSseWritten) { + perf.mark("first-sse-write"); + firstSseWritten = true; + } + res.write(payload); + }; child.stderr.on("data", (chunk) => { stderrChunks.push(Buffer.from(chunk)); }); @@ -1939,8 +1969,8 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const parsed = parseAgentError(errSource); const msg = formatErrorForUser(parsed); const errChunk = createChatCompletionChunk(id, created, model, msg, true); - res.write(`data: ${JSON.stringify(errChunk)}\n\n`); - res.write(formatSseDone()); + writeSse(`data: ${JSON.stringify(errChunk)}\n\n`); + writeSse(formatSseDone()); streamTerminated = true; res.end(); }); @@ -1958,9 +1988,9 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: boundary.createStreamToolCallChunks({ id, created, model }, toolCall), ); for (const chunk of streamChunks) { - res.write(`data: ${JSON.stringify(chunk)}\n\n`); + writeSse(`data: ${JSON.stringify(chunk)}\n\n`); } - res.write(formatSseDone()); + writeSse(formatSseDone()); streamTerminated = true; res.end(); try { @@ -1974,8 +2004,8 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: return; } const errChunk = createChatCompletionChunk(id, created, model, message, true); - res.write(`data: ${JSON.stringify(errChunk)}\n\n`); - res.write(formatSseDone()); + writeSse(`data: ${JSON.stringify(errChunk)}\n\n`); + writeSse(formatSseDone()); streamTerminated = true; res.end(); try { @@ -2033,10 +2063,10 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: responseMeta: { id, created, model }, passThroughTracker, onToolUpdate: (update) => { - res.write(formatToolUpdateEvent(update)); + writeSse(formatToolUpdateEvent(update)); }, onToolResult: (toolResult) => { - res.write(`data: ${JSON.stringify(toolResult)}\n\n`); + writeSse(`data: ${JSON.stringify(toolResult)}\n\n`); }, onInterceptedToolCall: (toolCall) => { emitToolCallAndTerminate(toolCall); @@ -2064,7 +2094,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: sawSuccessfulStreamOutput = true; } for (const sse of sseChunks) { - res.write(sse); + writeSse(sse); } } }; @@ -2076,6 +2106,7 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: while (chunkQueue.length > 0) { if (streamTerminated || res.writableEnded) break; const chunk = chunkQueue.shift()!; + if (!firstStdoutByteReceived) { perf.mark("first-stdout-byte"); firstStdoutByteReceived = true; } if (!firstTokenReceived) { perf.mark("first-token"); firstTokenReceived = true; } await processLines(lineBuffer.push(chunk)); } @@ -2112,8 +2143,8 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: const parsed = parseAgentError(errSource); const msg = formatErrorForUser(parsed); const errChunk = createChatCompletionChunk(id, created, model, msg, true); - res.write(`data: ${JSON.stringify(errChunk)}\n\n`); - res.write(formatSseDone()); + writeSse(`data: ${JSON.stringify(errChunk)}\n\n`); + writeSse(formatSseDone()); streamTerminated = true; res.end(); return; @@ -2144,12 +2175,12 @@ async function ensureCursorProxyServer(workspaceDirectory: string, toolRouter?: model, choices: [{ index: 0, delta: {}, finish_reason: "stop" }], }; - res.write(`data: ${JSON.stringify(doneChunk)}\n\n`); + writeSse(`data: ${JSON.stringify(doneChunk)}\n\n`); if (usage) { const usageChunk = createChatCompletionUsageChunk(id, created, model, usage); - res.write(`data: ${JSON.stringify(usageChunk)}\n\n`); + writeSse(`data: ${JSON.stringify(usageChunk)}\n\n`); } - res.write(formatSseDone()); + writeSse(formatSseDone()); streamTerminated = true; res.end(); } diff --git a/src/utils/perf.ts b/src/utils/perf.ts index c85303f..161dc95 100644 --- a/src/utils/perf.ts +++ b/src/utils/perf.ts @@ -7,6 +7,24 @@ export interface PerfMarker { ts: number; } +export interface PerfPhase { + name: string; + deltaMs: number; + atMs: number; +} + +export interface PerfSummary { + requestId: string; + total: number; + phaseTotals: Record; + timeline: PerfPhase[]; +} + +function isTimingLogEnabled(): boolean { + const value = process.env.CURSOR_ACP_TIMING?.toLowerCase(); + return value === "1" || value === "true" || value === "on" || value === "yes"; +} + export class RequestPerf { private markers: PerfMarker[] = []; private readonly requestId: string; @@ -20,16 +38,30 @@ export class RequestPerf { this.markers.push({ name, ts: Date.now() }); } - /** Log timing summary at debug level. Call once at request end. */ - summarize(): void { - if (this.markers.length < 2) return; + /** Log timing summary. Call once at request end. */ + summarize(): PerfSummary | undefined { + if (this.markers.length < 2) return undefined; const start = this.markers[0].ts; - const phases: Record = {}; + const phaseTotals: Record = {}; + const timeline: PerfPhase[] = []; for (let i = 1; i < this.markers.length; i++) { - phases[this.markers[i].name] = this.markers[i].ts - this.markers[i - 1].ts; + const marker = this.markers[i]; + const deltaMs = marker.ts - this.markers[i - 1].ts; + phaseTotals[marker.name] = (phaseTotals[marker.name] ?? 0) + deltaMs; + timeline.push({ + name: marker.name, + deltaMs, + atMs: marker.ts - start, + }); } const total = this.markers[this.markers.length - 1].ts - start; - log.debug("Request timing", { requestId: this.requestId, total, phases }); + const summary: PerfSummary = { requestId: this.requestId, total, phaseTotals, timeline }; + if (isTimingLogEnabled()) { + log.info("Request timing", summary); + } else { + log.debug("Request timing", summary); + } + return summary; } /** Get elapsed ms since construction. */ diff --git a/tests/integration/opencode-loop.integration.test.ts b/tests/integration/opencode-loop.integration.test.ts index 0a26178..885543a 100644 --- a/tests/integration/opencode-loop.integration.test.ts +++ b/tests/integration/opencode-loop.integration.test.ts @@ -1,5 +1,5 @@ import { afterAll, beforeAll, describe, expect, it } from "bun:test"; -import { chmodSync, mkdtempSync, readFileSync, rmSync, writeFileSync } from "fs"; +import { chmodSync, existsSync, mkdtempSync, readFileSync, rmSync, writeFileSync } from "fs"; import { join } from "path"; import { tmpdir } from "os"; @@ -264,6 +264,19 @@ async function requestCompletion(baseURL: string, body: any): Promise return response; } +async function waitForFileText(path: string, requiredText?: string): Promise { + for (let i = 0; i < 20; i++) { + if (existsSync(path)) { + const text = readFileSync(path, "utf8"); + if (text.length > 0 && (requiredText === undefined || text.includes(requiredText))) { + return text; + } + } + await new Promise((resolve) => setTimeout(resolve, 25)); + } + return existsSync(path) ? readFileSync(path, "utf8") : ""; +} + describe("OpenCode-owned tool loop integration", () => { let originalPath = ""; let originalToolLoopMode: string | undefined; @@ -271,9 +284,13 @@ describe("OpenCode-owned tool loop integration", () => { let originalReuseExistingProxy: string | undefined; let originalProviderBoundary: string | undefined; let originalToolLoopMaxRepeat: string | undefined; + let originalTiming: string | undefined; + let originalLogDir: string | undefined; + let originalLogConsole: string | undefined; let mockDir = ""; let promptFile = ""; let argsFile = ""; + let logDir = ""; let baseURL = ""; beforeAll(async () => { @@ -283,9 +300,13 @@ describe("OpenCode-owned tool loop integration", () => { originalReuseExistingProxy = process.env.CURSOR_ACP_REUSE_EXISTING_PROXY; originalProviderBoundary = process.env.CURSOR_ACP_PROVIDER_BOUNDARY; originalToolLoopMaxRepeat = process.env.CURSOR_ACP_TOOL_LOOP_MAX_REPEAT; + originalTiming = process.env.CURSOR_ACP_TIMING; + originalLogDir = process.env.CURSOR_ACP_LOG_DIR; + originalLogConsole = process.env.CURSOR_ACP_LOG_CONSOLE; mockDir = mkdtempSync(join(tmpdir(), "cursor-agent-mock-")); promptFile = join(mockDir, "prompt.txt"); argsFile = join(mockDir, "args.json"); + logDir = join(mockDir, "logs"); const mockCursorPath = join(mockDir, "cursor-agent"); writeFileSync(mockCursorPath, MOCK_CURSOR_AGENT, "utf8"); @@ -297,10 +318,16 @@ describe("OpenCode-owned tool loop integration", () => { process.env.CURSOR_ACP_REUSE_EXISTING_PROXY = "false"; process.env.CURSOR_ACP_PROVIDER_BOUNDARY = "v1"; process.env.CURSOR_ACP_TOOL_LOOP_MAX_REPEAT = "1"; + process.env.CURSOR_ACP_TIMING = "1"; + process.env.CURSOR_ACP_LOG_DIR = logDir; + process.env.CURSOR_ACP_LOG_CONSOLE = "0"; process.env.MOCK_CURSOR_PROMPT_FILE = ""; process.env.MOCK_CURSOR_ARGS_FILE = ""; process.env.MOCK_CURSOR_SCENARIO = "assistant-text"; + const { _resetLoggerState } = await import("../../src/utils/logger"); + _resetLoggerState(); + const { CursorPlugin } = await import("../../src/plugin"); const hooks = await CursorPlugin({ directory: process.cwd(), @@ -325,7 +352,7 @@ describe("OpenCode-owned tool loop integration", () => { baseURL = output.options.baseURL; }); - afterAll(() => { + afterAll(async () => { process.env.PATH = originalPath; if (originalToolLoopMode === undefined) { delete process.env.CURSOR_ACP_TOOL_LOOP_MODE; @@ -352,6 +379,23 @@ describe("OpenCode-owned tool loop integration", () => { } else { process.env.CURSOR_ACP_TOOL_LOOP_MAX_REPEAT = originalToolLoopMaxRepeat; } + if (originalTiming === undefined) { + delete process.env.CURSOR_ACP_TIMING; + } else { + process.env.CURSOR_ACP_TIMING = originalTiming; + } + if (originalLogDir === undefined) { + delete process.env.CURSOR_ACP_LOG_DIR; + } else { + process.env.CURSOR_ACP_LOG_DIR = originalLogDir; + } + if (originalLogConsole === undefined) { + delete process.env.CURSOR_ACP_LOG_CONSOLE; + } else { + process.env.CURSOR_ACP_LOG_CONSOLE = originalLogConsole; + } + const { _resetLoggerState } = await import("../../src/utils/logger"); + _resetLoggerState(); delete process.env.MOCK_CURSOR_PROMPT_FILE; delete process.env.MOCK_CURSOR_ARGS_FILE; delete process.env.MOCK_CURSOR_SCENARIO; @@ -387,6 +431,27 @@ describe("OpenCode-owned tool loop integration", () => { expect(dataLines[dataLines.length - 1]).toBe("[DONE]"); }); + it("writes request timing phases for streaming requests", async () => { + process.env.MOCK_CURSOR_SCENARIO = "assistant-text"; + + const response = await requestCompletion(baseURL, { + model: "auto", + stream: true, + messages: [{ role: "user", content: "Say hello" }], + }); + + await response.text(); + + const logText = await waitForFileText(join(logDir, "plugin.log"), "Request timing"); + expect(logText).toContain("Request timing"); + expect(logText).toContain("body-parsed"); + expect(logText).toContain("prompt-built"); + expect(logText).toContain("backend-resolved"); + expect(logText).toContain("first-stdout-byte"); + expect(logText).toContain("first-sse-write"); + expect(logText).toContain("request:done"); + }); + it("returns non-streaming tool_calls response", async () => { process.env.MOCK_CURSOR_SCENARIO = "tool-read-then-text"; process.env.MOCK_CURSOR_PROMPT_FILE = ""; diff --git a/tests/unit/perf.test.ts b/tests/unit/perf.test.ts index 8e92f66..285b772 100644 --- a/tests/unit/perf.test.ts +++ b/tests/unit/perf.test.ts @@ -47,6 +47,22 @@ describe("RequestPerf", () => { expect(() => perf.summarize()).not.toThrow(); }); + it("summarize preserves repeated marker phases", () => { + const perf = new RequestPerf("test-repeated"); + perf.mark("tool-call"); + perf.mark("tool-call"); + perf.mark("request:done"); + + const summary = perf.summarize(); + + expect(summary?.timeline.map((phase) => phase.name)).toEqual([ + "tool-call", + "tool-call", + "request:done", + ]); + expect(summary?.phaseTotals["tool-call"]).toBeGreaterThanOrEqual(0); + }); + it("markers have monotonically increasing timestamps", () => { const perf = new RequestPerf("test-6"); perf.mark("a");