Record per-step duration in trace and operational logs #35

New issue

Closed

opened 2026-04-08 22:47:07 +00:00 by claude-code · 0 comments

claude-code commented

2026-04-08 22:47:07 +00:00

Collaborator

Problem

Trace and operational logs record an ISO timestamp per step but not how long each step took. Operators have to compute durations by subtracting consecutive timestamps in the JSONL trace, which is awkward and impossible from a single log line.

Goal

First-class duration_ms on each *_complete trace step, plus a total_duration_sec on the terminal complete step. Mirrors automatically into operational logs because they're emitted from the same TraceLogger.log_step call.

Pairings

Starter	Completer	Duration field on
`web_search`	`web_search_complete`	completer
`fetch_url`	`fetch_url_complete`	completer
`synthesis_start`	`synthesis_complete` / `synthesis_error`	completer
`start`	`complete`	completer (`total_duration_sec`)

Iteration durations are derivable from consecutive iteration_start timestamps; not addressed here.

Implementation

TraceLogger tracks a small dict of starter action → start time (monotonic)
On a starter action, record the start time keyed by action name
On a completer action, look up the matching starter, compute duration, attach as a field on the completer entry, and clear it
Starters and completers are tightly paired in the agent code (_execute_tool runs start→end before returning), so a simple dict works without queueing

Tests

Each pairing produces a duration_ms (or total_duration_sec) on the completer
Unpaired completer doesn't crash, just records no duration
Existing trace fields are unchanged

## Problem Trace and operational logs record an ISO `timestamp` per step but not how long each step took. Operators have to compute durations by subtracting consecutive timestamps in the JSONL trace, which is awkward and impossible from a single log line. ## Goal First-class `duration_ms` on each `*_complete` trace step, plus a `total_duration_sec` on the terminal `complete` step. Mirrors automatically into operational logs because they're emitted from the same `TraceLogger.log_step` call. ## Pairings | Starter | Completer | Duration field on | |---|---|---| | `web_search` | `web_search_complete` | completer | | `fetch_url` | `fetch_url_complete` | completer | | `synthesis_start` | `synthesis_complete` / `synthesis_error` | completer | | `start` | `complete` | completer (`total_duration_sec`) | Iteration durations are derivable from consecutive `iteration_start` timestamps; not addressed here. ## Implementation - `TraceLogger` tracks a small dict of starter action → start time (monotonic) - On a starter action, record the start time keyed by action name - On a completer action, look up the matching starter, compute duration, attach as a field on the completer entry, and clear it - Starters and completers are tightly paired in the agent code (`_execute_tool` runs start→end before returning), so a simple dict works without queueing ## Tests - Each pairing produces a `duration_ms` (or `total_duration_sec`) on the completer - Unpaired completer doesn't crash, just records no duration - Existing trace fields are unchanged