Record per-step durations in trace and operational logs #36

Merged

archeious merged 1 commit from feat/step-durations into main

2026-04-08 22:58:12 +00:00

claude-code commented

2026-04-08 22:50:32 +00:00

Collaborator

Closes Issue #35

Change

TraceLogger now tracks monotonic start times for starter actions and attaches a duration_ms field to the matching completer:

Starter	Completer	Field
`web_search`	`web_search_complete`	`duration_ms`
`fetch_url`	`fetch_url_complete`	`duration_ms`
`synthesis_start`	`synthesis_complete` / `synthesis_error`	`duration_ms`
`start`	`complete`	`total_duration_sec`

Pairings are tightly sequential in the agent code (each _execute_tool call runs start→end before returning), so a simple dict keyed by starter name suffices — no queueing needed. An unpaired completer leaves the duration unset and does not crash.

Durations flow into both the JSONL trace and the structlog operational log, so OpenSearch queries can filter / aggregate by step latency without cross-row joins.

Verified end-to-end

Real shallow query:

{"step":4, "action":"web_search_complete",   "duration_ms":5233}
{"step":6, "action":"web_search_complete",   "duration_ms":3006}
{"step":10,"action":"synthesis_complete",    "duration_ms":27658}
{"step":11,"action":"complete",              "total_duration_sec":47.547}

Synthesis is by far the slowest step — visible at a glance for the first time. Useful insight for future optimization.

Tests

7 new tests in test_trace.py: each pairing's duration field, error-path duration, total seconds, unpaired completer no-crash, existing fields preserved. 123/123 passing.

Closes Issue #35 ## Change `TraceLogger` now tracks monotonic start times for starter actions and attaches a `duration_ms` field to the matching completer: | Starter | Completer | Field | |---|---|---| | `web_search` | `web_search_complete` | `duration_ms` | | `fetch_url` | `fetch_url_complete` | `duration_ms` | | `synthesis_start` | `synthesis_complete` / `synthesis_error` | `duration_ms` | | `start` | `complete` | `total_duration_sec` | Pairings are tightly sequential in the agent code (each `_execute_tool` call runs start→end before returning), so a simple dict keyed by starter name suffices — no queueing needed. An unpaired completer leaves the duration unset and does not crash. Durations flow into **both** the JSONL trace and the structlog operational log, so OpenSearch queries can filter / aggregate by step latency without cross-row joins. ## Verified end-to-end Real shallow query: ```json {"step":4, "action":"web_search_complete", "duration_ms":5233} {"step":6, "action":"web_search_complete", "duration_ms":3006} {"step":10,"action":"synthesis_complete", "duration_ms":27658} {"step":11,"action":"complete", "total_duration_sec":47.547} ``` **Synthesis is by far the slowest step** — visible at a glance for the first time. Useful insight for future optimization. ## Tests 7 new tests in `test_trace.py`: each pairing's duration field, error-path duration, total seconds, unpaired completer no-crash, existing fields preserved. **123/123 passing.**

claude-code added 1 commit 2026-04-08 22:50:33 +00:00

Record per-step durations in trace and operational logs (#35 ) ddaf7e85c3

TraceLogger now tracks monotonic start times for starter actions
(web_search, fetch_url, synthesis_start, start) and attaches a
duration_ms field to the matching completer (web_search_complete,
fetch_url_complete, synthesis_complete, synthesis_error). The
terminal 'complete' step gets total_duration_sec instead.

Pairings are tightly sequential in the agent code (each
_execute_tool call runs start→end before returning), so a simple
dict keyed by starter name suffices — no queueing needed. An
unpaired completer leaves duration unset and does not crash.

Durations flow into both the JSONL trace and the structlog
operational log, so OpenSearch queries can filter / aggregate
by step latency without cross-row joins.

Verified end-to-end on a real shallow query:
  web_search       5,233 ms
  web_search       3,006 ms
  synthesis_complete 27,658 ms
  complete         47.547 s total

Synthesis is by far the slowest step — visible at a glance
for the first time.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>