feat: bootstrap latency instrumentation + phase-label UX

packages/opencode/src/session/prompt.ts

@@ -90,6 +90,50 @@ const STRUCTURED_OUTPUT_SYSTEM_PROMPT = `IMPORTANT: The user has requested struc
 export namespace SessionPrompt {
   const log = Log.create({ service: "session.prompt" })
 
+  // altimate_change start (AI-7519) — first-answer latency instrumentation +
+  // user-facing phase label.
+  //
+  // Wraps an awaited operation with a Tracer span so bootstrap sub-steps are
+  // visible in session traces. Every wrapped await opens a discrete span so a
+  // future regression that adds a slow await also shows up automatically.
+  //
+  // On top of the tracing, publish a session.phase event (start on entry, end
+  // on exit) so the TUI can render an honest label like "Discovering
+  // warehouse tools..." during the pre-first-visible-response window. This is
+  // the SLO half of AI-7519 — target <10s to first *visible* response. The
+  // instrumentation names double as user-facing signal.
+  //
+  // The trace span is a sibling of the root (tracing.ts:1009 assigns
+  // parentSpanId to rootSpanId), not a nested child — good enough for
+  // waterfall correlation via timestamps, and no schema change is required.
+  async function traceSpan<T>(
+    name: string,
+    fn: () => Promise<T>,
+    input?: unknown,
+    sessionID?: SessionID,
+  ): Promise<T> {
+    const startTime = Date.now()
+    if (sessionID) void SessionStatus.publishPhase(sessionID, name, true)
+    try {
+      const result = await fn()
+      Tracer.active?.logSpan({ name, startTime, endTime: Date.now(), input })
+      return result
+    } catch (e) {
+      Tracer.active?.logSpan({
+        name,
+        startTime,
+        endTime: Date.now(),
+        status: "error",
+        input,
+        output: { error: String(e) },
+      })
+      throw e
+    } finally {
+      if (sessionID) void SessionStatus.publishPhase(sessionID, name, false)
+    }
+  }
+  // altimate_change end
+
   // altimate_change start — single source of truth for legacy agent-name normalization
   //
   // The "build" agent was renamed to "builder" but some persisted sessions and
@@ -359,17 +403,61 @@ export namespace SessionPrompt {
     let structuredOutput: unknown | undefined
 
     let step = 0
-    const session = await Session.get(sessionID)
-    // altimate_change start - detect environment fingerprint at session start
-    const altCfg = await Config.get()
-    if (altCfg.experimental?.env_fingerprint_skill_selection === true) {
-      await Fingerprint.detect(Instance.directory, Instance.worktree).catch((e) => {
-        log.warn("fingerprint detection failed", { error: e })
-      })
+    // altimate_change start (AI-7519) — capture bootstrap start; emitted as a
+    // single "bootstrap" span right before the first processor.process call so
+    // the pre-first-generation region has a visible parent duration in traces.
+    const bootstrapStart = Date.now()
+    // Enter busy state BEFORE the first bootstrap traceSpan fires so the
+    // phase labels the TUI renders are actually visible during
+    // session-get / config-get / fingerprint-detect / telemetry-init. The
+    // TUI's status renderer gates on `status.type === "busy"`; without
+    // this early set only `bootstrap.resolve-tools` (which fires inside
+    // the while-loop after the existing busy set at line 506) would show
+    // a label. The while-loop re-set below is now a no-op busy → busy
+    // transition, preserved for legacy call sites that may enter the
+    // loop from elsewhere.
+    await SessionStatus.set(sessionID, { type: "busy" })
+    // altimate_change end
+    // altimate_change start (AI-7519) — discharge the busy status if a bootstrap
+    // await throws. cancel() (prompt.ts:364) deliberately does NOT set idle
+    // when the state entry still exists — it relies on the processor's catch
+    // block for that. But during bootstrap the processor hasn't taken over
+    // yet, so a throw here (Session.get / Config.get / Fingerprint.detect /
+    // Telemetry.init) would leave the session permanently `busy` with no
+    // idle/error transition. Reset to idle on any bootstrap failure and
+    // re-throw so callers still see the error.
+    let session: Awaited<ReturnType<typeof Session.get>>
+    let altCfg: Awaited<ReturnType<typeof Config.get>>
+    try {
+      session = await traceSpan(
+        "bootstrap.session-get",
+        () => Session.get(sessionID),
+        { sessionID },
+        sessionID,
+      )
+      // altimate_change start - detect environment fingerprint at session start
+      altCfg = await traceSpan("bootstrap.config-get", () => Config.get(), undefined, sessionID)
+      if (altCfg.experimental?.env_fingerprint_skill_selection === true) {
+        await traceSpan(
+          "bootstrap.fingerprint-detect",
+          () => Fingerprint.detect(Instance.directory, Instance.worktree),
+          undefined,
+          sessionID,
+        ).catch((e) => {
+          log.warn("fingerprint detection failed", { error: e })
+        })
+      }
+      // altimate_change end
+      // altimate_change start — session telemetry tracking
+      await traceSpan("bootstrap.telemetry-init", () => Telemetry.init(), undefined, sessionID)
+    } catch (e) {
+      // Best-effort transition to idle so the TUI spinner + any busy-gated
+      // callers don't stay stuck. Swallow inner failure so the original
+      // bootstrap error is what bubbles out.
+      await SessionStatus.set(sessionID, { type: "idle" }).catch(() => {})
+      throw e
     }
     // altimate_change end
-    // altimate_change start — session telemetry tracking
-    await Telemetry.init()
     Telemetry.setContext({ sessionId: sessionID, projectId: Instance.project?.id ?? "" })
     const sessionStartTime = Date.now()
     let sessionTotalCost = 0
@@ -913,15 +1001,28 @@ export namespace SessionPrompt {
       const lastUserMsg = msgs.findLast((m) => m.info.role === "user")
       const bypassAgentCheck = lastUserMsg?.parts.some((p) => p.type === "agent") ?? false
 
-      const tools = await resolveTools({
-        agent,
-        session,
-        model,
-        tools: lastUser.tools,
-        processor,
-        bypassAgentCheck,
-        messages: msgs,
-      })
+      // altimate_change start (AI-7519) — trace resolveTools per step.
+      // Included in the parent `bootstrap` span on step===1; on later steps
+      // this measures the per-turn tool-listing overhead (MCP.tools connect
+      // cost etc.). Distinct span name per phase so telemetry doesn't
+      // double-count non-bootstrap turns under "bootstrap.*", and the TUI
+      // falls back to the safe "Thinking..." label on later turns.
+      const tools = await traceSpan(
+        step === 1 ? "bootstrap.resolve-tools" : "turn.resolve-tools",
+        () =>
+          resolveTools({
+            agent,
+            session,
+            model,
+            tools: lastUser.tools,
+            processor,
+            bypassAgentCheck,
+            messages: msgs,
+          }),
+        { step, agent: agent.name },
+        sessionID,
+      )
+      // altimate_change end
 
       // Inject StructuredOutput tool if JSON schema mode enabled
       if (lastUser.format?.type === "json_schema") {
@@ -1070,6 +1171,25 @@ export namespace SessionPrompt {
           input: { agent: agent.name, step },
           output: { parts: system.length, content: system.join("\n\n") },
         })
+        // altimate_change start (AI-7519) — emit the parent bootstrap span
+        // covering everything from loop() entry to just-before-first-generation.
+        // Companion sub-spans (bootstrap.session-get, bootstrap.config-get,
+        // bootstrap.resolve-tools, etc.) are already emitted; this span gives
+        // the waterfall a single top-level duration to render + gate against.
+        // Capture endTime once so duration_ms is guaranteed to match — two
+        // Date.now() calls can straddle a clock tick.
+        const bootstrapEnd = Date.now()
+        Tracer.active?.logSpan({
+          name: "bootstrap",
+          startTime: bootstrapStart,
+          endTime: bootstrapEnd,
+          input: { agent: agent.name, sessionID },
+          output: {
+            duration_ms: bootstrapEnd - bootstrapStart,
+            system_parts: system.length,
+          },
+        })
+        // altimate_change end
       }
       // altimate_change end
 

packages/opencode/src/session/status.ts

@@ -53,6 +53,22 @@ export const Event = {
       sessionID: SessionID,
     },
   }),
+  // altimate_change start (AI-7519) — session.phase carries the currently-active bootstrap or per-turn
+  // sub-step name so the TUI can render an honest "Loading config..." / "Discovering tools..." label
+  // during the invisible pre-first-visible-response window (target <10s to first visible response).
+  Phase: EventV2.define({
+    type: "session.phase",
+    schema: {
+      sessionID: SessionID,
+      // Sub-span name from the traceSpan wrapper — e.g. "bootstrap.resolve-tools". The TUI maps
+      // this to a human label; unknown phases fall back to "Thinking...".
+      phase: Schema.String,
+      // true when the phase opens, false when it closes. TUI clears the label on close if it
+      // matches the currently-rendered phase.
+      active: Schema.Boolean,
+    },
+  }),
+  // altimate_change end
 }
 
 // altimate_change start - mirror status events onto the legacy Bus SSE stream
@@ -71,13 +87,28 @@ const LegacyEvent = {
       sessionID: SessionID.zod,
     }),
   ),
+  // altimate_change start (AI-7519) — legacy SSE mirror for the phase event
+  Phase: BusEvent.define(
+    "session.phase",
+    z.object({
+      sessionID: SessionID.zod,
+      phase: z.string(),
+      active: z.boolean(),
+    }),
+  ),
+  // altimate_change end
 }
 // altimate_change end
 
 export interface Interface {
   readonly get: (sessionID: SessionID) => Effect.Effect<Info>
   readonly list: () => Effect.Effect<Map<SessionID, Info>>
   readonly set: (sessionID: SessionID, status: Info) => Effect.Effect<void>
+  // altimate_change start (AI-7519) — publish a session.phase event through
+  // the EventV2 bus so V2 subscribers see phase transitions alongside the
+  // legacy bus mirror.
+  readonly publishPhase: (sessionID: SessionID, phase: string, active: boolean) => Effect.Effect<void>
+  // altimate_change end
 }
 
 export class Service extends Context.Service<Service, Interface>()("@opencode/SessionStatus") {}
@@ -111,7 +142,19 @@ export const layer = Layer.effect(
       data.set(sessionID, status)
     })
 
-    return Service.of({ get, list, set })
+    // altimate_change start (AI-7519) — V2 publish for the session.phase event.
+    // Complements the LegacyEvent.Phase publish that happens in the imperative
+    // wrapper below so both V1 (SSE mirror) and V2 subscribers see phases.
+    const publishPhase = Effect.fn("SessionStatus.publishPhase")(function* (
+      sessionID: SessionID,
+      phase: string,
+      active: boolean,
+    ) {
+      yield* events.publish(Event.Phase, { sessionID, phase, active })
+    })
+    // altimate_change end
+
+    return Service.of({ get, list, set, publishPhase })
   }),
 )
 
@@ -142,4 +185,27 @@ export async function list() {
 }
 // altimate_change end
 
+// altimate_change start (AI-7519) — publish a session.phase event. Fired by SessionPrompt.traceSpan
+// on entry (active=true) and exit (active=false); the TUI subscribes to render an honest label like
+// "Discovering warehouse tools..." during the pre-first-visible-response window. Publishes on both
+// the EventV2 bus (for V2 subscribers) and the LegacyEvent.Phase bus (for the SSE mirror the TUI
+// consumes). Best-effort: any failure here must not affect the traced operation itself. The two
+// publishes are intentionally sequential (V2 first, legacy second) — an earlier attempt to
+// parallelise them via `Promise.allSettled` produced intermittent e2e failures where the label
+// wouldn't render, likely because the first ManagedRuntime warm-up races with the immediate
+// legacy Bus.publish. Sequential is reliable + the cost is negligible on the hot path.
+export async function publishPhase(sessionID: SessionID, phase: string, active: boolean) {
+  try {
+    await runStatus((s) => s.publishPhase(sessionID, phase, active))
+  } catch {
+    // never surface phase-publish failures back to the caller
+  }
+  try {
+    await Bus.publish(LegacyEvent.Phase, { sessionID, phase, active })
+  } catch {
+    // never surface phase-publish failures back to the caller
+  }
+}
+// altimate_change end
+
 export * as SessionStatus from "./status"

packages/opencode/test/cli/tui/phase-label.tui-e2e.test.ts

@@ -0,0 +1,93 @@
+/**
+ * TUI e2e — AI-7519: phase-label renders during the busy pre-first-visible-response window.
+ *
+ * The <10s-to-first-visible-response half of AI-7519 relies on the server
+ * publishing session.phase events (fired by SessionPrompt.traceSpan on entry
+ * and exit) and the TUI subscribing + rendering an honest label like
+ * "Discovering tools..." or the "Thinking..." fallback next to the busy
+ * spinner. Every static check + unit test can pass while the actual TUI
+ * render silently drops the label — the AI-6298 experience demonstrated
+ * exactly that failure mode. This spec drives the real TUI end-to-end so the
+ * label is verified against the user's actual view.
+ *
+ * Two hard assertions:
+ *   1. The "Thinking..." fallback renders during any busy window — proves
+ *      the render chain (status → phaseLabel → spinner row) is intact.
+ *   2. A specific mapped label ("Discovering tools") renders somewhere in
+ *      the run — proves the full phase-event pipeline (publishPhase →
+ *      Bus.publish → sync.tsx handler → store update → render) is intact
+ *      end-to-end. Without this, a regression that entirely broke phase
+ *      publishing would still green here because the fallback renders
+ *      regardless.
+ *
+ * "Discovering tools" is the label mapped from `bootstrap.resolve-tools`,
+ * whose span duration (~30-100ms while listing MCP tools) is comfortably
+ * larger than the PTY harness poll interval (50ms). The other bootstrap
+ * sub-spans are sub-millisecond and observed to not survive PTY sampling —
+ * a diagnostic dump of all specific label hits is retained for future
+ * timing-driven debugging.
+ */
+
+import { describe, expect, test } from "bun:test"
+import { launchTui } from "../../fixture/pty-tui"
+import { tmpdir } from "../../fixture/fixture"
+
+describe("TUI e2e — AI-7519 phase-label render", () => {
+  test("phase-label pipeline renders 'Discovering tools' + 'Thinking...' fallback beside the busy spinner", async () => {
+    // await using ensures the temp directory is cleaned up even if launchTui
+    // rejects before the try block — matches the codebase convention in
+    // scheduler.test.ts and the coding guideline enforced by CI.
+    await using tmp = await tmpdir()
+    const tui = await launchTui({
+      cwd: tmp.path,
+      cols: 140,
+      rows: 50,
+      waitForReady: "Ask anything",
+    })
+    try {
+      // Type a short prompt and submit it. The exact content doesn't matter —
+      // we're driving the session-prompt loop() to fire, which runs the
+      // bootstrap traceSpan wrappers that publish session.phase events. The
+      // loop() runs before any LLM call, so this works even if the machine
+      // has no provider auth configured — the phase labels fire during
+      // bootstrap, and the busy state is entered before the eventual error
+      // banner (if any) resolves.
+      for (const ch of "hi") {
+        tui.write(ch)
+        await new Promise((r) => setTimeout(r, 25))
+      }
+      tui.sendKey("Enter")
+
+      // (1) Fallback assertion — proves the render chain is alive.
+      // phaseLabel(undefined) renders "Thinking..." during any busy window
+      // without a specific phase name mapped.
+      await tui.waitForText(/Thinking\.\.\./, { timeoutMs: 8000 })
+
+      // (2) Mapped-label assertion — proves the full phase pipeline is alive.
+      // "Discovering tools" is the label for `bootstrap.resolve-tools`, which
+      // fires on step===1 inside loop(). Its span (MCP tool listing) is
+      // reliably longer than the PTY poll interval. Regression that breaks
+      // publishPhase / Bus.publish / sync handler / store update would fail
+      // this assertion even though the fallback above still succeeds.
+      await tui.waitForText("Discovering tools", { timeoutMs: 8000 })
+
+      // Diagnostic dump of any other mapped labels that landed — helpful for
+      // future timing-related debugging without gating the test on
+      // sub-millisecond span durations we can't reliably observe over PTY.
+      const rendered = tui.text()
+      const specificLabels = {
+        "Loading session": rendered.includes("Loading session"),
+        "Loading config": rendered.includes("Loading config"),
+        "Discovering tools": rendered.includes("Discovering tools"),
+        "Preparing telemetry": rendered.includes("Preparing telemetry"),
+        "Detecting project shape": rendered.includes("Detecting project shape"),
+      }
+      // eslint-disable-next-line no-console
+      console.log("[AI-7519 e2e] specific label hits:", JSON.stringify(specificLabels))
+      expect(rendered).toContain("Thinking...")
+      expect(rendered).toContain("Discovering tools")
+    } finally {
+      await tui.dispose()
+    }
+  }, 45_000)
+})