feat(gooddata-eval): run start/finish times, per-trace latency percentiles and a restyled HTML report

Dockerfile

@@ -17,7 +17,7 @@ COPY --from=uv /uv /usr/local/bin/uv
 ENV GOSU_VERSION=1.14
 RUN set -x \
   && apt-get update \
-  && apt-get install -y --no-install-recommends make curl gnupg \
+  && apt-get install -y --no-install-recommends make curl gnupg nodejs \
   && curl -sSLo /usr/local/bin/gosu "https://github.com/tianon/gosu/releases/download/$GOSU_VERSION/gosu-$(dpkg --print-architecture)" \
   && curl -sSLo /usr/local/bin/gosu.asc "https://github.com/tianon/gosu/releases/download/$GOSU_VERSION/gosu-$(dpkg --print-architecture).asc" \
   && export GNUPGHOME="$(mktemp -d)" \

packages/gooddata-eval/AGENTS.md

@@ -168,8 +168,11 @@ A gitignored `.env` at the repo root is the normal place for these; load it with
 **Adding an evaluator is a registry change, not a naming convention.** Single-shot kinds go
 into `_EAGER_EVALUATORS`, or `_LAZY_EVALUATOR_MODULES` plus `_LAZY_EVALUATOR_CLASSES`, in
 `core/evaluators/__init__.py`. Agentic kinds need the string added to `AGENTIC_TEST_KINDS`
-and a new branch in `_dispatch_agentic`. Test file naming follows the capability, but
-naming a test file correctly registers nothing.
+and a new branch in `_dispatch_agentic`, and must also be classified in `core/interaction.py`:
+add it to `SINGLE_TURN_AGENTIC_KINDS` (one chat message per run) or `MULTI_TURN_KINDS` (a
+simulated user or several turns). That decides which latency section its items land in;
+`test_every_agentic_kind_is_classified_on_purpose` fails until it is done. Test file naming
+follows the capability, but naming a test file correctly registers nothing.
 
 **Parallel-safety is a reviewed allowlist, and getting it wrong corrupts results.**
 `WORKSPACE_MUTATING_TEST_KINDS` is computed as `AGENTIC_TEST_KINDS - PARALLEL_SAFE_TEST_KINDS`,

packages/gooddata-eval/src/gooddata_eval/cli/agentic_runner.py

@@ -6,6 +6,7 @@
 import sys
 import time
 from concurrent.futures import ThreadPoolExecutor, as_completed
+from datetime import datetime, timezone
 from typing import Any, TypedDict
 
 from gooddata_eval.core.agentic._gate import DEFAULT_GATE, EvalGate, normalize_gate
@@ -28,6 +29,7 @@
 from gooddata_eval.core.evaluators.visualization import requires_execution_of
 from gooddata_eval.core.models import AgenticEvalOutcome, CreatedVisualization, DatasetItem
 from gooddata_eval.core.runner import EvalReport, ItemReport
+from gooddata_eval.core.timing import TraceRecorder
 
 
 class _LfKw(TypedDict, total=False):
@@ -375,6 +377,18 @@ def _apply_failed_runs(item_report: ItemReport, source: Any) -> None:
         item_report.failed_runs = list(failed_runs)
 
 
