Skip to content

Log per-turn timing checkpoints in the Logs tab #60

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
Cellcote wants to merge 1 commit into
base: main
Choose a base branch
from
+55 −5
Open

Log per-turn timing checkpoints in the Logs tab #60

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
60 changes: 55 additions & 5 deletions src/Conclave.App/Claude/ClaudeService.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
using System.Diagnostics;
using System.Text;
using System.Text.Json;
using Conclave.App.Sessions;
Expand Down Expand Up @@ -63,7 +64,11 @@ public async Task RunTurnAsync(SessionVm session, string prompt, bool isAutoResu
session.AppendTranscript(userMsg);
_manager.PersistMessage(session, userMsg);

Log(session, LogLevel.Inf, $"Turn started (model={session.Model}, branch={session.Branch})");
var timings = new TurnTimings();
var resumeLabel = string.IsNullOrEmpty(session.ClaudeSessionId) ? "fresh" : "resume";
Log(session, LogLevel.Inf,
$"Turn started (model={session.Model}, branch={session.Branch}, " +
$"add-dirs={session.AdditionalDirs.Count}, {resumeLabel})");
_manager.UpdateStatus(session, SessionStatus.Working);

// Let the dispatcher render the user's bubble + Working status before we spawn the
Expand Down Expand Up @@ -106,7 +111,14 @@ public async Task RunTurnAsync(SessionVm session, string prompt, bool isAutoResu
settingsJson: settingsJson,
ct: linked.Token))
{
Handle(session, ev, toolsById, messageByToolId, liveByMessageId, permHandler);
if (!timings.LoggedFirstEvent)
{
timings.LoggedFirstEvent = true;
Log(session, LogLevel.Inf,
$"First stream event after {timings.Total.ElapsedMilliseconds}ms " +
"(CLI cold start + add-dir loading + resume replay)");
}
Handle(session, ev, toolsById, messageByToolId, liveByMessageId, permHandler, timings);
}
// The stream completed without throwing — claude has consumed the preamble (it
// was injected into the system prompt of this invocation). Clear it so future
Expand Down Expand Up @@ -180,6 +192,19 @@ private static void Log(SessionVm session, LogLevel level, string message) =>
TimestampUtc = DateTime.UtcNow,
});

// Per-turn timing scratch. Wallclock from the moment we start the turn — used to log
// checkpoint latencies (first stream event, first text, first tool call) so the user
// can see where a slow turn is spending its time. Per-tool start times live here too
// so the matching tool_result can log how long the tool itself took.
private sealed class TurnTimings
{
public Stopwatch Total { get; } = Stopwatch.StartNew();
public bool LoggedFirstEvent { get; set; }
public bool LoggedFirstText { get; set; }
public bool LoggedFirstTool { get; set; }
public Dictionary<string, long> ToolStartMs { get; } = new();
}

// Per-live-message scratch state. Buffer accumulates text_delta payloads cheaply;
// VM.Content is only refreshed periodically (see HandleStreamDelta) so a long response
// with thousands of deltas doesn't allocate a full new string per delta.
Expand All @@ -197,7 +222,8 @@ private void Handle(
Dictionary<string, ToolCallVm> toolsById,
Dictionary<string, TranscriptMessageVm> messageByToolId,
Dictionary<string, LiveAssistantState> liveByMessageId,
PermissionTurnHandler? permHandler)
PermissionTurnHandler? permHandler,
TurnTimings timings)
{
// StallDetectionService checks how long ago the last event was — stamp on every
// type so a long-running tool (no text deltas for minutes) doesn't false-positive.
Expand All @@ -219,11 +245,20 @@ private void Handle(
break;

case StreamDeltaEvent delta:
if (!timings.LoggedFirstText
&& delta.EventType == "content_block_delta"
&& delta.DeltaType == "text_delta"
&& !string.IsNullOrEmpty(delta.DeltaText))
{
timings.LoggedFirstText = true;
Log(session, LogLevel.Inf,
$"First model text after {timings.Total.ElapsedMilliseconds}ms");
}
HandleStreamDelta(session, delta, liveByMessageId);
break;

case AssistantEvent asst:
AppendAssistantMessage(session, asst, toolsById, messageByToolId, liveByMessageId, permHandler);
AppendAssistantMessage(session, asst, toolsById, messageByToolId, liveByMessageId, permHandler, timings);
break;

case UserEvent user:
Expand All @@ -236,6 +271,12 @@ private void Handle(
vm.Meta = MetaFromResult(vm.Kind, tr.Content);
if (messageByToolId.TryGetValue(tr.ToolUseId, out var owner))
touched.Add(owner);
if (timings.ToolStartMs.Remove(tr.ToolUseId, out var startMs))
{
var elapsed = timings.Total.ElapsedMilliseconds - startMs;
Log(session, LogLevel.Dbg,
$"tool {vm.Kind} done after {elapsed}ms ({(tr.IsError ? "fail" : "ok")})");
}
}
}
// Persist the tool-result updates against whatever messages own them.
Expand Down Expand Up @@ -364,7 +405,8 @@ private void AppendAssistantMessage(
Dictionary<string, ToolCallVm> toolsById,
Dictionary<string, TranscriptMessageVm> messageByToolId,
Dictionary<string, LiveAssistantState> liveByMessageId,
PermissionTurnHandler? permHandler)
PermissionTurnHandler? permHandler,
TurnTimings timings)
{
var buf = new StringBuilder();

Expand Down Expand Up @@ -400,6 +442,12 @@ private void AppendAssistantMessage(
break;
case ToolUseContent tu:
hasToolUse = true;
if (!timings.LoggedFirstTool)
{
timings.LoggedFirstTool = true;
Log(session, LogLevel.Inf,
$"First tool call after {timings.Total.ElapsedMilliseconds}ms");
}
Comment on lines 444 to +450
Copy link
Copy Markdown

@greptile-apps greptile-apps Bot May 5, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 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.

// TodoWrite is mirrored into the right-hand plan panel — rendering a
// pill in the transcript too is just noise, so update the plan and skip.
if (tu.Name == "TodoWrite")
Expand All @@ -419,6 +467,8 @@ private void AppendAssistantMessage(
ToolUseId = tu.Id,
PermissionHandler = permHandler,
};
timings.ToolStartMs[tu.Id] = timings.Total.ElapsedMilliseconds;
Log(session, LogLevel.Dbg, $"tool {vm.Kind} {vm.Target} starting");
message.Tools.Add(vm);
toolsById[tu.Id] = vm;
messageByToolId[tu.Id] = message;
Expand Down
Loading