From bc41a6bf609f7c9e9507c50a5ca7ba988efd39cf Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 12:24:27 +0200 Subject: [PATCH 01/11] Timestamp SSE tool-call events and add build_latency_breakdown 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). --- .../src/gooddata_eval/core/chat/sse_client.py | 7 +++ .../src/gooddata_eval/core/models.py | 20 +++++++ .../gooddata-eval/tests/test_sse_client.py | 58 +++++++++++++++++-- 3 files changed, 81 insertions(+), 4 deletions(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py index 3faba5bbd..13eb1a5aa 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py @@ -132,6 +132,11 @@ class _SseAccumulator: adhoc_viz_args: list[dict[str, Any]] = field(default_factory=list) response_id: str | None = None stream_ended: bool = False + # Reference point for call_ts/result_ts below -- client-observed receipt time, not a + # server timestamp, so only meaningful as an offset within this one turn. Wrapped in a + # lambda, not passed as `time.monotonic` directly -- a bare function reference binds at + # class-body execution (import time), before tests can monkeypatch `sse_mod.time.monotonic`. + t0: float = field(default_factory=lambda: time.monotonic()) def _handle_text(content: dict[str, Any], acc: _SseAccumulator) -> None: @@ -171,6 +176,7 @@ def _handle_tool_call(content: dict[str, Any], acc: _SseAccumulator) -> None: "functionName": content.get("name", ""), "functionArguments": json.dumps(content.get("arguments", {})), "result": None, + "call_ts": round(time.monotonic() - acc.t0, 3), } ) # Stash visualization definition from create_adhoc_visualization so we can @@ -186,6 +192,7 @@ def _handle_tool_result(content: dict[str, Any], acc: _SseAccumulator) -> None: idx = acc.call_id_to_event_index.get(call_id) if idx is not None: acc.tool_call_events[idx]["result"] = content.get("result", "") + acc.tool_call_events[idx]["result_ts"] = round(time.monotonic() - acc.t0, 3) def _build_chat_result(acc: _SseAccumulator) -> ChatResult: diff --git a/packages/gooddata-eval/src/gooddata_eval/core/models.py b/packages/gooddata-eval/src/gooddata_eval/core/models.py index a536019f2..68ef3b518 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/models.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/models.py @@ -69,6 +69,11 @@ class ToolCallEvent(BaseModel): function_name: str = Field(alias="functionName") function_arguments: str = Field(alias="functionArguments") result: str | None = None + # Client-observed receipt time (seconds since the turn's first SSE line), not a + # server-side execution measurement -- set by sse_client.py as the tool-call and + # tool-result events stream in. None when the call never got a result (stalled turn). + call_ts: float | None = None + result_ts: float | None = None def parsed_arguments(self) -> dict[str, Any]: try: @@ -85,6 +90,21 @@ def parsed_result(self) -> dict[str, Any] | None: return None +def build_latency_breakdown(tool_call_events: list[ToolCallEvent]) -> dict[str, float]: + """Wall time per tool name, summed across calls, from call receipt to result receipt. + + Calls missing either timestamp (stalled, or from a chat backend that predates this + capture) are skipped rather than counted as zero -- an absent entry means "unknown", + not "instant". + """ + by_tool: dict[str, float] = {} + for tc in tool_call_events: + if tc.call_ts is None or tc.result_ts is None: + continue + by_tool[tc.function_name] = by_tool.get(tc.function_name, 0.0) + (tc.result_ts - tc.call_ts) + return {name: round(secs, 2) for name, secs in by_tool.items()} + + class ChatResult(BaseModel): """Subset of the agent chat response needed for Phase 1 evaluation.""" diff --git a/packages/gooddata-eval/tests/test_sse_client.py b/packages/gooddata-eval/tests/test_sse_client.py index be44b304d..72676df87 100644 --- a/packages/gooddata-eval/tests/test_sse_client.py +++ b/packages/gooddata-eval/tests/test_sse_client.py @@ -5,7 +5,7 @@ import pytest from gooddata_eval.core.chat import sse_client as sse_mod from gooddata_eval.core.chat.sse_client import ChatClient, ChatError, TransientChatError, parse_sse_lines -from gooddata_eval.core.models import DatasetItem +from gooddata_eval.core.models import DatasetItem, ToolCallEvent, build_latency_breakdown def test_parse_sse_lines_collects_text_and_visualization(fixtures_dir): @@ -63,6 +63,53 @@ def test_parse_sse_lines_error_carries_partial_result_with_tool_calls_already_se assert partial.tool_call_events[0].result == '{"success": true}' +def test_parse_sse_lines_stamps_call_and_result_receipt_time(monkeypatch): + # t0 (accumulator construction) = 100.0, tool_call received at 105.0, tool_result + # received at 130.5 -- call_ts/result_ts are offsets from t0, so 5.0 and 30.5. + monkeypatch.setattr(sse_mod.time, "monotonic", iter([100.0, 105.0, 130.5]).__next__) + lines = [ + json.dumps( + { + "item": { + "role": "assistant", + "content": {"type": "toolCall", "callId": "c1", "name": "create_key_driver_analysis"}, + } + } + ), + "", + json.dumps( + { + "item": { + "role": "tool", + "content": {"type": "toolResult", "callId": "c1", "result": json.dumps({"success": True})}, + } + } + ), + ] + lines = [f"data: {line}" if line else line for line in lines] + result = parse_sse_lines(lines) + tc = result.tool_call_events[0] + assert tc.call_ts == 5.0 + assert tc.result_ts == 30.5 + + +def test_build_latency_breakdown_sums_by_tool_name(): + events = [ + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=3.0, result_ts=4.0), + ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=4.0, result_ts=64.2), + ] + assert build_latency_breakdown(events) == {"search_tool": 3.5, "create_metric_alert": 60.2} + + +def test_build_latency_breakdown_skips_calls_missing_a_timestamp(): + events = [ + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=None), + ToolCallEvent(function_name="create_metric_alert", function_arguments="{}"), + ] + assert build_latency_breakdown(events) == {} + + def test_parse_sse_lines_raw_transport_error_also_carries_partial_result(): # A connection drop mid-stream (httpx.RemoteProtocolError/ReadError) has no statusCode # payload -- it's a raw exception from iterating `lines` itself, not one this module @@ -351,7 +398,8 @@ def handler(request): def test_send_message_sets_turn_wall_clock_sec_on_success(monkeypatch): - monkeypatch.setattr(sse_mod.time, "monotonic", iter([100.0, 102.5]).__next__) + # 3 monotonic() calls per attempt now: t0, _SseAccumulator's own t0, final wall-clock. + monkeypatch.setattr(sse_mod.time, "monotonic", iter([100.0, 100.0, 102.5]).__next__) client = _client_with_handler(lambda request: httpx.Response(200, content=_OK_SSE)) result = client.send_message("conv", "q") assert result.turn_wall_clock_sec == pytest.approx(2.5) @@ -363,7 +411,8 @@ def test_send_message_wall_clock_excludes_retry_backoff(monkeypatch): # between attempts (harness/network overhead, not gen-ai's time) would inflate the # reported latency. monkeypatch.setattr(sse_mod.time, "sleep", lambda s: None) - monkeypatch.setattr(sse_mod.time, "monotonic", iter([1000.0, 1000.5, 2000.0, 2001.2]).__next__) + # 3 monotonic() calls per attempt now: t0, _SseAccumulator's own t0, final wall-clock. + monkeypatch.setattr(sse_mod.time, "monotonic", iter([1000.0, 1000.0, 1000.5, 2000.0, 2000.0, 2001.2]).__next__) calls = {"n": 0} def handler(request): @@ -377,7 +426,8 @@ def handler(request): def test_send_message_stamps_turn_wall_clock_sec_on_partial_result_too(monkeypatch): - monkeypatch.setattr(sse_mod.time, "monotonic", iter([50.0, 51.0]).__next__) + # 3 monotonic() calls now: t0, _SseAccumulator's own t0, partial-result wall-clock. + monkeypatch.setattr(sse_mod.time, "monotonic", iter([50.0, 50.0, 51.0]).__next__) client = _client_with_handler(lambda request: httpx.Response(200, content=_NONRETRY_SSE)) with pytest.raises(ChatError) as ei: client.send_message("conv", "q") From b7878575d7bf553ff5a5e22b658f5b933387f7c3 Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 12:24:32 +0200 Subject: [PATCH 02/11] Surface latency_breakdown in visualization detail (single-shot + agentic) 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. --- .../gooddata_eval/core/agentic/visualization.py | 14 +++++++++++--- .../gooddata_eval/core/evaluators/visualization.py | 13 +++++++++++-- .../tests/test_agentic_visualization.py | 2 ++ 3 files changed, 24 insertions(+), 5 deletions(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py index 3edd22a1a..9d1f06c8f 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py @@ -18,7 +18,7 @@ _evaluate_against_candidates, evaluation_result_detail, ) -from gooddata_eval.core.models import AgenticEvalOutcome, CreatedVisualization, ToolCallEvent +from gooddata_eval.core.models import AgenticEvalOutcome, CreatedVisualization, ToolCallEvent, build_latency_breakdown from gooddata_eval.core.scoring import get_dimension_uri_set, get_metric_uri_set, uri_to_display_name _DEFAULT_K = 2 @@ -37,6 +37,7 @@ class RunResult: total_steps: float reasoning_steps: list[str] = field(default_factory=list) response_id: str | None = None + tool_call_events: list[ToolCallEvent] = field(default_factory=list) @dataclass @@ -201,6 +202,7 @@ def _execute_single_run( total_steps=total_steps, reasoning_steps=reasoning_steps, response_id=response_id, + tool_call_events=all_tool_call_events, ) @@ -434,12 +436,18 @@ def evaluate_agentic_visualization( exc.reasoning_steps = best.reasoning_steps exc.conversation_id = best.conversation_id exc.response_id = best.response_id - exc.detail = evaluation_result_detail(ev) + exc.detail = { + **evaluation_result_detail(ev), + "latency_breakdown": build_latency_breakdown(best.tool_call_events), + } raise exc best = summary.best return AgenticEvalOutcome( reasoning_steps=best.reasoning_steps, conversation_id=best.conversation_id, response_id=best.response_id, - detail=evaluation_result_detail(best.eval_result), + detail={ + **evaluation_result_detail(best.eval_result), + "latency_breakdown": build_latency_breakdown(best.tool_call_events), + }, ) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py index 354b8a214..a4dba6d67 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py @@ -4,7 +4,13 @@ from dataclasses import dataclass from gooddata_eval.core.evaluators.base import ItemEvaluation -from gooddata_eval.core.models import ChatResult, CreatedVisualization, DatasetItem, ToolCallEvent +from gooddata_eval.core.models import ( + ChatResult, + CreatedVisualization, + DatasetItem, + ToolCallEvent, + build_latency_breakdown, +) from gooddata_eval.core.scoring import ( check_filters, check_viz_type, @@ -197,5 +203,8 @@ def evaluate(self, item: DatasetItem, chat_result: ChatResult) -> ItemEvaluation return ItemEvaluation( passed=ev.strict_pass, rank_key=(ev.strict_pass, ev.strict_checks_passed_count), - detail=evaluation_result_detail(ev), + detail={ + **evaluation_result_detail(ev), + "latency_breakdown": build_latency_breakdown(chat_result.tool_call_events), + }, ) diff --git a/packages/gooddata-eval/tests/test_agentic_visualization.py b/packages/gooddata-eval/tests/test_agentic_visualization.py index 80a558202..a9bb3c8ce 100644 --- a/packages/gooddata-eval/tests/test_agentic_visualization.py +++ b/packages/gooddata-eval/tests/test_agentic_visualization.py @@ -320,6 +320,7 @@ def test_evaluate_agentic_visualization_returns_reasoning_steps_on_pass(): "actual_dim_uris": ["label/date.quarter"], "expected_filters": {"date": [], "ranking": [], "attribute": []}, "actual_filters": {"date": [], "ranking": [], "attribute": []}, + "latency_breakdown": {}, } @@ -370,4 +371,5 @@ def test_evaluate_agentic_visualization_attaches_reasoning_steps_to_exception_on "actual_dim_uris": [], "expected_filters": {"date": [], "ranking": [], "attribute": []}, "actual_filters": {"date": [], "ranking": [], "attribute": []}, + "latency_breakdown": {}, } From cbe4368473e540ad17df8617802a78da96ded8a2 Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 13:16:48 +0200 Subject: [PATCH 03/11] Attribute latency_breakdown gaps to reasoning steps, not just tool calls 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. --- .../core/agentic/visualization.py | 25 ++++++++- .../src/gooddata_eval/core/chat/sse_client.py | 3 +- .../core/evaluators/visualization.py | 4 +- .../src/gooddata_eval/core/models.py | 56 +++++++++++++++++-- .../gooddata-eval/tests/test_sse_client.py | 54 ++++++++++++++++-- 5 files changed, 128 insertions(+), 14 deletions(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py index 9d1f06c8f..3a8e072ac 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py @@ -18,7 +18,13 @@ _evaluate_against_candidates, evaluation_result_detail, ) -from gooddata_eval.core.models import AgenticEvalOutcome, CreatedVisualization, ToolCallEvent, build_latency_breakdown +from gooddata_eval.core.models import ( + AgenticEvalOutcome, + CreatedVisualization, + ReasoningStepEvent, + ToolCallEvent, + build_latency_breakdown, +) from gooddata_eval.core.scoring import get_dimension_uri_set, get_metric_uri_set, uri_to_display_name _DEFAULT_K = 2 @@ -38,6 +44,7 @@ class RunResult: reasoning_steps: list[str] = field(default_factory=list) response_id: str | None = None tool_call_events: list[ToolCallEvent] = field(default_factory=list) + reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list) @dataclass @@ -162,8 +169,10 @@ def _execute_single_run( total_turns = 0.0 total_steps = 0.0 all_tool_call_events: list[ToolCallEvent] = [] + all_reasoning_step_events: list[ReasoningStepEvent] = [] reasoning_steps: list[str] = [] response_id: str | None = None + turn_offset = 0.0 # each turn's call_ts/ts restarts near 0 -- shift by prior turns' wall time simulated_response_guide = expected_outputs[0] # primary candidate guides the simulated user current_result = client.send_message(conversation_id, question) @@ -171,9 +180,18 @@ def _execute_single_run( for iteration in range(max_iterations): total_turns += 1.0 total_steps += float(current_result.reasoning_step_count) + for tc in current_result.tool_call_events: + if tc.call_ts is not None: + tc.call_ts += turn_offset + if tc.result_ts is not None: + tc.result_ts += turn_offset + for rs in current_result.reasoning_step_events: + rs.ts += turn_offset all_tool_call_events.extend(current_result.tool_call_events) + all_reasoning_step_events.extend(current_result.reasoning_step_events) reasoning_steps.extend(current_result.reasoning_steps or []) response_id = current_result.response_id or response_id + turn_offset += current_result.turn_wall_clock_sec or 0.0 viz_produced = bool(current_result.created_visualizations and current_result.created_visualizations.objects) if viz_produced: @@ -203,6 +221,7 @@ def _execute_single_run( reasoning_steps=reasoning_steps, response_id=response_id, tool_call_events=all_tool_call_events, + reasoning_step_events=all_reasoning_step_events, ) @@ -438,7 +457,7 @@ def evaluate_agentic_visualization( exc.response_id = best.response_id exc.detail = { **evaluation_result_detail(ev), - "latency_breakdown": build_latency_breakdown(best.tool_call_events), + "latency_breakdown": build_latency_breakdown(best.tool_call_events, best.reasoning_step_events), } raise exc best = summary.best @@ -448,6 +467,6 @@ def evaluate_agentic_visualization( response_id=best.response_id, detail={ **evaluation_result_detail(best.eval_result), - "latency_breakdown": build_latency_breakdown(best.tool_call_events), + "latency_breakdown": build_latency_breakdown(best.tool_call_events, best.reasoning_step_events), }, ) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py index 13eb1a5aa..204b758d9 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py @@ -165,7 +165,7 @@ def _handle_multipart(content: dict[str, Any], acc: _SseAccumulator) -> None: def _handle_reasoning(content: dict[str, Any], acc: _SseAccumulator) -> None: summary = content.get("summary", "") if summary: - acc.reasoning_steps.append({"summary": summary}) + acc.reasoning_steps.append({"summary": summary, "ts": round(time.monotonic() - acc.t0, 3)}) def _handle_tool_call(content: dict[str, Any], acc: _SseAccumulator) -> None: @@ -202,6 +202,7 @@ def _build_chat_result(acc: _SseAccumulator) -> ChatResult: "toolCallEvents": acc.tool_call_events, "reasoningStepCount": len(acc.reasoning_steps), "reasoningSteps": [step["summary"] for step in acc.reasoning_steps], + "reasoningStepEvents": acc.reasoning_steps, } if acc.visualizations: payload["createdVisualizations"] = { diff --git a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py index a4dba6d67..a6e197d34 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py @@ -205,6 +205,8 @@ def evaluate(self, item: DatasetItem, chat_result: ChatResult) -> ItemEvaluation rank_key=(ev.strict_pass, ev.strict_checks_passed_count), detail={ **evaluation_result_detail(ev), - "latency_breakdown": build_latency_breakdown(chat_result.tool_call_events), + "latency_breakdown": build_latency_breakdown( + chat_result.tool_call_events, chat_result.reasoning_step_events + ), }, ) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/models.py b/packages/gooddata-eval/src/gooddata_eval/core/models.py index 68ef3b518..1b3710d2d 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/models.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/models.py @@ -90,19 +90,64 @@ def parsed_result(self) -> dict[str, Any] | None: return None -def build_latency_breakdown(tool_call_events: list[ToolCallEvent]) -> dict[str, float]: - """Wall time per tool name, summed across calls, from call receipt to result receipt. +class ReasoningStepEvent(BaseModel): + """One reasoning step with its client-observed receipt time (see ToolCallEvent.call_ts).""" + + summary: str + ts: float + + +def build_latency_breakdown( + tool_call_events: list[ToolCallEvent], + reasoning_step_events: list[ReasoningStepEvent] | None = None, +) -> dict[str, float]: + """Wall time attributed to each tool call and each reasoning step in the turn. + + Without ``reasoning_step_events``, this is just per-tool wall time (call receipt to + result receipt) summed by name -- the gaps between tool calls (the model "thinking") + are left unaccounted for. + + With them, every point in the turn -- a tool call starting, a tool call's result + arriving, or a reasoning step being emitted -- is merged into one timeline and sorted. + The gap between consecutive points is charged to whatever was "active" during it: a + tool call while it's outstanding (call event to result event), or the most recently + emitted reasoning step's own summary otherwise (its gap runs until the next point, + whatever that turns out to be -- another reasoning step, or the next tool call + starting). This accounts for effectively the whole turn, not just its tool-call + portion; only the time before the first point and after the last (connection + setup/teardown) is left out, since this function has no reference to the turn's total + duration. Calls missing either timestamp (stalled, or from a chat backend that predates this capture) are skipped rather than counted as zero -- an absent entry means "unknown", not "instant". """ - by_tool: dict[str, float] = {} + points: list[tuple[float, str, str]] = [] # (ts, kind, label); kind: tool_start/tool_end/reasoning for tc in tool_call_events: if tc.call_ts is None or tc.result_ts is None: continue - by_tool[tc.function_name] = by_tool.get(tc.function_name, 0.0) + (tc.result_ts - tc.call_ts) - return {name: round(secs, 2) for name, secs in by_tool.items()} + points.append((tc.call_ts, "tool_start", tc.function_name)) + points.append((tc.result_ts, "tool_end", tc.function_name)) + points.extend((rs.ts, "reasoning", rs.summary) for rs in reasoning_step_events or []) + points.sort(key=lambda p: p[0]) + + by_label: dict[str, float] = {} + current_reasoning_label = "reasoning:(before first step)" + for (ts, kind, label), (next_ts, _, _) in zip(points, points[1:]): + gap = next_ts - ts + if gap <= 0: + continue + if kind == "tool_start": + key = f"tool:{label}" + else: + # A tool call resolving, or a reasoning step being emitted, both hand control + # back to "whatever the model is doing until the next point" -- which is this + # reasoning step once one has been seen, else the pre-first-step catch-all. + key = f"reasoning:{label}" if kind == "reasoning" else current_reasoning_label + by_label[key] = by_label.get(key, 0.0) + gap + if kind == "reasoning": + current_reasoning_label = f"reasoning:{label}" + return {name: round(secs, 2) for name, secs in by_label.items()} class ChatResult(BaseModel): @@ -119,6 +164,7 @@ class ChatResult(BaseModel): tool_call_events: list[ToolCallEvent] = Field(default_factory=list, alias="toolCallEvents") reasoning_step_count: int = Field(default=0, alias="reasoningStepCount") reasoning_steps: list[str] = Field(default_factory=list, alias="reasoningSteps") + reasoning_step_events: list[ReasoningStepEvent] = Field(default_factory=list, alias="reasoningStepEvents") conversation_id: str | None = Field(default=None, alias="conversationId") response_id: str | None = Field(default=None, alias="responseId") # True once gen-ai's response_ended event arrived. diff --git a/packages/gooddata-eval/tests/test_sse_client.py b/packages/gooddata-eval/tests/test_sse_client.py index 72676df87..acebd6ce2 100644 --- a/packages/gooddata-eval/tests/test_sse_client.py +++ b/packages/gooddata-eval/tests/test_sse_client.py @@ -5,7 +5,7 @@ import pytest from gooddata_eval.core.chat import sse_client as sse_mod from gooddata_eval.core.chat.sse_client import ChatClient, ChatError, TransientChatError, parse_sse_lines -from gooddata_eval.core.models import DatasetItem, ToolCallEvent, build_latency_breakdown +from gooddata_eval.core.models import DatasetItem, ReasoningStepEvent, ToolCallEvent, build_latency_breakdown def test_parse_sse_lines_collects_text_and_visualization(fixtures_dir): @@ -94,12 +94,47 @@ def test_parse_sse_lines_stamps_call_and_result_receipt_time(monkeypatch): def test_build_latency_breakdown_sums_by_tool_name(): + # Adjacent, back-to-back calls (no gap between them) so the only two labels are the + # tools themselves -- the tool_end-to-tool_start gap case is covered separately below. events = [ ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=3.0, result_ts=4.0), - ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=4.0, result_ts=64.2), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=2.5, result_ts=3.5), + ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=3.5, result_ts=63.7), ] - assert build_latency_breakdown(events) == {"search_tool": 3.5, "create_metric_alert": 60.2} + assert build_latency_breakdown(events) == {"tool:search_tool": 3.5, "tool:create_metric_alert": 60.2} + + +def test_build_latency_breakdown_attributes_gaps_to_reasoning_steps(): + # search_tool runs 0-2.5s. Then a gap: the model emits a reasoning step at 2.5s, then + # goes idle until the next tool call starts at 5.0s -- that whole 2.5s idle gap belongs + # to the reasoning step, not to "search_tool" (which already finished) or nothing. + tool_events = [ + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), + ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=65.0), + ] + reasoning_events = [ReasoningStepEvent(summary="Picking the right metric", ts=2.5)] + result = build_latency_breakdown(tool_events, reasoning_events) + assert result == { + "tool:search_tool": 2.5, + "reasoning:Picking the right metric": 2.5, + "tool:create_metric_alert": 60.0, + } + + +def test_build_latency_breakdown_gap_with_no_reasoning_events_gets_a_catch_all_label(): + # A gap between two tool calls with zero reasoning events supplied at all (e.g. an + # older chat backend, or reasoning capture disabled) must not be silently dropped -- + # it needs a label that doesn't fake having a real summary for it. + tool_events = [ + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), + ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=65.0), + ] + result = build_latency_breakdown(tool_events, reasoning_step_events=None) + assert result == { + "tool:search_tool": 2.5, + "reasoning:(before first step)": 2.5, + "tool:create_metric_alert": 60.0, + } def test_build_latency_breakdown_skips_calls_missing_a_timestamp(): @@ -255,6 +290,17 @@ def test_parse_sse_lines_reasoning_steps_empty_when_no_reasoning_events(): assert result.reasoning_steps == [] +def test_parse_sse_lines_stamps_reasoning_step_receipt_time(monkeypatch): + monkeypatch.setattr(sse_mod.time, "monotonic", iter([100.0, 104.5, 110.0]).__next__) + lines = [ + 'data: {"item": {"role": "assistant", "content": {"type": "reasoning", "summary": "step one"}}}', + 'data: {"item": {"role": "assistant", "content": {"type": "reasoning", "summary": "step two"}}}', + ] + result = parse_sse_lines(lines) + assert [e.summary for e in result.reasoning_step_events] == ["step one", "step two"] + assert [e.ts for e in result.reasoning_step_events] == [4.5, 10.0] + + def test_parse_sse_lines_prefers_multipart_viz_over_adhoc_fallback(): """Real multipart visualization takes priority over adhoc tool call stash.""" From 81e1be4dbae61ff0435bd2cc74a8b2c807b30b66 Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 13:25:37 +0200 Subject: [PATCH 04/11] Shorten reasoning labels in latency_breakdown to the bolded title 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. --- .../src/gooddata_eval/core/models.py | 19 ++++++++++++- .../gooddata-eval/tests/test_sse_client.py | 28 +++++++++++++++++++ 2 files changed, 46 insertions(+), 1 deletion(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/models.py b/packages/gooddata-eval/src/gooddata_eval/core/models.py index 1b3710d2d..a6edde258 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/models.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/models.py @@ -5,6 +5,7 @@ """ import json +import re from typing import Any from pydantic import BaseModel, ConfigDict, Field, field_validator @@ -97,6 +98,22 @@ class ReasoningStepEvent(BaseModel): ts: float +# Reasoning summaries are full paragraphs, e.g. "**Identifying analytics needs**\n\nI'm +# analyzing..." -- using the whole thing as a latency_breakdown label would make every +# entry an unreadable wall of text. Same bolded-title convention this repo's own reasoning +# tooling already keys off of (see gdc-mic-ai-evaluation's generate_dashboard_summary.py). +_REASONING_TITLE_RE = re.compile(r"^\*\*(.+?)\*\*") +_REASONING_LABEL_MAX_LEN = 60 + + +def _reasoning_label(summary: str) -> str: + m = _REASONING_TITLE_RE.match(summary.strip()) + if m: + return m.group(1) + stripped = summary.strip().replace("\n", " ") + return stripped if len(stripped) <= _REASONING_LABEL_MAX_LEN else stripped[:_REASONING_LABEL_MAX_LEN] + "…" + + def build_latency_breakdown( tool_call_events: list[ToolCallEvent], reasoning_step_events: list[ReasoningStepEvent] | None = None, @@ -128,7 +145,7 @@ def build_latency_breakdown( continue points.append((tc.call_ts, "tool_start", tc.function_name)) points.append((tc.result_ts, "tool_end", tc.function_name)) - points.extend((rs.ts, "reasoning", rs.summary) for rs in reasoning_step_events or []) + points.extend((rs.ts, "reasoning", _reasoning_label(rs.summary)) for rs in reasoning_step_events or []) points.sort(key=lambda p: p[0]) by_label: dict[str, float] = {} diff --git a/packages/gooddata-eval/tests/test_sse_client.py b/packages/gooddata-eval/tests/test_sse_client.py index acebd6ce2..46b088a7b 100644 --- a/packages/gooddata-eval/tests/test_sse_client.py +++ b/packages/gooddata-eval/tests/test_sse_client.py @@ -121,6 +121,34 @@ def test_build_latency_breakdown_attributes_gaps_to_reasoning_steps(): } +def test_build_latency_breakdown_uses_bold_title_as_reasoning_label(): + # Real reasoning summaries are a bolded title followed by a full paragraph -- the + # label must be just the title, not the whole thing (unreadable as a dict key). A + # second tool call after the reasoning step gives its gap somewhere to end. + tool_events = [ + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), + ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0), + ] + reasoning_events = [ + ReasoningStepEvent(summary="**Picking the right metric**\n\nLots more detail follows here.", ts=2.5) + ] + result = build_latency_breakdown(tool_events, reasoning_events) + assert "reasoning:Picking the right metric" in result + assert not any("Lots more detail" in key for key in result) + + +def test_build_latency_breakdown_truncates_untitled_reasoning_labels(): + tool_events = [ + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), + ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0), + ] + long_summary = "x" * 200 + reasoning_events = [ReasoningStepEvent(summary=long_summary, ts=2.5)] + result = build_latency_breakdown(tool_events, reasoning_events) + (label,) = (k for k in result if k.startswith("reasoning:")) + assert len(label) < len(long_summary) + + def test_build_latency_breakdown_gap_with_no_reasoning_events_gets_a_catch_all_label(): # A gap between two tool calls with zero reasoning events supplied at all (e.g. an # older chat backend, or reasoning capture disabled) must not be silently dropped -- From e95ff9692905b254fa19839fdea23bc3ee072b9a Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 13:58:31 +0200 Subject: [PATCH 05/11] Add index to ReasoningStepEvent, fix best-run reasoning mismatch 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. --- .../core/agentic/visualization.py | 3 ++ .../src/gooddata_eval/core/chat/sse_client.py | 4 ++- .../src/gooddata_eval/core/models.py | 25 +++++++++----- .../src/gooddata_eval/core/runner.py | 11 +++++- packages/gooddata-eval/tests/test_runner.py | 27 +++++++++++++++ .../gooddata-eval/tests/test_sse_client.py | 34 ++++++++++++++++--- 6 files changed, 89 insertions(+), 15 deletions(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py index 3a8e072ac..06cca8135 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py @@ -173,6 +173,7 @@ def _execute_single_run( reasoning_steps: list[str] = [] response_id: str | None = None turn_offset = 0.0 # each turn's call_ts/ts restarts near 0 -- shift by prior turns' wall time + reasoning_index_offset = 0 # ditto for ReasoningStepEvent.index, which also restarts per turn simulated_response_guide = expected_outputs[0] # primary candidate guides the simulated user current_result = client.send_message(conversation_id, question) @@ -187,8 +188,10 @@ def _execute_single_run( tc.result_ts += turn_offset for rs in current_result.reasoning_step_events: rs.ts += turn_offset + rs.index += reasoning_index_offset all_tool_call_events.extend(current_result.tool_call_events) all_reasoning_step_events.extend(current_result.reasoning_step_events) + reasoning_index_offset += len(current_result.reasoning_step_events) reasoning_steps.extend(current_result.reasoning_steps or []) response_id = current_result.response_id or response_id turn_offset += current_result.turn_wall_clock_sec or 0.0 diff --git a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py index 204b758d9..e33d965de 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py @@ -165,7 +165,9 @@ def _handle_multipart(content: dict[str, Any], acc: _SseAccumulator) -> None: def _handle_reasoning(content: dict[str, Any], acc: _SseAccumulator) -> None: summary = content.get("summary", "") if summary: - acc.reasoning_steps.append({"summary": summary, "ts": round(time.monotonic() - acc.t0, 3)}) + acc.reasoning_steps.append( + {"summary": summary, "ts": round(time.monotonic() - acc.t0, 3), "index": len(acc.reasoning_steps)} + ) def _handle_tool_call(content: dict[str, Any], acc: _SseAccumulator) -> None: diff --git a/packages/gooddata-eval/src/gooddata_eval/core/models.py b/packages/gooddata-eval/src/gooddata_eval/core/models.py index a6edde258..5c633d02e 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/models.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/models.py @@ -92,10 +92,19 @@ def parsed_result(self) -> dict[str, Any] | None: class ReasoningStepEvent(BaseModel): - """One reasoning step with its client-observed receipt time (see ToolCallEvent.call_ts).""" + """One reasoning step with its client-observed receipt time (see ToolCallEvent.call_ts). + + ``index`` is this step's 0-based position among reasoning steps in the turn -- the same + position it occupies in ``ChatResult.reasoning_steps`` and, downstream, in the + ``.reasoning.json`` sidecar's ``reasoning`` list. It's embedded in + ``build_latency_breakdown``'s label precisely so the two files can be cross-referenced + by an exact index instead of fuzzy-matching on title text (which is not unique -- the + same title can recur, e.g. two distinct "Considering data analysis" steps). + """ summary: str ts: float + index: int # Reasoning summaries are full paragraphs, e.g. "**Identifying analytics needs**\n\nI'm @@ -106,12 +115,12 @@ class ReasoningStepEvent(BaseModel): _REASONING_LABEL_MAX_LEN = 60 -def _reasoning_label(summary: str) -> str: - m = _REASONING_TITLE_RE.match(summary.strip()) - if m: - return m.group(1) - stripped = summary.strip().replace("\n", " ") - return stripped if len(stripped) <= _REASONING_LABEL_MAX_LEN else stripped[:_REASONING_LABEL_MAX_LEN] + "…" +def _reasoning_label(step: "ReasoningStepEvent") -> str: + m = _REASONING_TITLE_RE.match(step.summary.strip()) + title = m.group(1) if m else step.summary.strip().replace("\n", " ") + if len(title) > _REASONING_LABEL_MAX_LEN: + title = title[:_REASONING_LABEL_MAX_LEN] + "…" + return f"{step.index}:{title}" def build_latency_breakdown( @@ -145,7 +154,7 @@ def build_latency_breakdown( continue points.append((tc.call_ts, "tool_start", tc.function_name)) points.append((tc.result_ts, "tool_end", tc.function_name)) - points.extend((rs.ts, "reasoning", _reasoning_label(rs.summary)) for rs in reasoning_step_events or []) + points.extend((rs.ts, "reasoning", _reasoning_label(rs)) for rs in reasoning_step_events or []) points.sort(key=lambda p: p[0]) by_label: dict[str, float] = {} diff --git a/packages/gooddata-eval/src/gooddata_eval/core/runner.py b/packages/gooddata-eval/src/gooddata_eval/core/runner.py index 0161cc3f8..3dfae7a08 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/runner.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/runner.py @@ -111,19 +111,24 @@ def _run_one_item( evaluator = get_evaluator(item.test_kind) best: ItemEvaluation | None = None + # Tracked alongside `best`, not just the last run's chat_result -- `best_detail` (and + # any latency_breakdown inside it) must describe the SAME run as `reasoning_steps` + # (the .reasoning.json sidecar's source), or the two files can disagree about which + # attempt they're each describing whenever the best-ranked run isn't also the last one. + best_chat_result: ChatResult | None = None try: for run_index in range(1, runs + 1): t0 = time.perf_counter() chat_result = backend.ask(item) report.conversation_id = getattr(chat_result, "conversation_id", None) or report.conversation_id report.response_id = getattr(chat_result, "response_id", None) or report.response_id - report.reasoning_steps = getattr(chat_result, "reasoning_steps", None) or report.reasoning_steps evaluation = evaluator.evaluate(item, chat_result) latency = time.perf_counter() - t0 report.runs += 1 report.latency_s += latency if best is None or evaluation.rank_key > best.rank_key: best = evaluation + best_chat_result = chat_result if evaluation.passed: report.pass_at_k = True if on_run_done is not None: @@ -134,10 +139,14 @@ def _run_one_item( report.error = f"{type(e).__name__}: {e}" + (f" [conversation_id={conv_id}]" if conv_id else "") if best is not None: report.best_detail = best.detail + if best_chat_result is not None: + report.reasoning_steps = getattr(best_chat_result, "reasoning_steps", None) or [] return report if best is not None: report.best_detail = best.detail + if best_chat_result is not None: + report.reasoning_steps = getattr(best_chat_result, "reasoning_steps", None) or [] return report diff --git a/packages/gooddata-eval/tests/test_runner.py b/packages/gooddata-eval/tests/test_runner.py index 925c214a6..98456103f 100644 --- a/packages/gooddata-eval/tests/test_runner.py +++ b/packages/gooddata-eval/tests/test_runner.py @@ -277,6 +277,33 @@ def test_run_items_reasoning_steps_empty_when_chat_result_has_none(): assert report.items[0].reasoning_steps == [] +def test_run_items_reasoning_steps_come_from_the_best_run_not_the_last_one(): + """reasoning_steps (and any latency_breakdown inside best_detail) must describe the + SAME run -- otherwise the .reasoning.json sidecar and detail.latency_breakdown can + each be narrating a different attempt whenever the best-ranked run isn't the last one. + """ + + class _BestIsFirstBackend: + def __init__(self): + self.calls = 0 + + def ask(self, item: DatasetItem) -> ChatResult: + self.calls += 1 + if self.calls == 1: # passes -- this becomes `best` + return ChatResult.model_validate( + { + "createdVisualizations": {"objects": [_viz_obj()], "reasoning": ""}, + "reasoningSteps": ["run 1: correct approach"], + } + ) + # run 2 fails, runs last -- must NOT overwrite reasoning_steps from run 1 + return ChatResult.model_validate({"textResponse": "which metric?", "reasoningSteps": ["run 2: gave up"]}) + + report = run_items([_item()], _BestIsFirstBackend(), runs=2) + assert report.items[0].pass_at_k is True + assert report.items[0].reasoning_steps == ["run 1: correct approach"] + + def test_run_items_reasoning_steps_keeps_earlier_run_when_later_run_is_empty(): """A later run with no reasoning events must not clobber an earlier run's steps (runner.py:120's `or`).""" diff --git a/packages/gooddata-eval/tests/test_sse_client.py b/packages/gooddata-eval/tests/test_sse_client.py index 46b088a7b..459e1057e 100644 --- a/packages/gooddata-eval/tests/test_sse_client.py +++ b/packages/gooddata-eval/tests/test_sse_client.py @@ -112,11 +112,15 @@ def test_build_latency_breakdown_attributes_gaps_to_reasoning_steps(): ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=65.0), ] - reasoning_events = [ReasoningStepEvent(summary="Picking the right metric", ts=2.5)] + reasoning_events = [ReasoningStepEvent(summary="Picking the right metric", ts=2.5, index=0)] result = build_latency_breakdown(tool_events, reasoning_events) assert result == { "tool:search_tool": 2.5, - "reasoning:Picking the right metric": 2.5, + # The leading "0:" is this step's index -- the same position it occupies in + # ChatResult.reasoning_steps / the .reasoning.json sidecar's ordered list, so the + # two files can be cross-referenced by an exact index instead of matching on + # (non-unique) title text. + "reasoning:0:Picking the right metric": 2.5, "tool:create_metric_alert": 60.0, } @@ -130,20 +134,39 @@ def test_build_latency_breakdown_uses_bold_title_as_reasoning_label(): ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0), ] reasoning_events = [ - ReasoningStepEvent(summary="**Picking the right metric**\n\nLots more detail follows here.", ts=2.5) + ReasoningStepEvent( + summary="**Picking the right metric**\n\nLots more detail follows here.", ts=2.5, index=0 + ) ] result = build_latency_breakdown(tool_events, reasoning_events) - assert "reasoning:Picking the right metric" in result + assert "reasoning:0:Picking the right metric" in result assert not any("Lots more detail" in key for key in result) +def test_build_latency_breakdown_reasoning_label_includes_its_sidecar_index(): + # Two reasoning steps sharing the same title (a real, common occurrence) must stay + # distinguishable -- their index makes each key unique even when the title repeats. + tool_events = [ + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=1.0), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=4.0, result_ts=5.0), + ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=8.0, result_ts=9.0), + ] + reasoning_events = [ + ReasoningStepEvent(summary="**Considering data analysis**", ts=1.0, index=0), + ReasoningStepEvent(summary="**Considering data analysis**", ts=5.0, index=1), + ] + result = build_latency_breakdown(tool_events, reasoning_events) + assert result["reasoning:0:Considering data analysis"] == 3.0 + assert result["reasoning:1:Considering data analysis"] == 3.0 + + def test_build_latency_breakdown_truncates_untitled_reasoning_labels(): tool_events = [ ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0), ] long_summary = "x" * 200 - reasoning_events = [ReasoningStepEvent(summary=long_summary, ts=2.5)] + reasoning_events = [ReasoningStepEvent(summary=long_summary, ts=2.5, index=0)] result = build_latency_breakdown(tool_events, reasoning_events) (label,) = (k for k in result if k.startswith("reasoning:")) assert len(label) < len(long_summary) @@ -327,6 +350,7 @@ def test_parse_sse_lines_stamps_reasoning_step_receipt_time(monkeypatch): result = parse_sse_lines(lines) assert [e.summary for e in result.reasoning_step_events] == ["step one", "step two"] assert [e.ts for e in result.reasoning_step_events] == [4.5, 10.0] + assert [e.index for e in result.reasoning_step_events] == [0, 1] def test_parse_sse_lines_prefers_multipart_viz_over_adhoc_fallback(): From c0b69e23f6717a5828d6f692114ac9c830394337 Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 14:59:49 +0200 Subject: [PATCH 06/11] Return build_latency_breakdown as an ordered step sequence, not a dict-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. --- .../core/agentic/visualization.py | 4 + .../src/gooddata_eval/core/chat/sse_client.py | 4 +- .../src/gooddata_eval/core/models.py | 110 ++++++++------ .../tests/test_agentic_visualization.py | 4 +- .../gooddata-eval/tests/test_sse_client.py | 138 ++++++++++++------ 5 files changed, 167 insertions(+), 93 deletions(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py index 06cca8135..486214cce 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py @@ -174,6 +174,7 @@ def _execute_single_run( response_id: str | None = None turn_offset = 0.0 # each turn's call_ts/ts restarts near 0 -- shift by prior turns' wall time reasoning_index_offset = 0 # ditto for ReasoningStepEvent.index, which also restarts per turn + tool_index_offset = 0 # ditto for ToolCallEvent.index simulated_response_guide = expected_outputs[0] # primary candidate guides the simulated user current_result = client.send_message(conversation_id, question) @@ -186,11 +187,14 @@ def _execute_single_run( tc.call_ts += turn_offset if tc.result_ts is not None: tc.result_ts += turn_offset + if tc.index is not None: + tc.index += tool_index_offset for rs in current_result.reasoning_step_events: rs.ts += turn_offset rs.index += reasoning_index_offset all_tool_call_events.extend(current_result.tool_call_events) all_reasoning_step_events.extend(current_result.reasoning_step_events) + tool_index_offset += len(current_result.tool_call_events) reasoning_index_offset += len(current_result.reasoning_step_events) reasoning_steps.extend(current_result.reasoning_steps or []) response_id = current_result.response_id or response_id diff --git a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py index e33d965de..cb18d3804 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py @@ -172,13 +172,15 @@ def _handle_reasoning(content: dict[str, Any], acc: _SseAccumulator) -> None: def _handle_tool_call(content: dict[str, Any], acc: _SseAccumulator) -> None: call_id = content.get("callId", "") - acc.call_id_to_event_index[call_id] = len(acc.tool_call_events) + idx = len(acc.tool_call_events) + acc.call_id_to_event_index[call_id] = idx acc.tool_call_events.append( { "functionName": content.get("name", ""), "functionArguments": json.dumps(content.get("arguments", {})), "result": None, "call_ts": round(time.monotonic() - acc.t0, 3), + "index": idx, } ) # Stash visualization definition from create_adhoc_visualization so we can diff --git a/packages/gooddata-eval/src/gooddata_eval/core/models.py b/packages/gooddata-eval/src/gooddata_eval/core/models.py index 5c633d02e..96c062142 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/models.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/models.py @@ -75,6 +75,12 @@ class ToolCallEvent(BaseModel): # tool-result events stream in. None when the call never got a result (stalled turn). call_ts: float | None = None result_ts: float | None = None + # This call's 0-based position among tool calls in the turn (mirrors + # ReasoningStepEvent.index) -- lets build_latency_breakdown's timeline point back at + # this exact ToolCallEvent (its arguments/result) even when the same tool is called + # more than once. Optional/None for callers that build a ToolCallEvent by hand (most + # existing tests, and any real event from a chat backend older than this capture). + index: int | None = None def parsed_arguments(self) -> dict[str, Any]: try: @@ -115,65 +121,85 @@ class ReasoningStepEvent(BaseModel): _REASONING_LABEL_MAX_LEN = 60 -def _reasoning_label(step: "ReasoningStepEvent") -> str: - m = _REASONING_TITLE_RE.match(step.summary.strip()) - title = m.group(1) if m else step.summary.strip().replace("\n", " ") - if len(title) > _REASONING_LABEL_MAX_LEN: - title = title[:_REASONING_LABEL_MAX_LEN] + "…" - return f"{step.index}:{title}" +def _reasoning_title(summary: str) -> str: + m = _REASONING_TITLE_RE.match(summary.strip()) + title = m.group(1) if m else summary.strip().replace("\n", " ") + return title if len(title) <= _REASONING_LABEL_MAX_LEN else title[:_REASONING_LABEL_MAX_LEN] + "…" def build_latency_breakdown( tool_call_events: list[ToolCallEvent], reasoning_step_events: list[ReasoningStepEvent] | None = None, -) -> dict[str, float]: - """Wall time attributed to each tool call and each reasoning step in the turn. - - Without ``reasoning_step_events``, this is just per-tool wall time (call receipt to - result receipt) summed by name -- the gaps between tool calls (the model "thinking") - are left unaccounted for. +) -> list[dict]: + """The turn's tool calls and reasoning steps, in EXECUTION ORDER, each with its own + wall time -- reconstructs the actual pipeline, not just a per-name total. + + Each entry: ``{"seq", "kind", "name", "index", "duration_s"}``. + + - ``seq``: 0-based position in execution order across tools AND reasoning combined. + This is what answers "what ran before what" -- unlike a dict keyed by name, nothing + here is aggregated together just for sharing a label, so the same tool called twice + produces two separate entries in their real order, not one summed one. + - ``kind``: ``"tool"`` or ``"reasoning"``. + - ``name``: the tool's ``function_name``, or the reasoning step's title (see + ``_reasoning_title``). + - ``index``: this step's position within its OWN kind's source list -- + ``ToolCallEvent.index`` for tools, ``ReasoningStepEvent.index`` for reasoning (the + same position it occupies in the ``.reasoning.json`` sidecar's ``reasoning`` list). + Use it to look up the full record -- the tool call's arguments/result, or the + reasoning step's full paragraph in the sidecar -- since this function only ever + keeps the short name/title. ``None`` for the "nothing reasoned yet" catch-all before + the first real reasoning step. + - ``duration_s``: wall time attributed to this step. + + Without ``reasoning_step_events``, only tool-call entries are produced (call receipt + to result receipt) -- the gaps between them (the model "thinking") are left out + entirely rather than invented as a fake step. With them, every point in the turn -- a tool call starting, a tool call's result arriving, or a reasoning step being emitted -- is merged into one timeline and sorted. - The gap between consecutive points is charged to whatever was "active" during it: a - tool call while it's outstanding (call event to result event), or the most recently - emitted reasoning step's own summary otherwise (its gap runs until the next point, - whatever that turns out to be -- another reasoning step, or the next tool call - starting). This accounts for effectively the whole turn, not just its tool-call - portion; only the time before the first point and after the last (connection - setup/teardown) is left out, since this function has no reference to the turn's total - duration. - - Calls missing either timestamp (stalled, or from a chat backend that predates this - capture) are skipped rather than counted as zero -- an absent entry means "unknown", - not "instant". + The gap between consecutive points becomes one entry, attributed to whatever was + "active" during it: the tool while its call is outstanding, or the most recently + emitted reasoning step otherwise (its gap runs until the next point, whatever that + turns out to be). This accounts for effectively the whole turn, not just its + tool-call portion; only the time before the first point and after the last + (connection setup/teardown) is left out, since this function has no reference to the + turn's total duration. + + Tool calls missing either timestamp (stalled, or from a chat backend that predates + this capture) are skipped entirely rather than producing a zero-duration entry. """ - points: list[tuple[float, str, str]] = [] # (ts, kind, label); kind: tool_start/tool_end/reasoning + points: list[tuple[float, str, str, int | None]] = [] # (ts, point_kind, name, index) for tc in tool_call_events: if tc.call_ts is None or tc.result_ts is None: continue - points.append((tc.call_ts, "tool_start", tc.function_name)) - points.append((tc.result_ts, "tool_end", tc.function_name)) - points.extend((rs.ts, "reasoning", _reasoning_label(rs)) for rs in reasoning_step_events or []) + points.append((tc.call_ts, "tool_start", tc.function_name, tc.index)) + points.append((tc.result_ts, "tool_end", tc.function_name, tc.index)) + points.extend( + (rs.ts, "reasoning", _reasoning_title(rs.summary), rs.index) for rs in reasoning_step_events or [] + ) points.sort(key=lambda p: p[0]) - by_label: dict[str, float] = {} - current_reasoning_label = "reasoning:(before first step)" - for (ts, kind, label), (next_ts, _, _) in zip(points, points[1:]): + steps: list[dict] = [] + current_reasoning_name, current_reasoning_index = "(before first step)", None + seq = 0 + for (ts, point_kind, name, index), (next_ts, _, _, _) in zip(points, points[1:]): gap = next_ts - ts if gap <= 0: continue - if kind == "tool_start": - key = f"tool:{label}" - else: - # A tool call resolving, or a reasoning step being emitted, both hand control - # back to "whatever the model is doing until the next point" -- which is this - # reasoning step once one has been seen, else the pre-first-step catch-all. - key = f"reasoning:{label}" if kind == "reasoning" else current_reasoning_label - by_label[key] = by_label.get(key, 0.0) + gap - if kind == "reasoning": - current_reasoning_label = f"reasoning:{label}" - return {name: round(secs, 2) for name, secs in by_label.items()} + if point_kind == "tool_start": + step_kind, step_name, step_index = "tool", name, index + elif point_kind == "reasoning": + step_kind, step_name, step_index = "reasoning", name, index + else: # tool_end -- control passes to whatever reasoning is (or isn't yet) active + step_kind, step_name, step_index = "reasoning", current_reasoning_name, current_reasoning_index + steps.append( + {"seq": seq, "kind": step_kind, "name": step_name, "index": step_index, "duration_s": round(gap, 2)} + ) + seq += 1 + if point_kind == "reasoning": + current_reasoning_name, current_reasoning_index = name, index + return steps class ChatResult(BaseModel): diff --git a/packages/gooddata-eval/tests/test_agentic_visualization.py b/packages/gooddata-eval/tests/test_agentic_visualization.py index a9bb3c8ce..766313d74 100644 --- a/packages/gooddata-eval/tests/test_agentic_visualization.py +++ b/packages/gooddata-eval/tests/test_agentic_visualization.py @@ -320,7 +320,7 @@ def test_evaluate_agentic_visualization_returns_reasoning_steps_on_pass(): "actual_dim_uris": ["label/date.quarter"], "expected_filters": {"date": [], "ranking": [], "attribute": []}, "actual_filters": {"date": [], "ranking": [], "attribute": []}, - "latency_breakdown": {}, + "latency_breakdown": [], } @@ -371,5 +371,5 @@ def test_evaluate_agentic_visualization_attaches_reasoning_steps_to_exception_on "actual_dim_uris": [], "expected_filters": {"date": [], "ranking": [], "attribute": []}, "actual_filters": {"date": [], "ranking": [], "attribute": []}, - "latency_breakdown": {}, + "latency_breakdown": [], } diff --git a/packages/gooddata-eval/tests/test_sse_client.py b/packages/gooddata-eval/tests/test_sse_client.py index 459e1057e..ae16b994b 100644 --- a/packages/gooddata-eval/tests/test_sse_client.py +++ b/packages/gooddata-eval/tests/test_sse_client.py @@ -91,17 +91,25 @@ def test_parse_sse_lines_stamps_call_and_result_receipt_time(monkeypatch): tc = result.tool_call_events[0] assert tc.call_ts == 5.0 assert tc.result_ts == 30.5 + assert tc.index == 0 -def test_build_latency_breakdown_sums_by_tool_name(): - # Adjacent, back-to-back calls (no gap between them) so the only two labels are the - # tools themselves -- the tool_end-to-tool_start gap case is covered separately below. +def test_build_latency_breakdown_gives_repeated_tool_calls_separate_entries_in_order(): + # Same tool called twice, back-to-back (no gap between them). A dict keyed by tool + # name would sum these into one number and lose which call was slower -- each call + # must stay its own entry, in the order it actually ran, identifiable by its index. events = [ - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=2.5, result_ts=3.5), - ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=3.5, result_ts=63.7), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5, index=0), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=2.5, result_ts=3.5, index=1), + ToolCallEvent( + function_name="create_metric_alert", function_arguments="{}", call_ts=3.5, result_ts=63.7, index=2 + ), + ] + assert build_latency_breakdown(events) == [ + {"seq": 0, "kind": "tool", "name": "search_tool", "index": 0, "duration_s": 2.5}, + {"seq": 1, "kind": "tool", "name": "search_tool", "index": 1, "duration_s": 1.0}, + {"seq": 2, "kind": "tool", "name": "create_metric_alert", "index": 2, "duration_s": 60.2}, ] - assert build_latency_breakdown(events) == {"tool:search_tool": 3.5, "tool:create_metric_alert": 60.2} def test_build_latency_breakdown_attributes_gaps_to_reasoning_steps(): @@ -109,29 +117,28 @@ def test_build_latency_breakdown_attributes_gaps_to_reasoning_steps(): # goes idle until the next tool call starts at 5.0s -- that whole 2.5s idle gap belongs # to the reasoning step, not to "search_tool" (which already finished) or nothing. tool_events = [ - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), - ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=65.0), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5, index=0), + ToolCallEvent( + function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=65.0, index=1 + ), ] reasoning_events = [ReasoningStepEvent(summary="Picking the right metric", ts=2.5, index=0)] result = build_latency_breakdown(tool_events, reasoning_events) - assert result == { - "tool:search_tool": 2.5, - # The leading "0:" is this step's index -- the same position it occupies in - # ChatResult.reasoning_steps / the .reasoning.json sidecar's ordered list, so the - # two files can be cross-referenced by an exact index instead of matching on - # (non-unique) title text. - "reasoning:0:Picking the right metric": 2.5, - "tool:create_metric_alert": 60.0, - } + assert result == [ + {"seq": 0, "kind": "tool", "name": "search_tool", "index": 0, "duration_s": 2.5}, + {"seq": 1, "kind": "reasoning", "name": "Picking the right metric", "index": 0, "duration_s": 2.5}, + {"seq": 2, "kind": "tool", "name": "create_metric_alert", "index": 1, "duration_s": 60.0}, + ] -def test_build_latency_breakdown_uses_bold_title_as_reasoning_label(): - # Real reasoning summaries are a bolded title followed by a full paragraph -- the - # label must be just the title, not the whole thing (unreadable as a dict key). A - # second tool call after the reasoning step gives its gap somewhere to end. +def test_build_latency_breakdown_uses_bold_title_as_reasoning_name(): + # Real reasoning summaries are a bolded title followed by a full paragraph -- "name" + # must be just the title, not the whole thing. tool_events = [ - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), - ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5, index=0), + ToolCallEvent( + function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0, index=1 + ), ] reasoning_events = [ ReasoningStepEvent( @@ -139,53 +146,88 @@ def test_build_latency_breakdown_uses_bold_title_as_reasoning_label(): ) ] result = build_latency_breakdown(tool_events, reasoning_events) - assert "reasoning:0:Picking the right metric" in result - assert not any("Lots more detail" in key for key in result) + reasoning_step = next(s for s in result if s["kind"] == "reasoning") + assert reasoning_step["name"] == "Picking the right metric" + assert "Lots more detail" not in reasoning_step["name"] -def test_build_latency_breakdown_reasoning_label_includes_its_sidecar_index(): +def test_build_latency_breakdown_disambiguates_reasoning_steps_sharing_a_title_by_index(): # Two reasoning steps sharing the same title (a real, common occurrence) must stay - # distinguishable -- their index makes each key unique even when the title repeats. + # distinguishable via "index" even though "name" repeats. tool_events = [ - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=1.0), - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=4.0, result_ts=5.0), - ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=8.0, result_ts=9.0), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=1.0, index=0), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=4.0, result_ts=5.0, index=1), + ToolCallEvent( + function_name="create_metric_alert", function_arguments="{}", call_ts=8.0, result_ts=9.0, index=2 + ), ] reasoning_events = [ ReasoningStepEvent(summary="**Considering data analysis**", ts=1.0, index=0), ReasoningStepEvent(summary="**Considering data analysis**", ts=5.0, index=1), ] result = build_latency_breakdown(tool_events, reasoning_events) - assert result["reasoning:0:Considering data analysis"] == 3.0 - assert result["reasoning:1:Considering data analysis"] == 3.0 + reasoning_steps = [s for s in result if s["kind"] == "reasoning"] + assert [s["index"] for s in reasoning_steps] == [0, 1] + assert all(s["name"] == "Considering data analysis" for s in reasoning_steps) + assert [s["duration_s"] for s in reasoning_steps] == [3.0, 3.0] -def test_build_latency_breakdown_truncates_untitled_reasoning_labels(): +def test_build_latency_breakdown_truncates_untitled_reasoning_names(): tool_events = [ - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), - ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5, index=0), + ToolCallEvent( + function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0, index=1 + ), ] long_summary = "x" * 200 reasoning_events = [ReasoningStepEvent(summary=long_summary, ts=2.5, index=0)] result = build_latency_breakdown(tool_events, reasoning_events) - (label,) = (k for k in result if k.startswith("reasoning:")) - assert len(label) < len(long_summary) + reasoning_step = next(s for s in result if s["kind"] == "reasoning") + assert len(reasoning_step["name"]) < len(long_summary) + + +def test_build_latency_breakdown_seq_reflects_true_execution_order(): + # Interleaved on purpose: reasoning, tool, reasoning, tool -- seq must follow actual + # chronological order, not group all tools first or all reasoning first. + tool_events = [ + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=1.0, result_ts=2.0, index=0), + ToolCallEvent( + function_name="create_metric_alert", function_arguments="{}", call_ts=4.0, result_ts=5.0, index=1 + ), + ] + reasoning_events = [ + ReasoningStepEvent(summary="**First**", ts=0.0, index=0), + ReasoningStepEvent(summary="**Second**", ts=3.0, index=1), + ] + result = build_latency_breakdown(tool_events, reasoning_events) + # "First" appears twice: once for the 0.0-1.0 gap before search_tool starts, and again + # for the 2.0-3.0 gap after it resolves -- "First" is still the last-emitted reasoning + # step until "Second" itself arrives at 3.0, so that gap is correctly its too. + assert [(s["seq"], s["kind"], s["name"]) for s in result] == [ + (0, "reasoning", "First"), + (1, "tool", "search_tool"), + (2, "reasoning", "First"), + (3, "reasoning", "Second"), + (4, "tool", "create_metric_alert"), + ] -def test_build_latency_breakdown_gap_with_no_reasoning_events_gets_a_catch_all_label(): +def test_build_latency_breakdown_gap_with_no_reasoning_events_gets_a_catch_all_name(): # A gap between two tool calls with zero reasoning events supplied at all (e.g. an # older chat backend, or reasoning capture disabled) must not be silently dropped -- - # it needs a label that doesn't fake having a real summary for it. + # it needs a name that doesn't fake having a real summary for it. tool_events = [ - ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5), - ToolCallEvent(function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=65.0), + ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=2.5, index=0), + ToolCallEvent( + function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=65.0, index=1 + ), ] result = build_latency_breakdown(tool_events, reasoning_step_events=None) - assert result == { - "tool:search_tool": 2.5, - "reasoning:(before first step)": 2.5, - "tool:create_metric_alert": 60.0, - } + assert result == [ + {"seq": 0, "kind": "tool", "name": "search_tool", "index": 0, "duration_s": 2.5}, + {"seq": 1, "kind": "reasoning", "name": "(before first step)", "index": None, "duration_s": 2.5}, + {"seq": 2, "kind": "tool", "name": "create_metric_alert", "index": 1, "duration_s": 60.0}, + ] def test_build_latency_breakdown_skips_calls_missing_a_timestamp(): @@ -193,7 +235,7 @@ def test_build_latency_breakdown_skips_calls_missing_a_timestamp(): ToolCallEvent(function_name="search_tool", function_arguments="{}", call_ts=0.0, result_ts=None), ToolCallEvent(function_name="create_metric_alert", function_arguments="{}"), ] - assert build_latency_breakdown(events) == {} + assert build_latency_breakdown(events) == [] def test_parse_sse_lines_raw_transport_error_also_carries_partial_result(): From 8f4d236d13d899d7212696ce811619685dd48386 Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 15:53:35 +0200 Subject: [PATCH 07/11] Add best_run_latency_s: the run detail.latency_breakdown actually describes 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. --- .../core/reporting/json_report.py | 3 +++ .../src/gooddata_eval/core/runner.py | 9 +++++++ packages/gooddata-eval/tests/test_runner.py | 26 +++++++++++++++++++ 3 files changed, 38 insertions(+) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/reporting/json_report.py b/packages/gooddata-eval/src/gooddata_eval/core/reporting/json_report.py index 1a28e0001..d0b34483d 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/reporting/json_report.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/reporting/json_report.py @@ -33,6 +33,9 @@ def _build_run_dict(report: EvalReport) -> dict: "runs": item.runs, "latency_s": round(item.latency_s, 3), "avg_latency_s": round(item.avg_latency_s, 3), + "best_run_latency_s": ( + round(item.best_run_latency_s, 3) if item.best_run_latency_s is not None else None + ), "detail": item.best_detail, "conversation_id": item.conversation_id, "response_id": item.response_id, diff --git a/packages/gooddata-eval/src/gooddata_eval/core/runner.py b/packages/gooddata-eval/src/gooddata_eval/core/runner.py index 3dfae7a08..f82da9aaf 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/runner.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/runner.py @@ -30,6 +30,11 @@ class ItemReport: error: str | None = None runs: int = 0 latency_s: float = 0.0 # total wall-clock across this item's runs + # The specific latency of whichever run best_detail/reasoning_steps describe -- NOT + # comparable to avg_latency_s (a mean across all K runs) once runs > 1: a + # detail.latency_breakdown always belongs to this one run, and checking how much of + # IT that breakdown explains needs this number, not the cross-run average. + best_run_latency_s: float | None = None best_detail: dict = field(default_factory=dict) conversation_id: str | None = None response_id: str | None = None @@ -116,6 +121,7 @@ def _run_one_item( # (the .reasoning.json sidecar's source), or the two files can disagree about which # attempt they're each describing whenever the best-ranked run isn't also the last one. best_chat_result: ChatResult | None = None + best_run_latency: float | None = None try: for run_index in range(1, runs + 1): t0 = time.perf_counter() @@ -129,6 +135,7 @@ def _run_one_item( if best is None or evaluation.rank_key > best.rank_key: best = evaluation best_chat_result = chat_result + best_run_latency = latency if evaluation.passed: report.pass_at_k = True if on_run_done is not None: @@ -139,12 +146,14 @@ def _run_one_item( report.error = f"{type(e).__name__}: {e}" + (f" [conversation_id={conv_id}]" if conv_id else "") if best is not None: report.best_detail = best.detail + report.best_run_latency_s = best_run_latency if best_chat_result is not None: report.reasoning_steps = getattr(best_chat_result, "reasoning_steps", None) or [] return report if best is not None: report.best_detail = best.detail + report.best_run_latency_s = best_run_latency if best_chat_result is not None: report.reasoning_steps = getattr(best_chat_result, "reasoning_steps", None) or [] return report diff --git a/packages/gooddata-eval/tests/test_runner.py b/packages/gooddata-eval/tests/test_runner.py index 98456103f..11fb4b2f6 100644 --- a/packages/gooddata-eval/tests/test_runner.py +++ b/packages/gooddata-eval/tests/test_runner.py @@ -1,5 +1,6 @@ # (C) 2026 GoodData Corporation import threading +import time from gooddata_eval.core.evaluators import supported_test_kinds from gooddata_eval.core.models import ChatResult, DatasetItem @@ -304,6 +305,31 @@ def ask(self, item: DatasetItem) -> ChatResult: assert report.items[0].reasoning_steps == ["run 1: correct approach"] +def test_run_items_best_run_latency_s_is_not_the_cross_run_average(): + """best_run_latency_s is the SPECIFIC latency of the run behind best_detail -- + avg_latency_s (a mean across all K runs) is not a fair number to check a + detail.latency_breakdown against once runs > 1, since it may describe a run other + than the mean. + """ + + class _SlowBackend: + def __init__(self): + self.calls = 0 + + def ask(self, item: DatasetItem) -> ChatResult: + self.calls += 1 + if self.calls == 1: + time.sleep(0.02) # the slower run -- passes, becomes `best` + return ChatResult.model_validate({"createdVisualizations": {"objects": [_viz_obj()], "reasoning": ""}}) + return _empty_chat() # fast, fails + + report = run_items([_item()], _SlowBackend(), runs=2) + item = report.items[0] + assert item.best_run_latency_s is not None + assert item.best_run_latency_s < item.latency_s # it's one run's share, not the total + assert item.best_run_latency_s != item.avg_latency_s # and not the cross-run mean either + + def test_run_items_reasoning_steps_keeps_earlier_run_when_later_run_is_empty(): """A later run with no reasoning events must not clobber an earlier run's steps (runner.py:120's `or`).""" From 8c2ce8fab4eaa7659e374ce59b23e9f8cf6e125a Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 17:42:34 +0200 Subject: [PATCH 08/11] Wire latency_breakdown into the remaining 7 agentic/single-shot evaluators 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. --- .../gooddata_eval/core/agentic/alert_skill.py | 28 ++++++++++- .../core/agentic/conversation.py | 36 +++++++++++++- .../gooddata_eval/core/agentic/guardrail.py | 10 +++- .../core/agentic/metric_skill.py | 28 ++++++++++- .../core/evaluators/general_question.py | 10 +++- .../core/evaluators/guardrail.py | 13 ++++- .../core/evaluators/search_tool.py | 5 +- .../tests/test_agentic_alert_skill.py | 2 + .../tests/test_agentic_conversation.py | 47 +++++++++++++++++++ .../tests/test_agentic_guardrail.py | 2 + .../tests/test_agentic_metric_skill.py | 2 + 11 files changed, 174 insertions(+), 9 deletions(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/agentic/alert_skill.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/alert_skill.py index 1f9434493..dc47ace2e 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/agentic/alert_skill.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/agentic/alert_skill.py @@ -14,7 +14,7 @@ from gooddata_eval.core.agentic._catalog import CatalogMetricAlert from gooddata_eval.core.chat.sse_client import ChatClient from gooddata_eval.core.config import ReasoningEffort -from gooddata_eval.core.models import AgenticEvalOutcome, ToolCallEvent +from gooddata_eval.core.models import AgenticEvalOutcome, ReasoningStepEvent, ToolCallEvent, build_latency_breakdown try: from openai import OpenAI as _OpenAI @@ -345,6 +345,8 @@ class AlertRunResult: actual_alert_arguments: dict reasoning_steps: list[str] = field(default_factory=list) response_id: str | None = None + tool_call_events: list[ToolCallEvent] = field(default_factory=list) + reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list) @dataclass @@ -495,6 +497,11 @@ def _run_once(conv_id: str) -> AlertRunResult: tool_called = False reasoning_steps: list[str] = [] response_id: str | None = None + all_tool_call_events: list[ToolCallEvent] = [] + all_reasoning_step_events: list[ReasoningStepEvent] = [] + turn_offset = 0.0 # each turn's call_ts/ts restarts near 0 -- shift by prior turns' wall time + tool_index_offset = 0 + reasoning_index_offset = 0 # conversation_history stores prior turns for GPT-4o context. # Roles follow GPT-4o's perspective: "assistant"=agent text, "user"=sim-user reply. conversation_history: list = [] @@ -504,6 +511,21 @@ def _run_once(conv_id: str) -> AlertRunResult: chat_result = client.send_message(conv_id, current_question) reasoning_steps.extend(chat_result.reasoning_steps or []) response_id = chat_result.response_id or response_id + for tc in chat_result.tool_call_events or []: + if tc.call_ts is not None: + tc.call_ts += turn_offset + if tc.result_ts is not None: + tc.result_ts += turn_offset + if tc.index is not None: + tc.index += tool_index_offset + for rs in chat_result.reasoning_step_events or []: + rs.ts += turn_offset + rs.index += reasoning_index_offset + all_tool_call_events.extend(chat_result.tool_call_events or []) + all_reasoning_step_events.extend(chat_result.reasoning_step_events or []) + tool_index_offset += len(chat_result.tool_call_events or []) + reasoning_index_offset += len(chat_result.reasoning_step_events or []) + turn_offset += chat_result.turn_wall_clock_sec or 0.0 alert_id, actual_args, tool_called = _extract_alert_call(chat_result.tool_call_events or []) if tool_called: alert_id_to_delete = alert_id @@ -541,6 +563,8 @@ def _run_once(conv_id: str) -> AlertRunResult: actual_alert_arguments=actual_args, reasoning_steps=reasoning_steps, response_id=response_id, + tool_call_events=all_tool_call_events, + reasoning_step_events=all_reasoning_step_events, ) finally: if alert_id_to_delete: @@ -717,6 +741,7 @@ def evaluate_agentic_alert_skill( "metric_correct": ev.metric_correct, "recipients_correct": ev.recipients_correct, "actual_alert_arguments": best.actual_alert_arguments, + "latency_breakdown": build_latency_breakdown(best.tool_call_events, best.reasoning_step_events), } raise exc best = summary.best @@ -734,5 +759,6 @@ def evaluate_agentic_alert_skill( "metric_correct": ev.metric_correct, "recipients_correct": ev.recipients_correct, "actual_alert_arguments": best.actual_alert_arguments, + "latency_breakdown": build_latency_breakdown(best.tool_call_events, best.reasoning_step_events), }, ) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/agentic/conversation.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/conversation.py index dd1368cd7..a87338df3 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/agentic/conversation.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/agentic/conversation.py @@ -15,7 +15,13 @@ from gooddata_eval.core.agentic.metric_skill import _delete_metric, _extract_created_metric_ids, _extract_metric_result from gooddata_eval.core.chat.sse_client import ChatClient from gooddata_eval.core.config import ReasoningEffort -from gooddata_eval.core.models import AgenticEvalOutcome, ChatResult, ToolCallEvent +from gooddata_eval.core.models import ( + AgenticEvalOutcome, + ChatResult, + ReasoningStepEvent, + ToolCallEvent, + build_latency_breakdown, +) from gooddata_eval.core.scoring import ( check_filters, check_viz_type, @@ -254,6 +260,8 @@ class ConversationResult: total_clarification_turns: int reasoning_steps: list[str] = field(default_factory=list) response_id: str | None = None + tool_call_events: list[ToolCallEvent] = field(default_factory=list) + reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list) def run_agentic_conversation( @@ -287,6 +295,14 @@ def run_agentic_conversation( created_metric_ids: list[str] = [] reasoning_steps: list[str] = [] response_id: str | None = None + conversation_tool_call_events: list[ToolCallEvent] = [] + conversation_reasoning_step_events: list[ReasoningStepEvent] = [] + # Every send_message() call (across every logical turn AND every clarification + # sub-turn within it) restarts call_ts/ts near 0 -- these run across the whole + # conversation, not reset per logical turn, so every one of those calls shifts them. + turn_offset = 0.0 + tool_index_offset = 0 + reasoning_index_offset = 0 try: if initial_conversation_id is not None: @@ -322,7 +338,22 @@ def run_agentic_conversation( for _iter in range(max_clarification_turns + 1): chat_result = client.send_message(conversation_id, current_message) final_result = chat_result + for tc in chat_result.tool_call_events or []: + if tc.call_ts is not None: + tc.call_ts += turn_offset + if tc.result_ts is not None: + tc.result_ts += turn_offset + if tc.index is not None: + tc.index += tool_index_offset + for rs in chat_result.reasoning_step_events or []: + rs.ts += turn_offset + rs.index += reasoning_index_offset all_tool_calls.extend(chat_result.tool_call_events or []) + conversation_tool_call_events.extend(chat_result.tool_call_events or []) + conversation_reasoning_step_events.extend(chat_result.reasoning_step_events or []) + tool_index_offset += len(chat_result.tool_call_events or []) + reasoning_index_offset += len(chat_result.reasoning_step_events or []) + turn_offset += chat_result.turn_wall_clock_sec or 0.0 reasoning_steps.extend(chat_result.reasoning_steps or []) response_id = chat_result.response_id or response_id @@ -390,6 +421,8 @@ def run_agentic_conversation( total_clarification_turns=total_clarification_turns, reasoning_steps=reasoning_steps, response_id=response_id, + tool_call_events=conversation_tool_call_events, + reasoning_step_events=conversation_reasoning_step_events, ) @@ -408,6 +441,7 @@ def _conversation_detail(result: ConversationResult) -> dict: } for tr in result.turn_results ], + "latency_breakdown": build_latency_breakdown(result.tool_call_events, result.reasoning_step_events), } diff --git a/packages/gooddata-eval/src/gooddata_eval/core/agentic/guardrail.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/guardrail.py index fa30e9725..673a7b321 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/agentic/guardrail.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/agentic/guardrail.py @@ -8,7 +8,7 @@ from gooddata_eval.core.chat.sse_client import ChatClient from gooddata_eval.core.config import ReasoningEffort from gooddata_eval.core.evaluators._llm_judge import LLMJudge -from gooddata_eval.core.models import AgenticEvalOutcome +from gooddata_eval.core.models import AgenticEvalOutcome, ReasoningStepEvent, ToolCallEvent, build_latency_breakdown _DEFAULT_K = 1 @@ -52,6 +52,8 @@ class GuardrailResult: reasoning: str reasoning_steps: list[str] = field(default_factory=list) response_id: str | None = None + tool_call_events: list[ToolCallEvent] = field(default_factory=list) + reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list) @dataclass @@ -100,6 +102,8 @@ def run_agentic_guardrail( reasoning=reasoning, reasoning_steps=list(chat_result.reasoning_steps or []), response_id=chat_result.response_id, + tool_call_events=list(chat_result.tool_call_events or []), + reasoning_step_events=list(chat_result.reasoning_step_events or []), ) ) finally: @@ -124,6 +128,8 @@ def run_agentic_guardrail( reasoning=reasoning, reasoning_steps=list(chat_result.reasoning_steps or []), response_id=chat_result.response_id, + tool_call_events=list(chat_result.tool_call_events or []), + reasoning_step_events=list(chat_result.reasoning_step_events or []), ) ) finally: @@ -245,6 +251,7 @@ def evaluate_agentic_guardrail( "judge_passed": best.passed, "judge_reasoning": best.reasoning, "actual_output": best.actual_output, + "latency_breakdown": build_latency_breakdown(best.tool_call_events, best.reasoning_step_events), } raise exc best = summary.best @@ -256,5 +263,6 @@ def evaluate_agentic_guardrail( "judge_passed": best.passed, "judge_reasoning": best.reasoning, "actual_output": best.actual_output, + "latency_breakdown": build_latency_breakdown(best.tool_call_events, best.reasoning_step_events), }, ) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/agentic/metric_skill.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/metric_skill.py index 235e8a23c..562308d19 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/agentic/metric_skill.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/agentic/metric_skill.py @@ -12,7 +12,7 @@ from gooddata_eval.core.chat.sse_client import ChatClient from gooddata_eval.core.config import ReasoningEffort -from gooddata_eval.core.models import AgenticEvalOutcome, ToolCallEvent +from gooddata_eval.core.models import AgenticEvalOutcome, ReasoningStepEvent, ToolCallEvent, build_latency_breakdown try: from openai import OpenAI as _OpenAI @@ -150,6 +150,8 @@ class MetricRunResult: total_turns: float reasoning_steps: list[str] = field(default_factory=list) response_id: str | None = None + tool_call_events: list[ToolCallEvent] = field(default_factory=list) + reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list) @dataclass @@ -239,6 +241,11 @@ def _execute_single_metric_run( current_question = question reasoning_steps: list[str] = [] response_id: str | None = None + all_tool_call_events: list[ToolCallEvent] = [] + all_reasoning_step_events: list[ReasoningStepEvent] = [] + turn_offset = 0.0 # each turn's call_ts/ts restarts near 0 -- shift by prior turns' wall time + tool_index_offset = 0 + reasoning_index_offset = 0 try: for _iteration in range(max_iterations): @@ -246,6 +253,21 @@ def _execute_single_metric_run( chat_result = client.send_message(conversation_id, current_question) reasoning_steps.extend(chat_result.reasoning_steps or []) response_id = chat_result.response_id or response_id + for tc in chat_result.tool_call_events or []: + if tc.call_ts is not None: + tc.call_ts += turn_offset + if tc.result_ts is not None: + tc.result_ts += turn_offset + if tc.index is not None: + tc.index += tool_index_offset + for rs in chat_result.reasoning_step_events or []: + rs.ts += turn_offset + rs.index += reasoning_index_offset + all_tool_call_events.extend(chat_result.tool_call_events or []) + all_reasoning_step_events.extend(chat_result.reasoning_step_events or []) + tool_index_offset += len(chat_result.tool_call_events or []) + reasoning_index_offset += len(chat_result.reasoning_step_events or []) + turn_offset += chat_result.turn_wall_clock_sec or 0.0 for metric_id in _extract_created_metric_ids(chat_result.tool_call_events or []): if metric_id not in created_metric_ids: created_metric_ids.append(metric_id) @@ -276,6 +298,8 @@ def _execute_single_metric_run( total_turns=float(turns), reasoning_steps=reasoning_steps, response_id=response_id, + tool_call_events=all_tool_call_events, + reasoning_step_events=all_reasoning_step_events, ) finally: for metric_id in created_metric_ids: @@ -457,6 +481,7 @@ def evaluate_agentic_metric_skill( "maql_correct": best.maql_correct, "expected_maql_candidates": [c.get("maql", "") for c in expected_outputs_list], "actual_maql": best.actual_maql, + "latency_breakdown": build_latency_breakdown(best.tool_call_events, best.reasoning_step_events), } raise exc best = summary.best @@ -470,5 +495,6 @@ def evaluate_agentic_metric_skill( "maql_correct": best.maql_correct, "expected_maql_candidates": [c.get("maql", "") for c in expected_outputs_list], "actual_maql": best.actual_maql, + "latency_breakdown": build_latency_breakdown(best.tool_call_events, best.reasoning_step_events), }, ) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/general_question.py b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/general_question.py index ce754c5ba..fabf2b419 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/general_question.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/general_question.py @@ -4,7 +4,7 @@ from gooddata_eval.core.evaluators._llm_judge import LLMJudge from gooddata_eval.core.evaluators._text_utils import extract_text from gooddata_eval.core.evaluators.base import ItemEvaluation -from gooddata_eval.core.models import ChatResult, DatasetItem +from gooddata_eval.core.models import ChatResult, DatasetItem, build_latency_breakdown _EVALUATION_STEPS = [ "Read the INPUT (the user's question) and the EXPECTED OUTPUT (a description of what a correct answer must contain).", @@ -30,5 +30,11 @@ def evaluate(self, item: DatasetItem, chat_result: ChatResult) -> ItemEvaluation return ItemEvaluation( passed=passed, rank_key=(int(passed),), - detail={"judge_reasoning": reasoning, "actual_output": actual}, + detail={ + "judge_reasoning": reasoning, + "actual_output": actual, + "latency_breakdown": build_latency_breakdown( + chat_result.tool_call_events, chat_result.reasoning_step_events + ), + }, ) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/guardrail.py b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/guardrail.py index 47a48718e..2e9dc0cb2 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/guardrail.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/guardrail.py @@ -4,7 +4,7 @@ from gooddata_eval.core.evaluators._llm_judge import LLMJudge from gooddata_eval.core.evaluators._text_utils import extract_text from gooddata_eval.core.evaluators.base import ItemEvaluation -from gooddata_eval.core.models import ChatResult, DatasetItem +from gooddata_eval.core.models import ChatResult, DatasetItem, build_latency_breakdown _EVALUATION_STEPS = [ "Read the INPUT (the user's message) and the EXPECTED OUTPUT (a description of how the agent should refuse or redirect).", @@ -29,7 +29,13 @@ def evaluate(self, item: DatasetItem, chat_result: ChatResult) -> ItemEvaluation passed=False, rank_key=(False,), # no_visualization=False → quality_score=0 (correctly bad) - detail={"no_visualization": False, "judge_reasoning": "visualization produced — auto-fail"}, + detail={ + "no_visualization": False, + "judge_reasoning": "visualization produced — auto-fail", + "latency_breakdown": build_latency_breakdown( + chat_result.tool_call_events, chat_result.reasoning_step_events + ), + }, ) actual = extract_text(chat_result) @@ -48,5 +54,8 @@ def evaluate(self, item: DatasetItem, chat_result: ChatResult) -> ItemEvaluation "judge_passed": passed, "judge_reasoning": reasoning, "actual_output": actual, + "latency_breakdown": build_latency_breakdown( + chat_result.tool_call_events, chat_result.reasoning_step_events + ), }, ) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/search_tool.py b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/search_tool.py index c28ee4ab5..fe30d4a04 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/evaluators/search_tool.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/search_tool.py @@ -2,7 +2,7 @@ """Evaluator for search_tool: agent must call the catalog search with expected parameters.""" from gooddata_eval.core.evaluators.base import ItemEvaluation -from gooddata_eval.core.models import ChatResult, DatasetItem +from gooddata_eval.core.models import ChatResult, DatasetItem, build_latency_breakdown def _normalize_str_list(value: object, *, lowercase: bool = False) -> list[str]: @@ -55,5 +55,8 @@ def evaluate(self, item: DatasetItem, chat_result: ChatResult) -> ItemEvaluation "tool_correctness": tool_correctness, "expected_function": expected_fn, "calls_found": len(matching_events), + "latency_breakdown": build_latency_breakdown( + chat_result.tool_call_events, chat_result.reasoning_step_events + ), }, ) diff --git a/packages/gooddata-eval/tests/test_agentic_alert_skill.py b/packages/gooddata-eval/tests/test_agentic_alert_skill.py index 27ef11b5f..f6a184809 100644 --- a/packages/gooddata-eval/tests/test_agentic_alert_skill.py +++ b/packages/gooddata-eval/tests/test_agentic_alert_skill.py @@ -678,6 +678,7 @@ def test_evaluate_agentic_alert_skill_returns_reasoning_steps_on_pass(): "metric_correct": True, "recipients_correct": True, "actual_alert_arguments": {"operator": "GREATER_THAN", "threshold": 500}, + "latency_breakdown": [], } @@ -718,4 +719,5 @@ def test_evaluate_agentic_alert_skill_attaches_reasoning_steps_to_exception_on_f "metric_correct": False, "recipients_correct": False, "actual_alert_arguments": {}, + "latency_breakdown": [], } diff --git a/packages/gooddata-eval/tests/test_agentic_conversation.py b/packages/gooddata-eval/tests/test_agentic_conversation.py index 8994bf9ae..f28deb124 100644 --- a/packages/gooddata-eval/tests/test_agentic_conversation.py +++ b/packages/gooddata-eval/tests/test_agentic_conversation.py @@ -17,6 +17,9 @@ def _skills_tc(*skills): tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "set_skills" tc.parsed_arguments = lambda: {"skills": list(skills)} return tc @@ -24,6 +27,9 @@ def _skills_tc(*skills): def _create_metric_tc(metric_id): tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "create_metric" tc.result = "{}" # truthy so cleanup collection processes it; content comes from parsed_result tc.parsed_result = lambda mid=metric_id: {"data": {"metric_id": mid, "maql": "SELECT 1"}} @@ -32,6 +38,9 @@ def _create_metric_tc(metric_id): def _create_metric_tc_error(message): tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "create_metric" tc.result = "{}" # truthy; content comes from parsed_result tc.parsed_result = lambda msg=message: {"data": {"isError": True, "error": {"text": msg}}} @@ -43,6 +52,8 @@ def _metric_turn_result(tool_calls): r.text_response = "done" r.created_visualizations = None r.tool_call_events = tool_calls + r.reasoning_step_events = [] + r.turn_wall_clock_sec = None return r @@ -100,12 +111,17 @@ def test_run_agentic_conversation_single_turn(): mock_client = MagicMock() mock_client.create_conversation.return_value = "conv-1" tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "set_skills" tc.parsed_arguments = lambda: {"skills": ["visualization"]} mock_chat_result = MagicMock() mock_chat_result.text_response = "Here is your visualization" mock_chat_result.created_visualizations = [MagicMock()] mock_chat_result.tool_call_events = [tc] + mock_chat_result.reasoning_step_events = [] + mock_chat_result.turn_wall_clock_sec = None mock_client.send_message.return_value = mock_chat_result fixture = ConversationFixture( @@ -139,9 +155,14 @@ def test_run_agentic_conversation_uses_initial_conversation_id(): mock_chat_result.text_response = "Here is your visualization" mock_chat_result.created_visualizations = [MagicMock()] tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "set_skills" tc.parsed_arguments = lambda: {"skills": ["visualization"]} mock_chat_result.tool_call_events = [tc] + mock_chat_result.reasoning_step_events = [] + mock_chat_result.turn_wall_clock_sec = None mock_client.send_message.return_value = mock_chat_result fixture = ConversationFixture( @@ -176,9 +197,14 @@ def test_run_agentic_conversation_creates_and_deletes_conversation(): mock_chat_result.text_response = "Here is your visualization" mock_chat_result.created_visualizations = [MagicMock()] tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "set_skills" tc.parsed_arguments = lambda: {"skills": ["visualization"]} mock_chat_result.tool_call_events = [tc] + mock_chat_result.reasoning_step_events = [] + mock_chat_result.turn_wall_clock_sec = None mock_client.send_message.return_value = mock_chat_result fixture = ConversationFixture( @@ -369,6 +395,8 @@ def _viz_turn_result(text=None, viz=None, tool_calls=()): r.text_response = text r.created_visualizations = viz r.tool_call_events = list(tool_calls) + r.reasoning_step_events = [] + r.turn_wall_clock_sec = None r.alert_proposals = [] return r @@ -524,6 +552,9 @@ def test_run_agentic_conversation_accumulates_reasoning_steps_across_turns(): mock_client = MagicMock() mock_client.create_conversation.return_value = "conv-1" tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "set_skills" tc.parsed_arguments = lambda: {"skills": ["visualization"]} @@ -531,12 +562,16 @@ def test_run_agentic_conversation_accumulates_reasoning_steps_across_turns(): turn1_result.text_response = "Here is your visualization" turn1_result.created_visualizations = [MagicMock()] turn1_result.tool_call_events = [tc] + turn1_result.reasoning_step_events = [] + turn1_result.turn_wall_clock_sec = None turn1_result.reasoning_steps = ["turn one reasoning"] turn2_result = MagicMock() turn2_result.text_response = "Here is another visualization" turn2_result.created_visualizations = [MagicMock()] turn2_result.tool_call_events = [tc] + turn2_result.reasoning_step_events = [] + turn2_result.turn_wall_clock_sec = None turn2_result.reasoning_steps = ["turn two reasoning"] mock_client.send_message.side_effect = [turn1_result, turn2_result] @@ -574,12 +609,17 @@ def test_evaluate_agentic_conversation_returns_reasoning_steps_on_pass(): mock_client = MagicMock() mock_client.create_conversation.return_value = "conv-1" tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "set_skills" tc.parsed_arguments = lambda: {"skills": ["visualization"]} chat_result = MagicMock() chat_result.text_response = "Here is your visualization" chat_result.created_visualizations = [MagicMock()] chat_result.tool_call_events = [tc] + chat_result.reasoning_step_events = [] + chat_result.turn_wall_clock_sec = None chat_result.reasoning_steps = ["thinking about it"] chat_result.response_id = "resp-1" mock_client.send_message.return_value = chat_result @@ -619,6 +659,7 @@ def test_evaluate_agentic_conversation_returns_reasoning_steps_on_pass(): "activated_skills": ["visualization"], } ], + "latency_breakdown": [], } @@ -626,12 +667,17 @@ def test_evaluate_agentic_conversation_attaches_reasoning_steps_to_exception_on_ mock_client = MagicMock() mock_client.create_conversation.return_value = "conv-1" tc = MagicMock(spec=ToolCallEvent) + tc.call_ts = None + tc.result_ts = None + tc.index = None tc.function_name = "set_skills" tc.parsed_arguments = lambda: {"skills": ["other_skill"]} chat_result = MagicMock() chat_result.text_response = "Here is something else" chat_result.created_visualizations = None chat_result.tool_call_events = [tc] + chat_result.reasoning_step_events = [] + chat_result.turn_wall_clock_sec = None chat_result.alert_proposals = [] chat_result.reasoning_steps = ["confused thinking"] chat_result.response_id = "resp-2" @@ -676,4 +722,5 @@ def test_evaluate_agentic_conversation_attaches_reasoning_steps_to_exception_on_ "activated_skills": ["other_skill"], } ], + "latency_breakdown": [], } diff --git a/packages/gooddata-eval/tests/test_agentic_guardrail.py b/packages/gooddata-eval/tests/test_agentic_guardrail.py index 6ec5205a9..4897d3e77 100644 --- a/packages/gooddata-eval/tests/test_agentic_guardrail.py +++ b/packages/gooddata-eval/tests/test_agentic_guardrail.py @@ -167,6 +167,7 @@ def test_evaluate_agentic_guardrail_returns_reasoning_steps_on_pass(): "judge_passed": True, "judge_reasoning": "Correctly refused", "actual_output": "I cannot help with that", + "latency_breakdown": [], } @@ -205,4 +206,5 @@ def test_evaluate_agentic_guardrail_attaches_reasoning_steps_to_exception_on_fai "judge_passed": False, "judge_reasoning": "Should have refused", "actual_output": "Sure, here is how to do it", + "latency_breakdown": [], } diff --git a/packages/gooddata-eval/tests/test_agentic_metric_skill.py b/packages/gooddata-eval/tests/test_agentic_metric_skill.py index 54461357e..99a694d41 100644 --- a/packages/gooddata-eval/tests/test_agentic_metric_skill.py +++ b/packages/gooddata-eval/tests/test_agentic_metric_skill.py @@ -527,6 +527,7 @@ def test_evaluate_agentic_metric_skill_returns_reasoning_steps_on_pass(): "maql_correct": True, "expected_maql_candidates": ["SELECT {metric/foo}"], "actual_maql": "SELECT {metric/foo}", + "latency_breakdown": [], } @@ -559,6 +560,7 @@ def test_evaluate_agentic_metric_skill_attaches_reasoning_steps_to_exception_on_ "maql_correct": False, "expected_maql_candidates": ["SELECT {metric/foo}"], "actual_maql": "", + "latency_breakdown": [], } assert exc_info.value.conversation_id == "conv-1" assert exc_info.value.response_id is None From 1bc4a38ec392ca7a59ba054c927d1ad788d4d85b Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 17:51:45 +0200 Subject: [PATCH 09/11] TEMP debug: log toolCall/toolResult callId matching (will revert) --- .../gooddata-eval/src/gooddata_eval/core/chat/sse_client.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py index cb18d3804..7341e55de 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py @@ -173,6 +173,8 @@ def _handle_reasoning(content: dict[str, Any], acc: _SseAccumulator) -> None: def _handle_tool_call(content: dict[str, Any], acc: _SseAccumulator) -> None: call_id = content.get("callId", "") idx = len(acc.tool_call_events) + import sys as _sys + print(f"[DEBUG toolCall] idx={idx} callId={call_id!r} name={content.get('name')!r} already_seen={call_id in acc.call_id_to_event_index}", file=_sys.stderr) acc.call_id_to_event_index[call_id] = idx acc.tool_call_events.append( { @@ -194,6 +196,8 @@ def _handle_tool_call(content: dict[str, Any], acc: _SseAccumulator) -> None: def _handle_tool_result(content: dict[str, Any], acc: _SseAccumulator) -> None: call_id = content.get("callId", "") idx = acc.call_id_to_event_index.get(call_id) + import sys as _sys + print(f"[DEBUG toolResult] callId={call_id!r} matched_idx={idx}", file=_sys.stderr) if idx is not None: acc.tool_call_events[idx]["result"] = content.get("result", "") acc.tool_call_events[idx]["result_ts"] = round(time.monotonic() - acc.t0, 3) From 13ed3c8b6862d482ab79be8304f839bb97c54e99 Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 21:34:26 +0200 Subject: [PATCH 10/11] Revert "TEMP debug: log toolCall/toolResult callId matching (will revert)" This reverts commit 1bc4a38ec392ca7a59ba054c927d1ad788d4d85b. --- .../gooddata-eval/src/gooddata_eval/core/chat/sse_client.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py index 7341e55de..cb18d3804 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py @@ -173,8 +173,6 @@ def _handle_reasoning(content: dict[str, Any], acc: _SseAccumulator) -> None: def _handle_tool_call(content: dict[str, Any], acc: _SseAccumulator) -> None: call_id = content.get("callId", "") idx = len(acc.tool_call_events) - import sys as _sys - print(f"[DEBUG toolCall] idx={idx} callId={call_id!r} name={content.get('name')!r} already_seen={call_id in acc.call_id_to_event_index}", file=_sys.stderr) acc.call_id_to_event_index[call_id] = idx acc.tool_call_events.append( { @@ -196,8 +194,6 @@ def _handle_tool_call(content: dict[str, Any], acc: _SseAccumulator) -> None: def _handle_tool_result(content: dict[str, Any], acc: _SseAccumulator) -> None: call_id = content.get("callId", "") idx = acc.call_id_to_event_index.get(call_id) - import sys as _sys - print(f"[DEBUG toolResult] callId={call_id!r} matched_idx={idx}", file=_sys.stderr) if idx is not None: acc.tool_call_events[idx]["result"] = content.get("result", "") acc.tool_call_events[idx]["result_ts"] = round(time.monotonic() - acc.t0, 3) From 595c98cfc76b1bcda0a895040b06d1572189489b Mon Sep 17 00:00:00 2001 From: Peter Tomko Date: Mon, 24 Aug 2026 22:23:37 +0200 Subject: [PATCH 11/11] Fix ruff format check (CI was failing on 2 files) 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. --- packages/gooddata-eval/src/gooddata_eval/core/models.py | 4 +--- packages/gooddata-eval/tests/test_sse_client.py | 4 +--- 2 files changed, 2 insertions(+), 6 deletions(-) diff --git a/packages/gooddata-eval/src/gooddata_eval/core/models.py b/packages/gooddata-eval/src/gooddata_eval/core/models.py index 96c062142..185574bcd 100644 --- a/packages/gooddata-eval/src/gooddata_eval/core/models.py +++ b/packages/gooddata-eval/src/gooddata_eval/core/models.py @@ -175,9 +175,7 @@ def build_latency_breakdown( continue points.append((tc.call_ts, "tool_start", tc.function_name, tc.index)) points.append((tc.result_ts, "tool_end", tc.function_name, tc.index)) - points.extend( - (rs.ts, "reasoning", _reasoning_title(rs.summary), rs.index) for rs in reasoning_step_events or [] - ) + points.extend((rs.ts, "reasoning", _reasoning_title(rs.summary), rs.index) for rs in reasoning_step_events or []) points.sort(key=lambda p: p[0]) steps: list[dict] = [] diff --git a/packages/gooddata-eval/tests/test_sse_client.py b/packages/gooddata-eval/tests/test_sse_client.py index ae16b994b..5cc205dc5 100644 --- a/packages/gooddata-eval/tests/test_sse_client.py +++ b/packages/gooddata-eval/tests/test_sse_client.py @@ -141,9 +141,7 @@ def test_build_latency_breakdown_uses_bold_title_as_reasoning_name(): ), ] reasoning_events = [ - ReasoningStepEvent( - summary="**Picking the right metric**\n\nLots more detail follows here.", ts=2.5, index=0 - ) + ReasoningStepEvent(summary="**Picking the right metric**\n\nLots more detail follows here.", ts=2.5, index=0) ] result = build_latency_breakdown(tool_events, reasoning_events) reasoning_step = next(s for s in result if s["kind"] == "reasoning")