Log per-turn timing checkpoints in the Logs tab

[Cellcote]

Summary

• The Logs tab was nearly empty during a turn, so there was no way to tell where a slow response (especially on fusion sessions with multiple --add-dirs) was spending its time.
• Stamp elapsed wallclock at each checkpoint — first stream event, first model text, first tool call, and per-tool completion — so the user can see the breakdown directly.
• Turn started now also reports add-dirs=N and resume/fresh so it's obvious when fusion fan-out and JSONL replay are in play.

Notes

• INF: turn-level checkpoints (one or two extra lines per turn).
• DBG: per-tool start/done (still rendered, just dimmed).
• First stream event after Xms (CLI cold start + add-dir loading + resume replay) is the smoking-gun line for diagnosing slow fusion turns.

[greptile-apps]

Greptile Summary

• Introduces a turn-scoped TurnTimings class wrapping a Stopwatch plus three one-shot flags and a Dictionary<string, long> for per-tool start timestamps, then wires four new INF checkpoints ("Turn started" now includes add-dirs and fresh/resume, "First stream event", "First model text", "First tool call") and DBG per-tool start/done lines into Handle and AppendAssistantMessage.
• The only notable edge case: LoggedFirstTool and the "First tool call" log fire before the early break for TodoWrite and Task (both invisible in the UI), so those silent tools can claim the checkpoint without producing a matching "starting"/"done" pair in the Logs tab.

Confidence Score: 4/5

Safe to merge — the change is purely additive logging with no mutations to business logic or state management.

Only P2 findings present: the LoggedFirstTool flag firing on TodoWrite/Task before their early break is a cosmetic asymmetry in the Logs tab, not a correctness or data-integrity issue. No P0 or P1 issues identified.

No files require special attention; the single changed file is self-contained logging instrumentation.

Important Files Changed

Filename

Overview

src/Conclave.App/Claude/ClaudeService.cs

Adds per-turn TurnTimings class (Stopwatch + flag fields + ToolStartMs dict) and emits four new log checkpoints: "Turn started" (enriched), "First stream event", "First model text", "First tool call", plus per-tool start/done DBG lines. One minor inconsistency: LoggedFirstTool is set before the early-break for TodoWrite/Task, so those invisible tools claim the "First tool call" checkpoint without a matching start/done pair.

Sequence Diagram

sequenceDiagram
    participant UI as UI Thread
    participant CS as ClaudeService
    participant TT as TurnTimings (Stopwatch)
    participant Log as Logs Tab

    UI->>CS: RunTurnAsync()
    CS->>TT: new TurnTimings() [timer starts]
    CS->>Log: "Turn started (model, branch, add-dirs, fresh/resume)"
    CS->>CS: await Task.Yield()
    CS->>CS: _client.StreamAsync() begins

    Note over CS,TT: First event arrives
    CS->>TT: LoggedFirstEvent = true
    CS->>Log: "First stream event after Xms"

    Note over CS,TT: First text_delta with content
    CS->>TT: LoggedFirstText = true
    CS->>Log: "First model text after Xms"

    Note over CS,TT: First ToolUseContent
    CS->>TT: LoggedFirstTool = true
    CS->>Log: "First tool call after Xms"
    CS->>TT: ToolStartMs[tu.Id] = elapsed
    CS->>Log: DBG "tool X starting"

    Note over CS,TT: Matching tool_result arrives
    CS->>TT: ToolStartMs.Remove(tu.Id, out startMs)
    CS->>Log: DBG "tool X done after Yms (ok/fail)"

    CS->>Log: "Turn completed (stopReason, ms, cost)"

Loading

_{Reviews (1): Last reviewed commit: "Log per-turn timing checkpoints in the L..." | Re-trigger Greptile}

[greptile-apps]

LoggedFirstTool set before early-break for silent tools

timings.LoggedFirstTool = true and the "First tool call after Xms" log fire even when tu.Name is TodoWrite or Task, which both break before ToolStartMs is populated and before any "tool X starting" log is emitted. If one of these invisible tools is the first ToolUseContent in the turn, the Logs tab will show "First tool call after Xms" with no matching "tool … starting" or "tool … done" line — making the timing log misleading for diagnosing that specific turn.