fix(claude_code): measure per-tool latency, which was always reported as 0 - #601
Open
omkargaikwad23 wants to merge 4 commits into
Open
fix(claude_code): measure per-tool latency, which was always reported as 0#601omkargaikwad23 wants to merge 4 commits into
omkargaikwad23 wants to merge 4 commits into
Conversation
… as 0 Claude Code's stream-json carries no timestamps on tool_use or tool_result events and no duration field, and the CLI was run to completion before its output was parsed. tools.durationMs and tools.totalDurationMs were therefore initialized to 0 and never accumulated, so tool_call_latency scored 0 for every scenario. Stream stdout line-by-line and stamp the arrival time of each tool_use block and its matching tool_result, then accumulate the gap into the tool stats. This mirrors what codex_cli already does; gemini_cli gets duration_ms from the CLI itself.
omkargaikwad23
requested review from
IsmailMehdi,
helloeve and
prernakakkar-google
as code owners
September 11, 2026 13:27
…onse _stamp_tool_event assumed every parsed JSON line was an object, so a line decoding to a list raised AttributeError. That propagated into the stdout drain loop and broke out of it, discarding every remaining line -- losing the agent's response to salvage a timing number. Guard the parse and isolate the stamping so timing can never cost us stdout. Also flatten the tool_result id handling and cover the top-level tool_result shape, parallel calls, and malformed lines.
The 'stream-json carries no timestamps' rationale was stated in three places. Keep it once, on the method whose existence it justifies, and cut the prose that restated what the code already shows.
test_parse_stream_json_without_durations fed a stream with no tool calls, so the accumulation loop never ran and it only asserted totalDurationMs was still 0 -- which passes just as well against the bug it was meant to guard.
Collaborator
|
/gcbrun |
Collaborator
|
WHy verify-harness is showing up |
Collaborator
|
Parallel tool calls double-count into totalDurationMs |
4 tasks
Collaborator
Author
I have added the PR trigger in gcp project. We will be releasing that feature soon. |
Collaborator
Author
Good catch. Parallel calls do sum rather than merge. That's the existing convention in all four generators, and toolcalllatency.py:70 sums across turns on top of that, so the metric is cumulative tool work rather than elapsed time. Changing it here alone would make Claude the only harness reporting a different quantity. Happy to follow up with a change across all four if we want wall-clock semantics. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Issue found during harness CI check work: logs
tool_call_latencyscored 0 for every Claude Code scenario.tools.durationMsandtotalDurationMswere initialized to 0 in_parse_stream_jsonand never accumulated — and there was nothing to accumulate from: Claude's stream-json carries no timestamps, and the CLI ran to completion before parsing, so nothing measured the gap.Fix: stream stdout line-by-line, stamp
time.monotonic()when atool_usearrives and again at its matchingtool_result, then accumulate into the tool stats.Also guards the parser against a malformed line:
_stamp_tool_eventassumed every decoded line was an object, so a line parsing to a list raisedAttributeError, broke out of the stdout drain loop, and discarded the rest of the agent's response.Notes for reviewers
_execute_cli_streamingmirrorscodex_cli._execute_cli_commandverbatim. Hoisting both intoAgentCliGeneratoris the right end state, left as a follow-up to keep this bugfix reviewable.codex_clialso has the sameAttributeErrorhole._execute_cli_commandis unchanged — its two setup callers still expect a bareCompletedProcess.totalDurationMssums tool time rather than wall-clock. That matches the other generators and how the scorer already aggregates.Test plan
pytest evalbench/test/claude_code_test.py— 7 passed, up from 5tool_resultshapes, parallel calls, and malformed linestool_call_latency > 0forclaude_codein the next harness CI run