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/agentic/visualization.py b/packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py index 3edd22a1a..486214cce 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 +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 @@ -37,6 +43,8 @@ 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) + reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list) @dataclass @@ -161,8 +169,12 @@ 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 + 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) @@ -170,9 +182,23 @@ 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 + 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 + 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: @@ -201,6 +227,8 @@ def _execute_single_run( total_steps=total_steps, reasoning_steps=reasoning_steps, response_id=response_id, + tool_call_events=all_tool_call_events, + reasoning_step_events=all_reasoning_step_events, ) @@ -434,12 +462,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, best.reasoning_step_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, 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 3faba5bbd..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 @@ -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: @@ -160,17 +165,22 @@ 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), "index": len(acc.reasoning_steps)} + ) 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 @@ -186,6 +196,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: @@ -195,6 +206,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/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/src/gooddata_eval/core/evaluators/visualization.py b/packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py index 354b8a214..a6e197d34 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,10 @@ 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, 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 a536019f2..185574bcd 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 @@ -69,6 +70,17 @@ 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 + # 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: @@ -85,6 +97,109 @@ def parsed_result(self) -> dict[str, Any] | None: return None +class ReasoningStepEvent(BaseModel): + """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 +# 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_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, +) -> 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 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, 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, 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]) + + 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 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): """Subset of the agent chat response needed for Phase 1 evaluation.""" @@ -99,6 +214,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/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 0161cc3f8..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 @@ -111,19 +116,26 @@ 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 + best_run_latency: float | 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 + best_run_latency = latency if evaluation.passed: report.pass_at_k = True if on_run_done is not None: @@ -134,10 +146,16 @@ 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_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 diff --git a/packages/gooddata-eval/tests/test_agentic_visualization.py b/packages/gooddata-eval/tests/test_agentic_visualization.py index 80a558202..766313d74 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": [], } diff --git a/packages/gooddata-eval/tests/test_runner.py b/packages/gooddata-eval/tests/test_runner.py index 925c214a6..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 @@ -277,6 +278,58 @@ 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_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`).""" diff --git a/packages/gooddata-eval/tests/test_sse_client.py b/packages/gooddata-eval/tests/test_sse_client.py index be44b304d..5cc205dc5 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, ReasoningStepEvent, ToolCallEvent, build_latency_breakdown def test_parse_sse_lines_collects_text_and_visualization(fixtures_dir): @@ -63,6 +63,179 @@ 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 + assert tc.index == 0 + + +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, 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}, + ] + + +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, 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 == [ + {"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_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, index=0), + ToolCallEvent( + function_name="create_metric_alert", function_arguments="{}", call_ts=5.0, result_ts=6.0, index=1 + ), + ] + reasoning_events = [ + 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") + assert reasoning_step["name"] == "Picking the right metric" + assert "Lots more detail" not in reasoning_step["name"] + + +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 via "index" even though "name" repeats. + tool_events = [ + 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) + 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_names(): + tool_events = [ + 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) + 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_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 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, 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 == [ + {"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(): + 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 @@ -208,6 +381,18 @@ 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] + assert [e.index for e in result.reasoning_step_events] == [0, 1] + + def test_parse_sse_lines_prefers_multipart_viz_over_adhoc_fallback(): """Real multipart visualization takes priority over adhoc tool call stash.""" @@ -351,7 +536,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 +549,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 +564,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")