From 05023c3b8914e8ba7371e8e8250db863f8930831 Mon Sep 17 00:00:00 2001 From: Andrew Date: Sun, 23 Aug 2026 18:46:49 -0700 Subject: [PATCH 1/2] fix(opencode): log prep_ms and ttft_step on turn.done Co-Authored-By: Claude Fable 5 --- packages/opencode/src/session/prompt.ts | 10 +++++ packages/opencode/test/session/prompt.test.ts | 42 ++++++++++++++++++- 2 files changed, 51 insertions(+), 1 deletion(-) diff --git a/packages/opencode/src/session/prompt.ts b/packages/opencode/src/session/prompt.ts index 69dca1211a83..1337c05d3f42 100644 --- a/packages/opencode/src/session/prompt.ts +++ b/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.requestStartAt !== undefined) { + firstRequestStartAt = handle.requestStartAt + } 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, }) diff --git a/packages/opencode/test/session/prompt.test.ts b/packages/opencode/test/session/prompt.test.ts index 818035e4275c..fc5c5796d829 100644 --- a/packages/opencode/test/session/prompt.test.ts +++ b/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 = [] + 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 + 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) From 82ad220069da7a6532b3fc645d1033225ad241ef Mon Sep 17 00:00:00 2001 From: Andrew Date: Sun, 23 Aug 2026 19:05:22 -0700 Subject: [PATCH 2/2] fix(opencode): stamp firstRequestStartAt once so prep_ms excludes retry backoff Co-Authored-By: Claude Fable 5 --- packages/opencode/src/session/processor.ts | 8 ++++++++ packages/opencode/src/session/prompt.ts | 4 ++-- packages/opencode/test/session/compaction.test.ts | 1 + 3 files changed, 11 insertions(+), 2 deletions(-) diff --git a/packages/opencode/src/session/processor.ts b/packages/opencode/src/session/processor.ts index 710fd47682b3..2bfde3434daf 100644 --- a/packages/opencode/src/session/processor.ts +++ b/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 } @@ -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, diff --git a/packages/opencode/src/session/prompt.ts b/packages/opencode/src/session/prompt.ts index 1337c05d3f42..2af0dd530da8 100644 --- a/packages/opencode/src/session/prompt.ts +++ b/packages/opencode/src/session/prompt.ts @@ -1296,8 +1296,8 @@ const layer = Layer.effect( // 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.requestStartAt !== undefined) { - firstRequestStartAt = handle.requestStartAt + if (firstRequestStartAt === undefined && handle.firstRequestStartAt !== undefined) { + firstRequestStartAt = handle.firstRequestStartAt } if (firstTokenAt === undefined && handle.firstTokenAt !== undefined) { firstTokenAt = handle.firstTokenAt diff --git a/packages/opencode/test/session/compaction.test.ts b/packages/opencode/test/session/compaction.test.ts index 73a46689e2d5..2ddd7cc2b558 100644 --- a/packages/opencode/test/session/compaction.test.ts +++ b/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)),