feat(opencode): per-phase prep timings on turn.done

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<string, SessionV1.ReasoningPart>
 }
 
@@ -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,

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,13 +1271,15 @@ 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),
               instruction.system().pipe(Effect.orDie),
               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,
         })

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)),

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)
+    }
   }),
 )