Per-tool-call/reasoning-step latency breakdown (detail.latency_breakdown) - #1758
Open
Tomkess wants to merge 11 commits into
Open
Per-tool-call/reasoning-step latency breakdown (detail.latency_breakdown)#1758Tomkess wants to merge 11 commits into
Tomkess wants to merge 11 commits into
Conversation
Per-tool-call wall time (call receipt to result receipt) was invisible -- avg_latency_s is one number for the whole turn, and the reasoning sidecar has section titles but no timing. Stamps call_ts/result_ts on each ToolCallEvent as it streams in and adds build_latency_breakdown() to sum wall time by tool name, so a slow turn (e.g. 117s alert creation) can be attributed to the specific tool call(s) that dominated it. Experimental -- not wired into every agentic evaluator yet, just the plumbing plus visualization (next commit).
…tic) Wires build_latency_breakdown into both the single-shot VisualizationEvaluator and the agentic path's RunResult/AgenticEvalOutcome, so detail.latency_breakdown shows up in eval results for visualization/vis_agentic without any change to the eval harness's runner or result serialization -- detail already flows through verbatim.
The prior version only summed tool-call wall time, leaving most of a slow turn unexplained (e.g. 47s of tool time out of 119s total avg_latency_s). Timestamps each reasoning step as it streams in (ReasoningStepEvent) and merges it into the same timeline as tool calls in build_latency_breakdown: the gap between any two consecutive points -- a tool call starting, a tool call's result landing, or a reasoning step being emitted -- is charged to whichever was "active" during it. This accounts for effectively the whole turn instead of just its tool-call portion. Also fixes multi-turn accumulation in agentic/visualization.py: each turn's timestamps restart near 0, so RunResult now shifts them by a running turn_offset (each turn's own turn_wall_clock_sec) before concatenating -- without it, turn 2's points would overlap turn 1's in the merged timeline.
Reasoning summaries are a full paragraph ("**Title**\n\nlots of detail...");
using the whole thing as a dict key made latency_breakdown unreadable.
Extracts just the bolded title (same convention gdc-mic-ai-evaluation's own
generate_dashboard_summary.py already uses for these reasoning blocks),
falling back to a truncated snippet when a step has no title.
latency_breakdown reasoning labels were fuzzy-matchable to the .reasoning.json sidecar only by title text -- not reliable, since titles can repeat (two distinct steps both titled "Considering data analysis"). Each reasoning step now carries its own 0-based index (same position it occupies in ChatResult.reasoning_steps and the sidecar's ordered list), embedded directly in the latency_breakdown label, e.g. "reasoning:3:Evaluating YoY metrics" -> sidecar block 3. No sidecar format change needed -- the index was always implicit in list position, just not visible from the latency_breakdown side. Also fixes a real single-shot-path bug this surfaced: core/runner.py's _run_one_item took reasoning_steps from whichever run executed LAST, but best_detail (and any latency_breakdown inside it) from whichever run ranked BEST -- for K>1 these can be different runs entirely, so the sidecar and detail.latency_breakdown could each describe a different attempt with no way to tell. Now both come from the same best-ranked run's chat_result. The agentic path (core/agentic/visualization.py) already did this correctly via its own `best` RunResult, so only the single-shot runner needed the fix.
…t-by-name
A dict keyed by "tool:name"/"reasoning:index:title" aggregated repeat calls
of the same tool together and had no way to say what ran before what --
the actual pipeline order was lost. Returns a list of steps instead, each
{"seq", "kind", "name", "index", "duration_s"}: "seq" is the step's real
execution-order position across tools and reasoning combined, "index" is
its position within its own kind's source list (ToolCallEvent.index or
ReasoningStepEvent.index) for looking up the full record -- arguments/result
for a tool call, or the full paragraph in the .reasoning.json sidecar for a
reasoning step. The same tool called twice now produces two separate
entries in their real order, not one summed total.
Also adds ToolCallEvent.index (optional, mirroring the existing
call_ts/result_ts pattern) and re-numbers both tool and reasoning indices
across turns in the agentic visualization path, alongside the existing
turn_offset shift for timestamps.
…cribes avg_latency_s is a mean across all K runs. detail.latency_breakdown (and reasoning_steps/the sidecar) only ever describe the single best-ranked run. For K=1 these coincide, but for K>1 avg_latency_s is not a valid number to check latency_breakdown's coverage against -- it can describe a run whose own latency differs substantially from the mean of all K attempts, with no way to tell by how much. best_run_latency_s is that specific run's own latency, threaded through core/runner.py (same best_chat_result tracking as the earlier reasoning-steps fix) and into the JSON report next to avg_latency_s.
…ators Extends the visualization-only latency_breakdown work to every enabled test_kind: agentic_alert_skill, agentic_metric_skill, agentic_guardrail, agentic_conversation (all multi-turn -- same tool/reasoning index-offset shift across turns as visualization.py), plus the single-shot general_question, guardrail, and search_tool evaluators (single chat_result, no turn accumulation needed). conversation.py is nested two loops deep (logical turns x clarification sub-turns) -- added a conversation-wide tool_call_events/reasoning_step_events accumulator alongside the existing reasoning_steps one, offset-shifted per physical send_message() call regardless of which loop it's in. Test fixtures in test_agentic_conversation.py used bare MagicMock() chat results without call_ts/result_ts/index/reasoning_step_events/ turn_wall_clock_sec set (predating this capture) -- updated them to set these to their real no-op defaults, matching what an actual un-instrumented ChatResult already provides.
…ert)" This reverts commit 1bc4a38.
|
Warning Review limit reachedNext included review available in 41 minutes. View limit detailsLimit details: You’ve used the included review currently available. You've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository. Review configuration: ⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Plus Run ID: 📒 Files selected for processing (20)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## master #1758 +/- ##
==========================================
+ Coverage 80.59% 80.61% +0.02%
==========================================
Files 272 272
Lines 19223 19362 +139
==========================================
+ Hits 15492 15609 +117
- Misses 3731 3753 +22 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
Pure whitespace/line-wrap, no functional change -- I'd only run `ruff check` locally, not `ruff format --check`, which is CI's actual lint-and-format-check job.
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
1 participant
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
Motivating question from a colleague reviewing eval latency reports: "we report 117s for alert creation, can we break that down by task?" Neither
avg_latency_s(one number for the whole turn) nor the.reasoning.jsonsidecar (prose, no timing) could answer that.ToolCallEvent.call_ts/result_ts/index,ReasoningStepEvent.ts/index— client-observed receipt time, not a server measurement).build_latency_breakdown()merges tool calls and reasoning steps into one chronological timeline and returns an ordered sequence of steps (seq,kind,name,index,duration_s) — not a dict aggregated by name, so a tool called twice or two reasoning steps sharing a title stay distinguishable and in real execution order.indexis the step's position in its own source list (same position as inChatResult.reasoning_stepsand, downstream, the.reasoning.jsonsidecar's ordered list) — lets a human or script look up the full record (tool args/result, or the full reasoning paragraph) without a separate merge tool.**Title**\n\n...→Title), not the full paragraph — otherwise every entry is an unreadable wall of text.best_run_latency_s: for K>1,avg_latency_sis a cross-run mean whiledetail.latency_breakdownonly ever describes the single best-ranked run — comparing the breakdown's sum against the mean is not a valid "% explained" check. This is the run's own latency, computed alongside the same best-run tracking already needed for the fix below.core/runner.py's single-shot path tookreasoning_stepsfrom whichever run executed last, butbest_detailfrom whichever run ranked best — for K>1 these could be different runs, so the sidecar anddetail.latency_breakdowncould each describe a different attempt with no way to tell. Both now come from the same run.gdc-mic-ai-evaluation'sdata/test_kinds.yaml):visualization,vis_agentic,agentic_alert_skill,agentic_metric_skill,agentic_guardrail,agentic_conversation,general_question,guardrail,search_tool. The 4 multi-turn agentic kinds re-offset both timestamps and indices across turns (each turn's own SSE stream restarts near 0).Live verification (not just unit tests)
Ran real eval questions through
gdc-mic-ai-evaluationend-to-end at each step of this branch, with actual result-file writing:visualization/K=1: coverage went from 40% (tool-only) → 92-97% (tool+reasoning) ofavg_latency_sexplained, once reasoning attribution landed.visualization/K=3 real run: confirmedavg_latency_s(129.30) ≠best_run_latency_s(118.22) — the bug the last commit fixes, observed live, not just asserted in a test.search_tool/K=3: confirmed the new fields populate correctly for a newly-wired single-shot kind.search_objects/create_adhoc_visualizationcalls sharing identicalcall_ts) twice live — both resolved 100% of calls viacallId, zero collisions, confirming the SSEcallId-matching logic handles concurrency correctly.Test plan
uv run pytest packages/gooddata-eval/tests/— 454-465 passed across each commit (count varies as tests were added), same 9 pre-existing failures asmaster(missingopenaiextra + one unrelated registry test) throughout, zero new failures at any point.ruff check— clean at every commit.Note: commits
1bc4a38e/13ed3c8bare a temporary debug-logging commit and its revert (used to directly verify thecallId-matching live-verification claim above) — net zero diff, kept for transparency on how that claim was checked rather than squashed away.🤖 Generated with Claude Code