From f23e0f09d83de04c8528c44ba56d6c9dafe390c6 Mon Sep 17 00:00:00 2001 From: tmatup <51425734+tmatup@users.noreply.github.com> Date: Fri, 2 Oct 2026 20:18:01 +0000 Subject: [PATCH] feat(reports): report agent wall and grading separately from end-to-end latency MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `duration` (the run.md Latency column and the evalboard Duration column) is end-to-end: setup + the agent's turns + grading. A checker that runs a live command (maestro-flow `flow debug`) adds 20-50 s per task, which read as agent time. task.json already measured setup_ms and grading_ms; run.json dropped them. - run.json rows gain agent_wall_ms (sum of positive iteration durations, computed once in result_metrics.agent_wall_ms), setup_ms and grading_ms. Additive only; existing keys are unchanged. - run.md: Latency is labeled end-to-end; Task Details gains Agent Wall and Grading columns; Generation Metrics gains Agent Wall; Summary gains Avg Agent Wall and Avg Grading. Older run.json rows derive agent wall from iterations and show grading as N/A. - HTML report: Agent Wall / Setup / Grading stats beside the end-to-end total. - evalboard grid: Duration becomes End-to-end, with new Agent and Grading columns (sortable, tooltips, mobile card). agentSecondsFromRaw prefers the stored agent_wall_ms. Fixes #212 ๐Ÿค– Generated with Claude Code Co-Authored-By: [Claude](mailto:noreply@anthropic.com) Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016sCMS4Kv57eDUxpmW24z9e --- docs/REPORT_SCHEMA.md | 24 ++++++- .../runs/[id]/__tests__/task-grid.test.tsx | 60 ++++++++++++++-- evalboard/app/runs/[id]/task-grid.tsx | 40 +++++++++-- evalboard/lib/__tests__/runs.test.ts | 34 +++++++++ evalboard/lib/runs.ts | 18 +++++ src/coder_eval/reports/html.py | 27 +++++++- src/coder_eval/reports/markdown.py | 60 ++++++++++++++-- src/coder_eval/result_metrics.py | 24 +++++++ src/coder_eval/run_record.py | 8 ++- tests/_fixtures/report_snapshots/run_full.md | 19 ++--- .../_fixtures/report_snapshots/run_minimal.md | 4 +- tests/test_reports.py | 69 +++++++++++++++++-- tests/test_run_record.py | 30 ++++++++ 13 files changed, 379 insertions(+), 38 deletions(-) diff --git a/docs/REPORT_SCHEMA.md b/docs/REPORT_SCHEMA.md index f0fb59e16..ee11708fa 100644 --- a/docs/REPORT_SCHEMA.md +++ b/docs/REPORT_SCHEMA.md @@ -75,7 +75,10 @@ publishing different numbers for the same run. Each entry is an **untyped dict** (a denormalization, not a Pydantic model) with keys including: `task_id`, `replicate_index`, `variant_id`, `status` -([`FinalStatus`](#finalstatus)), `weighted_score`, `duration`, `iteration_count`, +([`FinalStatus`](#finalstatus)), `weighted_score`, `duration` (END-TO-END seconds: +setup + the agent's turns + grading), the timing split (`agent_wall_ms`, `setup_ms`, +`grading_ms` โ€” see [Agent wall vs end-to-end](#agent-wall-vs-end-to-end)), the four +turn buckets (`startup_ms`, `generation_ms`, `tool_ms`, `teardown_ms`), `iteration_count`, `tags`, `task_path`, `model_used`, `reference_similarity`, the token buckets (`input_tokens` = uncached input, `output_tokens`, `cache_creation_input_tokens`, `cache_read_input_tokens`, `total_tokens`), the cost fields @@ -89,6 +92,25 @@ including: `task_id`, `replicate_index`, `variant_id`, `status` turn digest (`{iteration, duration_seconds, command_count, assistant_turn_count, crashed, crash_reason}`) โ€” the full transcript is in `task.json`. +### Agent wall vs end-to-end + +`duration` is the task's whole wall clock. It includes `setup_ms` (sandbox, agent +start, `pre_run`) and `grading_ms` (every success check). A checker that runs a live +command can spend tens of seconds there, so `duration` is not the agent's time. + +| Key | Type | Meaning | +| --- | --- | --- | +| `agent_wall_ms` | `float \| None` | Sum of the positive `iterations[].duration_seconds`, in ms. The agent's own turns. `None` when no turn was timed. | +| `setup_ms` | `float \| None` | Copied from `task.json`. | +| `grading_ms` | `float \| None` | Copied from `task.json`. `None` on an ungraded row (`coder-eval execute`) and on a detached grade. | + +Example (calculator, one run): `duration` 101.3 s = `agent_wall_ms` 55,657 + +`setup_ms` 13,678 + `grading_ms` 27,657 + about 4 s not in a named phase. + +A `run.json` written before these keys existed has none of them. Readers derive +agent wall from the row's `iterations[].duration_seconds` with the same rule, and show +grading as unknown, never `0`. + ### Missing cost is never fatal Pricing degrades; the evaluation does not. A model absent from the rate card, a turn diff --git a/evalboard/app/runs/[id]/__tests__/task-grid.test.tsx b/evalboard/app/runs/[id]/__tests__/task-grid.test.tsx index 27953ed3f..0ad892021 100644 --- a/evalboard/app/runs/[id]/__tests__/task-grid.test.tsx +++ b/evalboard/app/runs/[id]/__tests__/task-grid.test.tsx @@ -52,10 +52,12 @@ function cellFor(taskId: string, index: number): HTMLElement { return cells[index]!; } -// Layout: Task, Status, Score, Duration, vs Exp, Cost, Turns, then the tokens +// Layout: Task, Status, Score, End-to-end, Agent, Grading, vs Exp, Cost, Turns, then the tokens const durationCellFor = (taskId: string) => cellFor(taskId, 3); -const vsExpCellFor = (taskId: string) => cellFor(taskId, 4); -const turnsCellFor = (taskId: string) => cellFor(taskId, 6); +const agentCellFor = (taskId: string) => cellFor(taskId, 4); +const gradingCellFor = (taskId: string) => cellFor(taskId, 5); +const vsExpCellFor = (taskId: string) => cellFor(taskId, 6); +const turnsCellFor = (taskId: string) => cellFor(taskId, 8); describe("TaskGrid โ€” mature rows", () => { test("opens a popover linking to the run where it last executed", () => { @@ -195,7 +197,7 @@ describe("TaskGrid โ€” vs Expected column", () => { .slice(1) .map((tr) => within(tr).getAllByRole("cell")[0].textContent); - fireEvent.click(screen.getByRole("button", { name: /^Duration$/ })); + fireEvent.click(screen.getByRole("button", { name: /^End-to-end$/ })); expect(order()[0]).toMatch(/long/i); fireEvent.click(screen.getByRole("button", { name: /^vs Expected$/ })); @@ -262,7 +264,9 @@ describe("TaskGrid โ€” Turns column", () => { "Task", "Status", "Score", - "Duration", + "End-to-end", + "Agent", + "Grading", "vs Expected", "Cost", "Turns", @@ -273,7 +277,9 @@ describe("TaskGrid โ€” Turns column", () => { "Task", "Status", "Score", - "Duration", + "End-to-end", + "Agent", + "Grading", "vs Expected", "Cost", "Turns", @@ -300,7 +306,15 @@ describe("TaskGrid โ€” column tooltips", () => { ); expect(header("vs Expected")).toHaveAttribute( "title", - expect.stringContaining("Duration รท"), + expect.stringContaining("End-to-end รท"), + ); + expect(header("End-to-end")).toHaveAttribute( + "title", + expect.stringContaining("+ grading"), + ); + expect(header("Agent")).toHaveAttribute( + "title", + expect.stringContaining("Excludes sandbox setup"), ); expect(header("Turns")).toHaveAttribute( "title", @@ -595,3 +609,35 @@ describe("TaskGrid โ€” default ordering keeps a task's arms together", () => { expect(order[2]).toMatch(/zzz/i); }); }); + +describe("TaskGrid โ€” end-to-end vs agent vs grading (#212)", () => { + test("splits a slow checker out of the agent's time", () => { + render( + , + ); + expect(durationCellFor("calc")).toHaveTextContent("1m41s"); + expect(agentCellFor("calc")).toHaveTextContent("55.7s"); + expect(gradingCellFor("calc")).toHaveTextContent("27.7s"); + }); + + test("an unmeasured grading time renders as a dash, never 0", () => { + render( + , + ); + expect(gradingCellFor("old")).toHaveTextContent("โ€”"); + }); +}); diff --git a/evalboard/app/runs/[id]/task-grid.tsx b/evalboard/app/runs/[id]/task-grid.tsx index 6d3fb7b99..ab773a82e 100644 --- a/evalboard/app/runs/[id]/task-grid.tsx +++ b/evalboard/app/runs/[id]/task-grid.tsx @@ -41,6 +41,8 @@ type SortKey = | "status" | "score" | "duration" + | "agent" + | "grading" | "vsExp" | "cost" | "turns" @@ -54,7 +56,10 @@ type SortKey = const COLUMN_HELP: Partial> = { ...TOKEN_COLUMN_HELP, turns: "Visible turns: one per tool call plus one for the final reply. Tinted against the task's hand-written expected_turns budget (yellow past 1.25ร—, red past 1.5ร—); untinted when the task declares none.", - vsExp: "Duration รท the time this task is expected to need. The expected time is derived per task, per harness by the eval runner (its fastest passing run, or p10 once there are ten) and stamped into the run โ€” never hand-written. Past 2ร— counts as slow; a task its harness has never passed shows โ€”.", + vsExp: "End-to-end รท the time this task is expected to need. The expected time is derived per task, per harness by the eval runner (its fastest passing run, or p10 once there are ten) and stamped into the run โ€” never hand-written. Past 2ร— counts as slow; a task its harness has never passed shows โ€”.", + duration: "End-to-end wall clock for this task: sandbox setup + the agent's turns + grading. A checker that runs a live command can add tens of seconds here, so this is not the agent's time โ€” see Agent.", + agent: "Agent wall clock: the agent's turns, summed. Excludes sandbox setup, pre_run and grading.", + grading: "Time spent checking success criteria (run.json grading_ms). โ€” when the run did not record it.", cost: "Total billed cost for this task, reported by the SDK (summed across turns).", variant: "Experiment arm this row was produced by. A run declaring `variants:` executes every task once per arm and keeps each arm's output in its own subtree, so the same task appears once per arm and the two rows are separate measurements โ€” never collapsed together.", }; @@ -302,6 +307,8 @@ const DEFAULT_DIR: Record = { status: "asc", score: "desc", duration: "desc", + agent: "desc", + grading: "desc", vsExp: "desc", cost: "desc", turns: "desc", @@ -347,6 +354,15 @@ function compare( (a.durationSeconds ?? -Infinity) - (b.durationSeconds ?? -Infinity) ); + case "agent": + return ( + (a.agentSeconds ?? -Infinity) - (b.agentSeconds ?? -Infinity) + ); + case "grading": + return ( + (a.gradingSeconds ?? -Infinity) - + (b.gradingSeconds ?? -Infinity) + ); case "vsExp": return ( (timeRatio(a.durationSeconds, a.expectedSeconds) ?? -Infinity) - @@ -390,7 +406,9 @@ const COLUMNS: Array<{ { key: "variant", header: "Variant" }, { key: "status", header: "Status" }, { key: "score", header: "Score", align: "right" }, - { key: "duration", header: "Duration", align: "right" }, + { key: "duration", header: "End-to-end", align: "right" }, + { key: "agent", header: "Agent", align: "right" }, + { key: "grading", header: "Grading", align: "right" }, { key: "vsExp", header: "vs Expected", align: "right" }, { key: "cost", header: "Cost", align: "right" }, { key: "turns", header: "Turns", align: "right" }, @@ -804,6 +822,12 @@ export function TaskGrid({ {fmtTableDuration(t.durationSeconds)} + + {fmtTableDuration(t.agentSeconds ?? null)} + + + {fmtTableDuration(t.gradingSeconds ?? null)} + -
+
+ + { agentSecondsFromRaw({ iterations: [{ duration_seconds: null }] }), ).toBeNull(); }); + + test("prefers the stored agent_wall_ms over the iterations sum (#212)", () => { + expect( + agentSecondsFromRaw({ + duration: 101.25, + agent_wall_ms: 55657, + iterations: [{ duration_seconds: 1 }], + }), + ).toBeCloseTo(55.657, 6); + }); + + test("a stored null stays null rather than falling back", () => { + expect( + agentSecondsFromRaw({ + agent_wall_ms: null, + iterations: [{ duration_seconds: 5 }], + }), + ).toBeNull(); + }); +}); + +describe("toTaskRow grading split (#212)", () => { + test("carries grading_ms as seconds", () => { + expect( + toTaskRow({ task_id: "x", grading_ms: 27657 }).gradingSeconds, + ).toBeCloseTo(27.657, 6); + }); + + test("null on a run.json that predates the key, never 0", () => { + expect(toTaskRow({ task_id: "x" }).gradingSeconds).toBeNull(); + expect( + toTaskRow({ task_id: "x", grading_ms: null }).gradingSeconds, + ).toBeNull(); + }); }); describe("extractComponentShas", () => { diff --git a/evalboard/lib/runs.ts b/evalboard/lib/runs.ts index f93f7aab0..ccd27bdba 100644 --- a/evalboard/lib/runs.ts +++ b/evalboard/lib/runs.ts @@ -105,6 +105,9 @@ export interface TaskResultSummary { // The agent's turns alone, without setup and grading. Optional so test // factories that predate it stay valid. agentSeconds?: number | null; + // Time spent checking success criteria (run.json `grading_ms`). Null when + // not measured or on a run.json that predates the key โ€” never 0. + gradingSeconds?: number | null; totalCostUsd: number | null; actualCommands: number | null; totalTurns: number | null; @@ -505,8 +508,14 @@ export interface RawTaskResult { replicate_index?: number | null; status?: string; weighted_score?: number; + // END-TO-END seconds: setup + the agent's turns + grading. duration?: number; iterations?: { duration_seconds?: number | null }[] | null; + // The split of `duration` (#212). Absent on run.json written before it; + // null = not measured (grading_ms is null on an ungraded or detached grade). + agent_wall_ms?: number | null; + setup_ms?: number | null; + grading_ms?: number | null; total_cost_usd?: number; input_tokens?: number | null; output_tokens?: number | null; @@ -896,6 +905,8 @@ export function toTaskRow(t: RawTaskResult): TaskResultSummary { weightedScore: t.weighted_score ?? null, durationSeconds: t.duration ?? null, agentSeconds: agentSecondsFromRaw(t), + gradingSeconds: + typeof t.grading_ms === "number" ? t.grading_ms / 1000 : null, totalCostUsd: t.total_cost_usd ?? null, actualCommands: t.actual_commands ?? null, totalTurns: t.total_turns ?? null, @@ -1265,7 +1276,14 @@ function mostCommonAgentType(rows: RawTaskResult[]): string | null { return best; } +// Prefers the row's stored `agent_wall_ms` (written by the runner's +// result_metrics.agent_wall_ms with this same rule), so the board and run.md +// agree by construction. The iterations sum is the legacy path for a run.json +// written before the key existed. A stored null stays null. export function agentSecondsFromRaw(t: RawTaskResult): number | null { + if (t.agent_wall_ms !== undefined) { + return typeof t.agent_wall_ms === "number" ? t.agent_wall_ms / 1000 : null; + } const seconds = (t.iterations ?? []) .map((i) => i.duration_seconds) .filter((d): d is number => typeof d === "number" && d > 0); diff --git a/src/coder_eval/reports/html.py b/src/coder_eval/reports/html.py index c9fb8ee23..16f048803 100644 --- a/src/coder_eval/reports/html.py +++ b/src/coder_eval/reports/html.py @@ -24,7 +24,7 @@ from ..analysis import calculate_command_statistics from ..durations import format_ms from ..models import JUDGE_CRITERION_TYPES, FinalStatus, eval_result_total_cost, sum_costs -from ..result_metrics import expected_turns_overage, turn_time_buckets +from ..result_metrics import agent_wall_ms, expected_turns_overage, turn_time_buckets from ..stats import stddev, welch_t_test from .helpers import ( collect_variant_series, @@ -979,11 +979,24 @@ def _render_generation_metrics(result: EvaluationResult) -> str: + "scripts/timing/decompose_run.py reports, and the two are not comparable. Negative means " + "generation and tool execution overlapped." ) + # `Total Latency` is END-TO-END. Agent Wall / Setup / Grading split it, so a + # checker that runs a live command is not read as agent time (#212). Each + # unmeasured one renders as a dash (CE058). + agent_wall = format_ms(agent_wall_ms(result)) + setup = format_ms(result.setup_ms) + grading = format_ms(result.grading_ms) return f"""

Generation Metrics

-
Total Latency
{total_latency}
+
+
Total Latency (end-to-end)
{total_latency}
+
+
+
Agent Wall
{agent_wall}
+
+
Setup
{setup}
+
Grading
{grading}
Turns
{num_turns}
Assistant Turns
{asst_turns}
Avg Turn Latency
{avg_latency}
@@ -1223,12 +1236,20 @@ def _render_variant_generation_metrics(eval_results: list[EvaluationResult]) -> avg_turn = (sum(per_turn_latencies) / len(per_turn_latencies)) if per_turn_latencies else 0.0 total_latency_fmt = _esc(_format_duration(total_duration)) avg_turn_fmt = _esc(_format_duration(avg_turn)) + walls = [ms for r in eval_results if (ms := agent_wall_ms(r)) is not None] + gradings = [r.grading_ms for r in eval_results if r.grading_ms is not None] + total_agent_fmt = _esc(format_ms(sum(walls) if walls else None)) + total_grading_fmt = _esc(format_ms(sum(gradings) if gradings else None)) return f"""

Generation Metrics

Tasks
{total_tasks}
-
Total Latency
{total_latency_fmt}
+
+
Total Latency (end-to-end)
{total_latency_fmt}
+
+
Total Agent Wall
{total_agent_fmt}
+
Total Grading
{total_grading_fmt}
Turns
{total_turns}
Assistant Turns
{total_asst}
Avg Turn Latency
{avg_turn_fmt}
diff --git a/src/coder_eval/reports/markdown.py b/src/coder_eval/reports/markdown.py index 05c3f8581..70ffc52cb 100644 --- a/src/coder_eval/reports/markdown.py +++ b/src/coder_eval/reports/markdown.py @@ -263,6 +263,30 @@ def _pass_rate_lines(summary: RunSummary) -> list[str]: return lines +def _row_agent_wall_ms(row: dict[str, Any]) -> float | None: + """A row's agent wall: the stored ``agent_wall_ms``, else the legacy derivation. + + PREFERS THE STORED KEY, written once by ``result_metrics.agent_wall_ms``. A + ``run.json`` written before the key existed is still renderable: its 6-key + ``iterations`` projection carries each turn's ``duration_seconds``, and the + same rule (sum the positive ones) applies. Presence is tested with ``in``, not + with truthiness, so a stored ``None`` (no turn timed) stays ``None``. + + Rationale: .claude/notes/reporting.md ยง Read the stored value, do not re-derive it + """ + if "agent_wall_ms" in row: + return row["agent_wall_ms"] + seconds = [ + d for t in row.get("iterations") or [] if isinstance(d := t.get("duration_seconds"), (int, float)) and d > 0 + ] + return sum(seconds) * 1000.0 if seconds else None + + +def _fmt_seconds_ms(ms: float | None) -> str: + """``ms`` as ``12.3s``, or ``N/A`` when it was not measured (never ``0.0s``).""" + return f"{ms / 1000.0:.1f}s" if ms is not None else "N/A" + + class ReportGenerator: """Generates reports from evaluation results.""" @@ -344,9 +368,9 @@ def _generate_generation_metrics_section(task_results: list[dict[str, Any]]) -> lines = [ "## Generation Metrics", "", - "| Task ID | Total Latency | Turns | Asst Turns | Avg Turn Latency " + "| Task ID | Total Latency (end-to-end) | Agent Wall | Turns | Asst Turns | Avg Turn Latency " + "| Startup | Generation | Tool exec | Teardown |", - "|---------|---------------|-------|------------|------------------" + "|---------|----------------------------|------------|-------|------------|------------------" + "|---------|------------|-----------|----------|", ] @@ -372,7 +396,11 @@ def _generate_generation_metrics_section(task_results: list[dict[str, Any]]) -> format_ms(task.get(key)) for key in ("startup_ms", "generation_ms", "tool_ms", "teardown_ms") ) - lines.append(f"| {task_id} | {total_latency} | {num_turns} | {asst_turns} | {avg_turn_str} | {buckets} |") + agent_wall = _fmt_seconds_ms(_row_agent_wall_ms(task)) + lines.append( + f"| {task_id} | {total_latency} | {agent_wall} | {num_turns} | {asst_turns} " + + f"| {avg_turn_str} | {buckets} |" + ) return lines @@ -434,7 +462,16 @@ def _summary_section_lines(summary: RunSummary) -> list[str]: if scores: lines.append(f"- **Avg Reliability Score**: {sum(scores) / len(scores):.3f}") if durations: - lines.append(f"- **Avg Generation Latency**: {sum(durations) / len(durations):.1f}s") + # `duration` is END-TO-END (setup + agent + grading), so the label says so. + # The agent's own share and the checker's share are averaged separately, + # each over only the rows that measured it (#212). + lines.append(f"- **Avg End-to-end Latency**: {sum(durations) / len(durations):.1f}s") + agent_walls = [ms for t in summary.task_results if (ms := _row_agent_wall_ms(t)) is not None] + if agent_walls: + lines.append(f"- **Avg Agent Wall**: {sum(agent_walls) / len(agent_walls) / 1000.0:.1f}s") + gradings = [ms for t in summary.task_results if (ms := t.get("grading_ms")) is not None] + if gradings: + lines.append(f"- **Avg Grading**: {sum(gradings) / len(gradings) / 1000.0:.1f}s") total_asst_turns = sum( sum(t.get("assistant_turn_count", 0) for t in task.get("iterations", [])) for task in summary.task_results @@ -467,8 +504,11 @@ def _task_details_lines(summary: RunSummary) -> list[str]: has_tags = any(t.get("tags") for t in summary.task_results) has_cmds_efficiency = any(t.get("commands_efficiency") is not None for t in summary.task_results) - header = "| Task ID | Status | Reliability Score | Latency |" - separator = "|---------|--------|-------------------|---------|" + # `Latency` is END-TO-END: setup + the agent's turns + grading. `Agent Wall` + # and `Grading` split it, so a checker that runs a live command is not read + # as agent time (#212). An older run.json has no `grading_ms`: N/A, not 0. + header = "| Task ID | Status | Reliability Score | Latency (end-to-end) | Agent Wall | Grading |" + separator = "|---------|--------|-------------------|----------------------|------------|---------|" if has_model: header += " Model |" separator += "-------|" @@ -489,7 +529,13 @@ def _task_details_lines(summary: RunSummary) -> list[str]: score_str = f"{weighted_score:.3f}" if weighted_score is not None else "N/A" duration = f"{task_result['duration']:.1f}s" - row = f"| {task_result['task_id']} | {task_result['status']} | {score_str} | {duration} |" + agent_wall = _fmt_seconds_ms(_row_agent_wall_ms(task_result)) + grading = _fmt_seconds_ms(task_result.get("grading_ms")) + + row = ( + f"| {task_result['task_id']} | {task_result['status']} | {score_str} | {duration} " + + f"| {agent_wall} | {grading} |" + ) if has_model: model = task_result.get("model_used") or "N/A" row += f" {model} |" diff --git a/src/coder_eval/result_metrics.py b/src/coder_eval/result_metrics.py index 10be401ec..3dde1b30f 100644 --- a/src/coder_eval/result_metrics.py +++ b/src/coder_eval/result_metrics.py @@ -93,6 +93,30 @@ def turn_time_buckets(result: EvaluationResult) -> TurnTimeBuckets: return TurnTimeBuckets(startup, generation, tool, teardown, unaccounted) +def agent_wall_ms(result: EvaluationResult) -> float | None: + """Wall milliseconds the agent's own turns took: the sum of ``iterations[].duration_seconds``. + + ``duration_seconds`` is the task's END-TO-END wall clock. It also holds + ``setup_ms`` (sandbox, pre_run) and ``grading_ms`` (every success check). A + checker that runs a live command, such as a tenant ``flow debug``, can spend + 30-120 s there, so ``duration_seconds`` is not a measure of the agent. + + It is the SUM, not ``duration - setup - grading``. A detached grade does not + carry ``grading_ms`` and ``coder-eval execute`` never sets it, so the + subtraction has no value on those rows. The sum does. It is also the rule + the evalboard's ``agentSecondsFromRaw`` applies, so the two agree: only a + POSITIVE turn duration counts, because ``0.0`` is the unmeasured default. + + ``None`` when no turn recorded a duration, never ``0.0`` (CE058). + """ + seconds = [ + t.duration_seconds + for t in result.iterations or [] + if isinstance(t.duration_seconds, (int, float)) and math.isfinite(t.duration_seconds) and t.duration_seconds > 0 + ] + return sum(seconds) * 1000.0 if seconds else None + + def _sum_measured(values: Iterable[float | None]) -> float | None: """Sum what was measured, or ``None`` when nothing was. diff --git a/src/coder_eval/run_record.py b/src/coder_eval/run_record.py index 8f99719df..615efc077 100644 --- a/src/coder_eval/run_record.py +++ b/src/coder_eval/run_record.py @@ -17,7 +17,7 @@ from coder_eval.errors import truncate_crash_message from coder_eval.models import EvaluationResult, FinalStatus, judge_cost_usd, simulator_cost_usd, sum_costs -from coder_eval.result_metrics import expected_turns_overage, turn_time_buckets, visible_turn_count +from coder_eval.result_metrics import agent_wall_ms, expected_turns_overage, turn_time_buckets, visible_turn_count from coder_eval.result_metrics import has_final_reply as _has_final_reply @@ -135,6 +135,12 @@ def eval_result_to_task_dict( "generation_ms": _buckets.generation_ms, "tool_ms": _buckets.tool_ms, "teardown_ms": _buckets.teardown_ms, + # `duration` is END-TO-END: setup + the agent's turns + grading. These three + # split it so a slow checker is not read as a slow agent (#212). Each is + # `float | None`; None means not measured, never 0 (CE049). + "agent_wall_ms": agent_wall_ms(result), + "setup_ms": result.setup_ms, + "grading_ms": result.grading_ms, "model_used": result.model_used, "reference_similarity": ref_similarity, # The UNCACHED slice, not TokenUsage.input_tokens; evalboard/lib/runs.ts diff --git a/tests/_fixtures/report_snapshots/run_full.md b/tests/_fixtures/report_snapshots/run_full.md index e576cf416..e7dc0f7d7 100644 --- a/tests/_fixtures/report_snapshots/run_full.md +++ b/tests/_fixtures/report_snapshots/run_full.md @@ -13,17 +13,18 @@ - **Errors**: 0 - **Pass Rate**: 50.0% (1/2) - **Avg Reliability Score**: 0.625 -- **Avg Generation Latency**: 10.2s +- **Avg End-to-end Latency**: 10.2s +- **Avg Agent Wall**: 3.1s - **Total Assistant Turns**: 4 - **Crashed Partials**: 1 (0 recovered, 1 terminal) - **Avg Ground Truth Similarity**: 0.715 ## Task Details -| Task ID | Status | Reliability Score | Latency | Model | Tags | Similarity | Cmd Efficiency | -|---------|--------|-------------------|---------|-------|------|------------|----------------| -| alpha | success | 0.950 | 12.5s | claude-haiku-4-5 | smoke, fast | 0.880 | 75.0% (4/6) | -| beta | failure | 0.300 | 8.0s | claude-sonnet-4-6 | regression | 0.550 | 100.0% (3/3) | +| Task ID | Status | Reliability Score | Latency (end-to-end) | Agent Wall | Grading | Model | Tags | Similarity | Cmd Efficiency | +|---------|--------|-------------------|----------------------|------------|---------|-------|------|------------|----------------| +| alpha | success | 0.950 | 12.5s | 4.2s | N/A | claude-haiku-4-5 | smoke, fast | 0.880 | 75.0% (4/6) | +| beta | failure | 0.300 | 8.0s | 2.0s | N/A | claude-sonnet-4-6 | regression | 0.550 | 100.0% (3/3) | ## Run-time Notes @@ -33,10 +34,10 @@ ## Generation Metrics -| Task ID | Total Latency | Turns | Asst Turns | Avg Turn Latency | Startup | Generation | Tool exec | Teardown | -|---------|---------------|-------|------------|------------------|---------|------------|-----------|----------| -| alpha | 12.5s | 1 | 3 | 4.2s | โ€” | โ€” | โ€” | โ€” | -| beta | 8.0s | 1 | 1 | 2.0s | โ€” | โ€” | โ€” | โ€” | +| Task ID | Total Latency (end-to-end) | Agent Wall | Turns | Asst Turns | Avg Turn Latency | Startup | Generation | Tool exec | Teardown | +|---------|----------------------------|------------|-------|------------|------------------|---------|------------|-----------|----------| +| alpha | 12.5s | 4.2s | 1 | 3 | 4.2s | โ€” | โ€” | โ€” | โ€” | +| beta | 8.0s | 2.0s | 1 | 1 | 2.0s | โ€” | โ€” | โ€” | โ€” | ## Token Usage diff --git a/tests/_fixtures/report_snapshots/run_minimal.md b/tests/_fixtures/report_snapshots/run_minimal.md index be0e83084..ef9266651 100644 --- a/tests/_fixtures/report_snapshots/run_minimal.md +++ b/tests/_fixtures/report_snapshots/run_minimal.md @@ -14,8 +14,8 @@ ## Task Details -| Task ID | Status | Reliability Score | Latency | -|---------|--------|-------------------|---------| +| Task ID | Status | Reliability Score | Latency (end-to-end) | Agent Wall | Grading | +|---------|--------|-------------------|----------------------|------------|---------| ## Environment diff --git a/tests/test_reports.py b/tests/test_reports.py index 18e9cb47d..4989f92c0 100644 --- a/tests/test_reports.py +++ b/tests/test_reports.py @@ -218,7 +218,7 @@ def test_generate_markdown_basic(): # Check P0 aggregate metrics assert "Avg Reliability Score**:" in report_md - assert "Avg Generation Latency**:" in report_md + assert "Avg End-to-end Latency**:" in report_md assert "Avg Ground Truth Similarity**:" in report_md # Check task details table has new columns @@ -397,9 +397,9 @@ def test_generate_markdown_generation_metrics_section(): assert "## Generation Metrics" in report_md # task1: 1 turn, 0 asst turns (no assistant_turn_count in test data) - assert "| task1 | 50.0s | 1 | 0 | 50.0s |" in report_md + assert "| task1 | 50.0s | 50.0s | 1 | 0 | 50.0s |" in report_md # task2: 3 turns, avg turn = (25+22+23)/3 = 23.3s - assert "| task2 | 70.0s | 3 | 0 | 23.3s |" in report_md + assert "| task2 | 70.0s | 70.0s | 3 | 0 | 23.3s |" in report_md def test_generate_markdown_no_generation_metrics_without_turns(): @@ -448,7 +448,7 @@ def test_generate_markdown_aggregate_metrics(): # Avg reliability = (0.8 + 0.6) / 2 = 0.7 assert "Avg Reliability Score**: 0.700" in report_md # Avg latency = (40 + 60) / 2 = 50.0s - assert "Avg Generation Latency**: 50.0s" in report_md + assert "Avg End-to-end Latency**: 50.0s" in report_md def test_generate_markdown_backward_compatible_task_results(): @@ -1535,3 +1535,64 @@ def test_importing_reports_does_not_pull_in_criteria(self): code = "import coder_eval.reports, sys; print('coder_eval.criteria' in sys.modules)" out = subprocess.run([sys.executable, "-c", code], capture_output=True, text=True, check=True) assert out.stdout.strip() == "False", "coder_eval.reports must not import coder_eval.criteria at module level" + + +def test_task_details_split_end_to_end_into_agent_wall_and_grading(): + """`Latency` is end-to-end; a slow checker must not read as a slow agent (#212). + + Numbers from adhoc-2026-10-01_19-24-36, calculator flow-v2 run 00: 101.3 s + end to end = 55.7 s of agent turns + 13.7 s setup + 27.7 s grading + residual. + """ + row = _make_task_result( + "calc", "SUCCESS", 1.0, 101.25, iteration_count=1, turns=[{"iteration": 1, "duration_seconds": 55.66}] + ) + row.update(agent_wall_ms=55657.3, setup_ms=13677.6, grading_ms=27656.9) + summary = RunSummary( + run_id="r", + start_time=datetime(2026, 10, 1, 19, 24, 36), + end_time=datetime(2026, 10, 1, 19, 26, 17), + total_duration_seconds=101.25, + tasks_run=1, + tasks_succeeded=1, + tasks_failed=0, + tasks_error=0, + task_results=[row], + framework_version="0.1.0", + environment_info={}, + ) + report_md = ReportGenerator.generate_markdown(summary) + assert "| Task ID | Status | Reliability Score | Latency (end-to-end) | Agent Wall | Grading |" in report_md + assert "| calc | SUCCESS | 1.000 | 101.2s | 55.7s | 27.7s |" in report_md + assert "Avg Agent Wall**: 55.7s" in report_md + assert "Avg Grading**: 27.7s" in report_md + + +def test_task_details_legacy_row_derives_agent_wall_and_never_fakes_grading(): + """A run.json written before #212 has no `agent_wall_ms` / `grading_ms` keys. + + Agent wall falls back to the row's own `iterations[].duration_seconds`; grading + was never recorded on the row, so it renders N/A, never 0.0s (CE058). + """ + row = _make_task_result( + "old", + "SUCCESS", + 1.0, + 90.0, + turns=[{"iteration": 1, "duration_seconds": 30.0}, {"iteration": 2, "duration_seconds": 0.0}], + ) + summary = RunSummary( + run_id="r", + start_time=datetime(2026, 10, 1, 19, 24, 36), + end_time=datetime(2026, 10, 1, 19, 26, 6), + total_duration_seconds=90.0, + tasks_run=1, + tasks_succeeded=1, + tasks_failed=0, + tasks_error=0, + task_results=[row], + framework_version="0.1.0", + environment_info={}, + ) + report_md = ReportGenerator.generate_markdown(summary) + assert "| old | SUCCESS | 1.000 | 90.0s | 30.0s | N/A |" in report_md + assert "Avg Grading" not in report_md diff --git a/tests/test_run_record.py b/tests/test_run_record.py index c2d0f82c3..922dc3be7 100644 --- a/tests/test_run_record.py +++ b/tests/test_run_record.py @@ -73,6 +73,9 @@ "task_id": "char-task", "task_path": None, "teardown_ms": None, + "agent_wall_ms": 2500.0, + "setup_ms": None, + "grading_ms": None, "tool_ms": None, "total_cost_usd": 0.5, "total_tokens": 1000, @@ -271,3 +274,30 @@ def test_none_when_run_limits_not_dict(self): ) d = eval_result_to_task_dict(result) assert d["expected_turns"] is None + + +class TestAgentWallIsSplitFromEndToEnd: + """`duration` is end-to-end; the row also carries the agent's and the checker's share (#212).""" + + def test_row_carries_setup_grading_and_agent_wall(self): + result = _result() + result.setup_ms = 14000.0 + result.grading_ms = 28000.0 + row = eval_result_to_task_dict(result) + assert row["duration"] == 3.0 + assert row["agent_wall_ms"] == 2500.0 + assert row["setup_ms"] == 14000.0 + assert row["grading_ms"] == 28000.0 + + def test_agent_wall_is_none_when_no_turn_was_timed(self): + result = _result() + result.iterations = [] + assert eval_result_to_task_dict(result)["agent_wall_ms"] is None + + def test_agent_wall_sums_turns_and_skips_the_unmeasured_default(self): + result = _result() + timed = result.iterations[0] + untimed = timed.model_copy(update={"iteration": 2, "duration_seconds": 0.0}) + third = timed.model_copy(update={"iteration": 3, "duration_seconds": 1.5}) + result.iterations = [timed, untimed, third] + assert eval_result_to_task_dict(result)["agent_wall_ms"] == 4000.0