fix(opencode): log prep_ms and ttft_step on turn.done

packages/opencode/src/session/processor.ts

@@ -33,6 +33,7 @@ export interface Handle {
   readonly message: SessionV1.Assistant
   readonly firstTokenAt: number | undefined
   readonly requestStartAt: number | undefined
+  readonly firstRequestStartAt: number | undefined
   readonly updateToolCall: (
     toolCallID: string,
     update: (part: SessionV1.ToolPart) => SessionV1.ToolPart,
@@ -75,6 +76,7 @@ interface ProcessorContext extends Input {
   currentText: SessionV1.TextPart | undefined
   firstTokenAt: number | undefined
   requestStartAt: number | undefined
+  firstRequestStartAt: number | undefined
   reasoningMap: Record<string, SessionV1.ReasoningPart>
 }
 
@@ -116,6 +118,7 @@ const layer = Layer.effect(
         currentText: undefined,
         firstTokenAt: undefined,
         requestStartAt: undefined,
+        firstRequestStartAt: undefined,
         reasoningMap: {},
       }
       let aborted = false
@@ -646,6 +649,8 @@ const layer = Layer.effect(
             ctx.reasoningMap = {}
             yield* status.set(ctx.sessionID, { type: "busy" })
             ctx.requestStartAt = Date.now()
+            // Retries re-stamp requestStartAt; keep the first attempt so prep_ms excludes backoff.
+            if (ctx.firstRequestStartAt === undefined) ctx.firstRequestStartAt = ctx.requestStartAt
             const stream = llm.stream(streamInput)
 
             yield* stream.pipe(
@@ -701,6 +706,9 @@ const layer = Layer.effect(
         get requestStartAt() {
           return ctx.requestStartAt
         },
+        get firstRequestStartAt() {
+          return ctx.firstRequestStartAt
+        },
         updateToolCall,
         completeToolCall,
         process,

packages/opencode/src/session/prompt.ts

@@ -1090,6 +1090,8 @@ const layer = Layer.effect(
         const turnStart = Date.now()
         let firstTokenAt: number | undefined
         let firstTokenReqStart: number | undefined
+        let firstRequestStartAt: number | undefined
+        let ttftStep: number | undefined
         const session = yield* sessions.get(sessionID).pipe(Effect.orDie)
 
         while (true) {
@@ -1292,9 +1294,15 @@ const layer = Layer.effect(
               toolChoice: format.type === "json_schema" ? "required" : undefined,
             })
 
+            // A tool-only first step emits no token, so the ttft pair can capture from a later
+            // step and straddle tool execution; prep_ms and ttft_step exist to keep that honest.
+            if (firstRequestStartAt === undefined && handle.firstRequestStartAt !== undefined) {
+              firstRequestStartAt = handle.firstRequestStartAt
+            }
             if (firstTokenAt === undefined && handle.firstTokenAt !== undefined) {
               firstTokenAt = handle.firstTokenAt
               firstTokenReqStart = handle.requestStartAt
+              ttftStep = step
             }
 
             if (structured !== undefined) {
@@ -1354,6 +1362,8 @@ const layer = Layer.effect(
             firstTokenAt !== undefined && firstTokenReqStart !== undefined
               ? firstTokenAt - firstTokenReqStart
               : undefined,
+          prep_ms: firstRequestStartAt !== undefined ? firstRequestStartAt - turnStart : undefined,
+          ttft_step: ttftStep,
           turn_ms: Date.now() - turnStart,
           steps: step,
         })

packages/opencode/test/session/compaction.test.ts

@@ -204,6 +204,7 @@ function fake(
     },
     firstTokenAt: undefined,
     requestStartAt: undefined,
+    firstRequestStartAt: undefined,
     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

@@ -6,7 +6,7 @@ import { SessionProjector } from "@opencode-ai/core/session/projector"
 import { eq } from "drizzle-orm"
 import { EventV2Bridge } from "@/event-v2-bridge"
 import { expect } from "bun:test"
-import { Cause, Deferred, Duration, Effect, Exit, Fiber, Layer, Option } from "effect"
+import { Cause, Deferred, Duration, Effect, Exit, Fiber, Layer, Logger, Option, References } from "effect"
 import path from "path"
 import { fileURLToPath } from "url"
 import { NamedError } from "@opencode-ai/core/util/error"
@@ -814,6 +814,46 @@ it.instance("loop continues when finish is tool-calls", () =>
   }),
 )
 
+it.instance("turn.done logs prep_ms from the first request even when ttft captures from a later step", () =>
+  Effect.gen(function* () {
+    const { llm } = yield* useServerConfig(providerCfg)
+    const prompt = yield* SessionPrompt.Service
+    const sessions = yield* Session.Service
+    const session = yield* sessions.create({
+      title: "Turn timing",
+      permission: [{ permission: "*", pattern: "*", action: "allow" }],
+    })
+    yield* prompt.prompt({
+      sessionID: session.id,
+      agent: "build",
+      noReply: true,
+      parts: [{ type: "text", text: "hello" }],
+    })
+    yield* llm.tool("first", { value: "first" })
+    yield* llm.text("second")
+
+    const captured: Array<unknown> = []
+    const capture = Logger.make((options) => {
+      captured.push(options.message)
+    })
+    yield* prompt.loop({ sessionID: session.id }).pipe(
+      Effect.provide(Logger.layer([capture], { mergeWithExisting: true })),
+      Effect.provide(Layer.succeed(References.MinimumLogLevel, "Debug")),
+    )
+
+    const message = captured.find((item) => Array.isArray(item) && item[0] === "turn.done")
+    expect(message).toBeDefined()
+    if (!Array.isArray(message)) return
+    const fields = message[1] as Record<string, number | undefined>
+    expect(fields.steps).toBe(2)
+    // Step 1 was tool-only, so the ttft pair comes from step 2 — the cross-step hazard.
+    expect(fields.ttft_step).toBe(2)
+    // 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!)
+  }),
+)
+
 it.instance("glob tool keeps instance context during prompt runs", () =>
   Effect.gen(function* () {
     const { dir, llm } = yield* useServerConfig(providerCfg)