+def _apply_run_latencies(item_report: ItemReport, source: Any) -> None:
+    """Copy the per-run wall-clock times off an outcome or a failure, if the kind timed them.
+
+    Read from both like ``_apply_failed_runs``: a failing item reaches the report through the
+    exception. A kind that records none leaves the empty default, so the item adds no sample
+    to the latency distribution rather than a zero.
+    """
+    run_latencies = getattr(source, "run_latencies_s", None)
+    if run_latencies:
+        item_report.run_latencies_s = list(run_latencies)
+
+
 def _apply_timings(item_report: ItemReport, timings: Any) -> None:
     """Copy an outcome's phase breakdown onto the item report, if the kind recorded one.
 
@@ -429,6 +443,7 @@ def run_agentic_items(
     # latency. Drained below before this function returns, so every score is written
     # before the caller renders a report or decides an exit code.
     linker = BackgroundTraceLinker()
+    report.started_at = datetime.now(timezone.utc)
     _t0 = time.perf_counter()
 
     def _process_item(index: int, item: DatasetItem) -> ItemReport:
@@ -447,6 +462,10 @@ def _process_item(index: int, item: DatasetItem) -> ItemReport:
         # None, not False, for the kinds _dispatch_agentic passes no gate to: ItemReport.passed
         # then falls back to pass_at_k and gate_passed keeps meaning "a gate ran".
         gated = item.test_kind not in UNGATED_AGENTIC_TEST_KINDS
+        # Started in this worker, where the item runs, so a concurrent item cannot write into it.
+        # Every kind reaches the chat client the same way, which is why the per-trace latencies are
+        # collected here once rather than handed out by each evaluator.
+        traces = TraceRecorder()
         t0 = time.perf_counter()
         try:
             outcome = _dispatch_agentic(
@@ -482,6 +501,7 @@ def _process_item(index: int, item: DatasetItem) -> ItemReport:
             _apply_timings(item_report, getattr(outcome, "timings", None))
             _apply_run_counts(item_report, outcome)
             _apply_failed_runs(item_report, outcome)
+            _apply_run_latencies(item_report, outcome)
         except AssertionError as exc:
             item_report.gate_passed = False if gated else None
             item_report.runs = k
@@ -492,6 +512,7 @@ def _process_item(index: int, item: DatasetItem) -> ItemReport:
             _apply_timings(item_report, getattr(exc, "timings", None))
             _apply_run_counts(item_report, exc)
             _apply_failed_runs(item_report, exc)
+            _apply_run_latencies(item_report, exc)
             # Read off the counts, not off the gate: pass^K fails items where runs did pass,
             # and reporting those as pass_at_k False would contradict the Langfuse score of
             # the same name. Kinds that report no count read as 0, i.e. a clean failure.
@@ -512,6 +533,7 @@ def _process_item(index: int, item: DatasetItem) -> ItemReport:
             _apply_timings(item_report, getattr(exc, "timings", None))
             _apply_run_counts(item_report, exc)
             _apply_failed_runs(item_report, exc)
+            _apply_run_latencies(item_report, exc)
             # Every run ungraded, by definition of this error -- said explicitly rather than
             # left to _apply_run_counts, whose source is detail["unscored_runs"] and which a
             # kind that attaches no diagnostics would leave at 0.
@@ -525,8 +547,15 @@ def _process_item(index: int, item: DatasetItem) -> ItemReport:
             # judge broke should not also report the agent as costing 0s. Kinds that
             # attach no timings to the exception keep their 0.0 defaults.
             _apply_timings(item_report, getattr(exc, "timings", None))
+            # Phase timings stay, but the per-turn response times do not: this item reports no
+            # runs (and so no run latencies), and keeping its turns would put them in the
+            # response population with no attempt beside them. An item that completed 2 of 3
+            # runs and then raised would otherwise show up in the per-response table and not in
+            # the per-conversation one.
+            traces.discard()
         finally:
             item_report.latency_s = time.perf_counter() - t0
+            item_report.trace_latencies_s = traces.stop()
 
         if on_item_done is not None:
             try:
@@ -607,6 +636,7 @@ def _process_item(index: int, item: DatasetItem) -> ItemReport:
             flush=True,
         )
     report.wall_clock_s = time.perf_counter() - _t0
+    report.finished_at = datetime.now(timezone.utc)
 
     if langfuse is not None:
         try:

packages/gooddata-eval/src/gooddata_eval/cli/main.py

@@ -649,6 +649,10 @@ def on_langfuse_item_done(
                 report.items.extend(agentic_report.items)
             report.items.extend(single_report.items)
             report.wall_clock_s = (agentic_report.wall_clock_s if agentic_report else 0.0) + single_report.wall_clock_s
+            # The two phases run back to back, so the merged run spans the earliest start to the latest finish.
+            phases = [r for r in (agentic_report, single_report) if r is not None]
+            report.started_at = min((r.started_at for r in phases if r.started_at), default=None)
+            report.finished_at = max((r.finished_at for r in phases if r.finished_at), default=None)
 
             skipped_kinds = sorted({i.test_kind for i in report.items if i.skipped})
             if skipped_kinds:

packages/gooddata-eval/src/gooddata_eval/core/agentic/alert_skill.py

@@ -6,6 +6,7 @@
 import json
 import os
 import re
+import time
 from dataclasses import dataclass, field
 from typing import Any
 
@@ -587,6 +588,8 @@ class AlertRunResult:
     # also report operator/threshold/metric/recipients as False.
     exit_reason: LoopExit = LoopExit.BUDGET_EXHAUSTED
     turns_used: int = 0
+    # This run's own wall time, from just before its chat call to the end of its scoring.
+    run_latency_s: float = 0.0
 
 
 @dataclass
@@ -802,6 +805,7 @@ def _run_once(conv_id: str) -> AlertRunResult:
             # that simply runs out of range() is correctly labelled without a trailing else.
             exit_reason = LoopExit.BUDGET_EXHAUSTED
             turns_used = 0
+            run_started = time.monotonic()
             for _iteration in range(max_iterations):
                 turns_used = _iteration + 1
                 try:
@@ -903,6 +907,7 @@ def _run_once(conv_id: str) -> AlertRunResult:
                 reasoning_step_events=all_reasoning_step_events,
                 exit_reason=exit_reason,
                 turns_used=turns_used,
+                run_latency_s=time.monotonic() - run_started,
             )
         finally:
             if alert_id_to_delete:
@@ -1122,6 +1127,7 @@ def _write_scores(ctx: RunTraceContext) -> None:
         exc.runs_passed = runs_passed
         exc.runs_effective = runs_effective
         exc.failed_runs = failed_runs
+        exc.run_latencies_s = [r.run_latency_s for r in summary.run_results]
         raise exc
     return AgenticEvalOutcome(
         runs_passed=runs_passed,
@@ -1133,4 +1139,5 @@ def _write_scores(ctx: RunTraceContext) -> None:
         # Also on the success path: pass@K clears the gate with one passing run, so a
         # 1/3 item reports success while two of its runs failed for reasons worth reading.
         failed_runs=failed_runs,
+        run_latencies_s=[r.run_latency_s for r in summary.run_results],
     )

packages/gooddata-eval/src/gooddata_eval/core/agentic/anomaly_detection.py

@@ -28,6 +28,7 @@
 import logging
 import os
 import re
+import time
 from dataclasses import dataclass, field
 from typing import Any
 
@@ -284,6 +285,8 @@ class AnomalyRunResult:
     response_id: str | None = None
     tool_call_events: list[ToolCallEvent] = field(default_factory=list)
     reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list)
+    # This run's own wall time, from just before its chat call to the end of its scoring.
+    run_latency_s: float = 0.0
 
 
 @dataclass
@@ -393,6 +396,7 @@ def _accumulate(result: ChatResult) -> None:
             all_tool_call_events.extend(result.tool_call_events or [])
             all_reasoning_step_events.extend(result.reasoning_step_events or [])
 
+        run_started = time.monotonic()
         for iteration in range(max_iterations):
             try:
                 chat_result = client.send_message(conv_id, current_question)
@@ -440,6 +444,7 @@ def _accumulate(result: ChatResult) -> None:
             response_id=response_id,
             tool_call_events=all_tool_call_events,
             reasoning_step_events=all_reasoning_step_events,
+            run_latency_s=time.monotonic() - run_started,
         )
 
     try:
@@ -651,6 +656,7 @@ def _write_scores(ctx: RunTraceContext) -> None:
         exc.runs_passed = runs_passed
         exc.runs_effective = len(summary.run_results)
         exc.failed_runs = failed_runs
+        exc.run_latencies_s = [r.run_latency_s for r in summary.run_results]
         raise exc
 
     return AgenticEvalOutcome(
@@ -661,4 +667,5 @@ def _write_scores(ctx: RunTraceContext) -> None:
         response_id=best.response_id,
         detail=detail,
         failed_runs=failed_runs,
+        run_latencies_s=[r.run_latency_s for r in summary.run_results],
     )

packages/gooddata-eval/src/gooddata_eval/core/agentic/conversation.py

@@ -19,6 +19,7 @@
 import json
 import os
 import re
+import time
 from dataclasses import dataclass, field
 from datetime import date
 from typing import ClassVar, Literal
@@ -612,6 +613,9 @@ class ConversationResult:
     stalled_turns: int = 0
     mode: ConversationMode = "legacy"
     judge_model: str | None = None
+    # The whole conversation's wall time, from just before its first message to the end of its
+    # last turn's scoring; conversation create/delete is not part of it.
+    run_latency_s: float = 0.0
 
 
 def _metric_creations(tool_call_events: list[ToolCallEvent]) -> list[tuple[str, bool]]:
@@ -771,6 +775,7 @@ def run_agentic_conversation(
     tool_index_offset = 0
     reasoning_index_offset = 0
     current_context = user_context
+    run_latency_s = 0.0
 
     try:
         if initial_conversation_id is not None:
@@ -779,10 +784,14 @@ def run_agentic_conversation(
             conversation_id = client.create_conversation()
             owns_conversation = True
 
+        run_started = time.monotonic()
+        conversation_swap_s = 0.0  # fresh_conversation_per_turn's delete/create, which is not the run's work
         for turn_index, turn in enumerate(fixture.turns):
             if fresh_conversation_per_turn and turn_index > 0:
+                swap_started = time.monotonic()
                 client.delete_conversation(conversation_id)
                 conversation_id = client.create_conversation()
+                conversation_swap_s += time.monotonic() - swap_started
                 transcript = []
                 active_skills = set()
             # Before the skip below: a turn whose expectation cannot resolve still changed what
@@ -1006,6 +1015,8 @@ def run_agentic_conversation(
                 )
             )
 
+        # Taken here, not after the finally: its cleanup is not part of the run.
+        run_latency_s = time.monotonic() - run_started - conversation_swap_s
     finally:
         if owns_conversation and conversation_id:
             client.delete_conversation(conversation_id)
@@ -1039,6 +1050,7 @@ def run_agentic_conversation(
         stalled_turns=stalled,
         mode=resolved_mode,
         judge_model=judge.model_name if judged else None,
+        run_latency_s=run_latency_s,
     )
 
 
@@ -1246,6 +1258,7 @@ def _write_scores(ctx: RunTraceContext) -> None:
         # for. Saying so explicitly stops the report claiming K runs that never happened.
         exc.runs_passed = 0
         exc.runs_effective = 1
+        exc.run_latencies_s = [result.run_latency_s]
         raise exc
     return AgenticEvalOutcome(
         reasoning_steps=result.reasoning_steps,
@@ -1254,4 +1267,5 @@ def _write_scores(ctx: RunTraceContext) -> None:
         detail=detail,
         runs_passed=1,
         runs_effective=1,
+        run_latencies_s=[result.run_latency_s],
     )

packages/gooddata-eval/src/gooddata_eval/core/agentic/dashboard_skill.py

@@ -1167,6 +1167,8 @@ class DashboardRunResult:
     tool_call_events: list[ToolCallEvent] = field(default_factory=list)
     reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list)
     timings: PhaseTimings = field(default_factory=PhaseTimings)
+    # This run's own wall time, from just before its chat call to the end of its scoring.
+    run_latency_s: float = 0.0
 
 
 @dataclass
@@ -1399,6 +1401,7 @@ def _execute_single_dashboard_run(
     tool_index_offset = 0
     reasoning_index_offset = 0
 
+    run_started = time.monotonic()
     for iteration in range(max_iterations):
         turns += 1
         agent_started = time.monotonic()
@@ -1475,6 +1478,7 @@ def _execute_single_dashboard_run(
         tool_call_events=all_tool_call_events,
         reasoning_step_events=all_reasoning_step_events,
         timings=timings,
+        run_latency_s=time.monotonic() - run_started,
     )
 
 
@@ -1703,6 +1707,7 @@ def _write_scores(ctx: RunTraceContext) -> None:
         exc.runs_passed = runs_passed
         exc.runs_effective = runs_effective
         exc.failed_runs = failed_runs
+        exc.run_latencies_s = [r.run_latency_s for r in summary.run_results]
         raise exc
     return AgenticEvalOutcome(
         runs_passed=runs_passed,
@@ -1713,4 +1718,5 @@ def _write_scores(ctx: RunTraceContext) -> None:
         detail=detail,
         timings=item_timings,
         failed_runs=failed_runs,
+        run_latencies_s=[r.run_latency_s for r in summary.run_results],
     )

packages/gooddata-eval/src/gooddata_eval/core/agentic/document_skill.py

@@ -638,6 +638,8 @@ class DocumentRunResult:
     tool_call_events: list[ToolCallEvent] = field(default_factory=list)
     reasoning_step_events: list[ReasoningStepEvent] = field(default_factory=list)
     timings: PhaseTimings = field(default_factory=PhaseTimings)
+    # This run's own wall time, from just before its chat call to the end of its scoring.
+    run_latency_s: float = 0.0
 
     @property
     def diagnostics(self) -> dict[str, bool]:
@@ -711,6 +713,7 @@ def _execute_single_document_run(
     reasoning_index_offset = 0
     first_turn_asked = False
 
+    run_started = time.monotonic()
     for iteration in range(max_iterations):
         turns += 1
         agent_started = time.monotonic()
@@ -781,6 +784,7 @@ def _execute_single_document_run(
         tool_call_events=all_tool_call_events,
         reasoning_step_events=all_reasoning_step_events,
         timings=timings,
+        run_latency_s=time.monotonic() - run_started,
     )
 
 
@@ -980,6 +984,7 @@ def _write_scores(ctx: RunTraceContext) -> None:
             + " | ".join(unscored)
         )
         exc_judge.timings = item_timings
+        exc_judge.run_latencies_s = [r.run_latency_s for r in summary.run_results]
         raise exc_judge
 
     runs_passed = sum(1 for r in summary.run_results if r.evaluation.strict_pass)
@@ -1033,6 +1038,7 @@ def _run_detail(run: DocumentRunResult) -> dict[str, Any]:
         exc.runs_passed = runs_passed
         exc.runs_effective = runs_effective
         exc.failed_runs = failed_runs
+        exc.run_latencies_s = [r.run_latency_s for r in summary.run_results]
         raise exc
     return AgenticEvalOutcome(
         runs_passed=runs_passed,
@@ -1043,4 +1049,5 @@ def _run_detail(run: DocumentRunResult) -> dict[str, Any]:
         detail=detail,
         timings=item_timings,
         failed_runs=failed_runs,
+        run_latencies_s=[r.run_latency_s for r in summary.run_results],
     )