diff --git a/packages/opencode/src/session/processor.ts b/packages/opencode/src/session/processor.ts index 2bfde3434daf..c6689252cd51 100644 --- a/packages/opencode/src/session/processor.ts +++ b/packages/opencode/src/session/processor.ts @@ -34,6 +34,7 @@ export interface Handle { readonly firstTokenAt: number | undefined readonly requestStartAt: number | undefined readonly firstRequestStartAt: number | undefined + readonly snapshotMs: number readonly updateToolCall: ( toolCallID: string, update: (part: SessionV1.ToolPart) => SessionV1.ToolPart, @@ -77,6 +78,7 @@ interface ProcessorContext extends Input { firstTokenAt: number | undefined requestStartAt: number | undefined firstRequestStartAt: number | undefined + snapshotMs: number reasoningMap: Record } @@ -105,6 +107,7 @@ const layer = Layer.effect( // Pre-capture snapshot before the LLM stream starts. The AI SDK // may execute tools internally before emitting start-step events, // so capturing inside the event handler can be too late. + const snapshotStart = Date.now() const initialSnapshot = yield* snapshot.track() const ctx: ProcessorContext = { assistantMessage: input.assistantMessage, @@ -113,6 +116,7 @@ const layer = Layer.effect( toolcalls: {}, shouldBreak: false, snapshot: initialSnapshot, + snapshotMs: Date.now() - snapshotStart, blocked: false, needsCompaction: false, currentText: undefined, @@ -709,6 +713,9 @@ const layer = Layer.effect( get firstRequestStartAt() { return ctx.firstRequestStartAt }, + get snapshotMs() { + return ctx.snapshotMs + }, updateToolCall, completeToolCall, process, diff --git a/packages/opencode/src/session/prompt.ts b/packages/opencode/src/session/prompt.ts index 2af0dd530da8..80363a2f29a1 100644 --- a/packages/opencode/src/session/prompt.ts +++ b/packages/opencode/src/session/prompt.ts @@ -1092,15 +1092,21 @@ const layer = Layer.effect( let firstTokenReqStart: number | undefined let firstRequestStartAt: number | undefined let ttftStep: number | undefined + let historyMs = 0 + let toolsMs = 0 + let contextMs = 0 + let snapshotMs = 0 const session = yield* sessions.get(sessionID).pipe(Effect.orDie) while (true) { yield* status.set(sessionID, { type: "busy" }) yield* Effect.logInfo("loop", { "session.id": sessionID, step }) + const historyStart = Date.now() let msgs = yield* MessageV2.filterCompactedEffect(sessionID).pipe( Effect.provideService(Database.Service, database), ) + historyMs += Date.now() - historyStart const { user: lastUser, assistant: lastAssistant, finished: lastFinished, tasks } = MessageV2.latest(msgs) @@ -1232,6 +1238,7 @@ const layer = Layer.effect( const bypassAgentCheck = lastUserMsg?.parts.some((p) => p.type === "agent") ?? false const promptOps = yield* ops() + const toolsStart = Date.now() const tools = yield* SessionTools.resolve({ agent, session, @@ -1248,6 +1255,7 @@ const layer = Layer.effect( Effect.provideService(Truncate.Service, truncate), Effect.provideService(RuntimeFlags.Service, flags), ) + toolsMs += Date.now() - toolsStart if (lastUser.format?.type === "json_schema") { tools["StructuredOutput"] = createStructuredOutputTool({ @@ -1263,6 +1271,7 @@ const layer = Layer.effect( yield* plugin.trigger("experimental.chat.messages.transform", {}, { messages: msgs }) + const contextStart = Date.now() const [skills, env, instructions, mcpInstructions, modelMsgs] = yield* Effect.all([ sys.skills(agent), sys.environment(model), @@ -1270,6 +1279,7 @@ const layer = Layer.effect( sys.mcp(agent, session.permission), MessageV2.toModelMessagesEffect(msgs, model), ]) + contextMs += Date.now() - contextStart const system = [ ...env, ...instructions, @@ -1299,6 +1309,7 @@ const layer = Layer.effect( if (firstRequestStartAt === undefined && handle.firstRequestStartAt !== undefined) { firstRequestStartAt = handle.firstRequestStartAt } + snapshotMs += handle.snapshotMs if (firstTokenAt === undefined && handle.firstTokenAt !== undefined) { firstTokenAt = handle.firstTokenAt firstTokenReqStart = handle.requestStartAt @@ -1364,6 +1375,10 @@ const layer = Layer.effect( : undefined, prep_ms: firstRequestStartAt !== undefined ? firstRequestStartAt - turnStart : undefined, ttft_step: ttftStep, + history_ms: historyMs, + tools_ms: toolsMs, + context_ms: contextMs, + snapshot_ms: snapshotMs, turn_ms: Date.now() - turnStart, steps: step, }) diff --git a/packages/opencode/test/session/compaction.test.ts b/packages/opencode/test/session/compaction.test.ts index 2ddd7cc2b558..1878cec50fc9 100644 --- a/packages/opencode/test/session/compaction.test.ts +++ b/packages/opencode/test/session/compaction.test.ts @@ -205,6 +205,7 @@ function fake( firstTokenAt: undefined, requestStartAt: undefined, firstRequestStartAt: undefined, + snapshotMs: 0, updateToolCall: Effect.fn("TestSessionProcessor.updateToolCall")(() => Effect.succeed(undefined)), completeToolCall: Effect.fn("TestSessionProcessor.completeToolCall")(() => Effect.void), process: Effect.fn("TestSessionProcessor.process")(() => Effect.succeed(result)), diff --git a/packages/opencode/test/session/prompt.test.ts b/packages/opencode/test/session/prompt.test.ts index fc5c5796d829..9272720dcb07 100644 --- a/packages/opencode/test/session/prompt.test.ts +++ b/packages/opencode/test/session/prompt.test.ts @@ -851,6 +851,10 @@ it.instance("turn.done logs prep_ms from the first request even when ttft captur // prep_ms must reflect step 1's request, which started before step 2's first token. expect(typeof fields.prep_ms).toBe("number") expect(fields.prep_ms!).toBeLessThanOrEqual(fields.ttft_ms!) + for (const phase of ["history_ms", "tools_ms", "context_ms", "snapshot_ms"] as const) { + expect(typeof fields[phase]).toBe("number") + expect(fields[phase]!).toBeGreaterThanOrEqual(0) + } }), )