From 573cd9747f35166a703da0f6a2355ae50f0d1153 Mon Sep 17 00:00:00 2001 From: Evan Hoffman Date: Sun, 19 Apr 2026 08:24:37 -0400 Subject: [PATCH] Add timing breakdown fields to run summaries --- benchmark/evaluator.py | 4 + benchmark/runner.py | 84 +++++++++++++++++++-- tests/test_evaluator.py | 56 ++++++++++++++ tests/test_runner.py | 158 ++++++++++++++++++++++++++++++++++++++++ 4 files changed, 296 insertions(+), 6 deletions(-) diff --git a/benchmark/evaluator.py b/benchmark/evaluator.py index 1f4ae3f..20f252e 100644 --- a/benchmark/evaluator.py +++ b/benchmark/evaluator.py @@ -8,6 +8,7 @@ import logging import re import stat +import time import tomllib from pathlib import Path from typing import Any @@ -51,6 +52,7 @@ def _empty_eval_result( "response_bytes": None, "body_has_refresh_mechanism": False, "body_has_limerick_shape": False, + "startup_seconds": None, "passed": False, "error": error, } @@ -230,6 +232,7 @@ async def _try_entry_point(workspace: Path, entry_cmd: str) -> dict[str, Any]: ) try: + startup_started = time.monotonic() up = await _wait_for_port(PORT, STARTUP_TIMEOUT) if not up: logger.warning("Server did not come up on port %d within %ds for '%s'", PORT, STARTUP_TIMEOUT, entry_cmd) @@ -253,6 +256,7 @@ async def _try_entry_point(workspace: Path, entry_cmd: str) -> dict[str, Any]: body = await resp.read() result["http_status"] = resp.status result["response_bytes"] = len(body) + result["startup_seconds"] = round(time.monotonic() - startup_started, 1) result.update(_classify_http_response(resp.status, body, workspace)) logger.info("GET / → %d (%d bytes)", resp.status, len(body)) except Exception as exc: diff --git a/benchmark/runner.py b/benchmark/runner.py index 2ae88ac..e3ce6ee 100644 --- a/benchmark/runner.py +++ b/benchmark/runner.py @@ -26,6 +26,8 @@ # and auto-register as a workspace member in our root pyproject.toml. WORKSPACE_BASE = Path.home() / ".limerick-benchmark" / "workspaces" RUN_ORDER_CHOICES = ("balanced", "random", "fixed") +_WORKSPACE_IGNORE_DIR_NAMES = {".venv", ".git", "__pycache__", "node_modules"} +_WORKSPACE_IGNORE_PREFIXES = (".aider.",) def _slug(model_id: str) -> str: @@ -66,6 +68,43 @@ def _run_dir_name( ) +def _round_seconds(value: float | None) -> float | None: + if value is None: + return None + return round(value, 1) + + +def _first_meaningful_edit_seconds(workspace: Path, started_epoch_ns: int) -> float | None: + """Return elapsed seconds until the first non-cache workspace file edit.""" + first_edit_ns: int | None = None + if not workspace.exists(): + return None + + for path in workspace.rglob("*"): + if not path.is_file(): + continue + try: + rel = path.relative_to(workspace) + except ValueError: + continue + if any(part in _WORKSPACE_IGNORE_DIR_NAMES for part in rel.parts): + continue + if any(part.startswith(_WORKSPACE_IGNORE_PREFIXES) for part in rel.parts): + continue + try: + mtime_ns = path.stat().st_mtime_ns + except OSError: + continue + if mtime_ns < started_epoch_ns: + continue + if first_edit_ns is None or mtime_ns < first_edit_ns: + first_edit_ns = mtime_ns + + if first_edit_ns is None: + return None + return _round_seconds(max(0.0, (first_edit_ns - started_epoch_ns) / 1_000_000_000)) + + def _ordered_models_for_round( models: list[dict[str, Any]], *, @@ -354,7 +393,9 @@ async def _run_one( ) collector.start(token_state) - wall_start = time.time() + started_at = datetime.now(timezone.utc).isoformat() + run_started_epoch_ns = time.time_ns() + run_started_monotonic = time.monotonic() agent_stats = await run_agent( model_id=model_id, @@ -369,15 +410,27 @@ async def _run_one( run_label=run_label, ) - wall_elapsed = round(time.time() - wall_start, 1) - collector.stop() + agent_finished_at = datetime.now(timezone.utc).isoformat() + agent_seconds = _round_seconds(time.monotonic() - run_started_monotonic) + first_edit_seconds = _first_meaningful_edit_seconds(workspace, run_started_epoch_ns) + eval_started_at: str | None = None + eval_finished_at: str | None = None + eval_seconds: float | None = None if _should_evaluate(agent_stats): assert_port_available(PORT, f"evaluating {model_id}") - logger.info("Agent done in %.1fs — evaluating…", wall_elapsed) + logger.info("Agent done in %.1fs — evaluating…", agent_seconds or 0.0) + eval_started_at = datetime.now(timezone.utc).isoformat() + eval_started_monotonic = time.monotonic() eval_result = await evaluate(workspace, run_dir) + eval_seconds = _round_seconds(time.monotonic() - eval_started_monotonic) + eval_finished_at = datetime.now(timezone.utc).isoformat() else: - logger.info("Agent done in %.1fs — skipping evaluation (%s)", wall_elapsed, agent_stats.get("finish_reason")) + logger.info( + "Agent done in %.1fs — skipping evaluation (%s)", + agent_seconds or 0.0, + agent_stats.get("finish_reason"), + ) eval_result = { "entry_point": None, "entry_point_candidates": [], @@ -387,23 +440,36 @@ async def _run_one( "response_bytes": None, "body_has_refresh_mechanism": False, "body_has_limerick_shape": False, + "startup_seconds": None, "passed": False, "error": "evaluation_skipped", } + finished_at = datetime.now(timezone.utc).isoformat() + wall_elapsed = _round_seconds(time.monotonic() - run_started_monotonic) or 0.0 + collector.stop() + normalized_agent_stats = _normalize_agent_stats_for_eval(agent_stats, eval_result) summary = { "model_id": model_id, "provider": provider, "run_dir": str(run_dir), - "started_at": datetime.now(timezone.utc).isoformat(), + "started_at": started_at, + "agent_finished_at": agent_finished_at, + "eval_started_at": eval_started_at, + "eval_finished_at": eval_finished_at, + "finished_at": finished_at, "run_index": run_index, "total_runs": total_runs, "round_index": round_index, "position_in_round": position_in_round, "total_rounds": total_rounds, "wall_seconds": wall_elapsed, + "agent_seconds": agent_seconds, + "eval_seconds": eval_seconds, + "first_edit_seconds": first_edit_seconds, + "startup_seconds": eval_result.get("startup_seconds"), "timeout_seconds": timeout, "aider_stagnation_timeout_seconds": aider_stagnation_timeout, **token_state, @@ -426,6 +492,12 @@ def _print_summary(s: dict[str, Any]) -> None: logger.info("─" * 60) logger.info(" Model : %s", s["model_id"]) logger.info(" Wall time : %.1fs", s["wall_seconds"]) + if isinstance(s.get("agent_seconds"), (int, float)): + logger.info(" Agent time : %.1fs", s["agent_seconds"]) + if isinstance(s.get("eval_seconds"), (int, float)): + logger.info(" Eval time : %.1fs", s["eval_seconds"]) + if isinstance(s.get("startup_seconds"), (int, float)): + logger.info(" Startup : %.1fs", s["startup_seconds"]) logger.info(" Tokens in : %s", _format_counter(s.get("tokens_in"))) logger.info(" Tokens out : %s", _format_counter(s.get("tokens_out"))) logger.info(" API calls : %s", _format_counter(s.get("api_calls"))) diff --git a/tests/test_evaluator.py b/tests/test_evaluator.py index b85c46f..e2c8586 100644 --- a/tests/test_evaluator.py +++ b/tests/test_evaluator.py @@ -198,3 +198,59 @@ async def test_try_entry_point_checks_port_before_starting_server(self) -> None: assert_mock.assert_called_once() create_proc_mock.assert_not_called() + + async def test_try_entry_point_records_startup_seconds_after_http_response(self) -> None: + class FakeResponse: + status = 200 + + async def __aenter__(self): + return self + + async def __aexit__(self, exc_type, exc, tb): + return False + + async def read(self) -> bytes: + return ( + b"" + b"
One\nTwo\nThree\nFour\nFive
" + ) + + class FakeSession: + async def __aenter__(self): + return self + + async def __aexit__(self, exc_type, exc, tb): + return False + + def get(self, *args, **kwargs): + return FakeResponse() + + with tempfile.TemporaryDirectory() as tmp: + workspace = Path(tmp) + proc = mock.Mock(pid=123, returncode=0) + with ( + mock.patch("benchmark.evaluator.assert_port_available"), + mock.patch( + "benchmark.evaluator.asyncio.create_subprocess_shell", + new=mock.AsyncMock(return_value=proc), + ), + mock.patch( + "benchmark.evaluator._wait_for_port", + new=mock.AsyncMock(return_value=True), + ), + mock.patch( + "benchmark.evaluator.listener_belongs_to_process_tree", + return_value=True, + ), + mock.patch( + "benchmark.evaluator.terminate_process_group", + new=mock.AsyncMock(), + ), + mock.patch("benchmark.evaluator.aiohttp.ClientSession", return_value=FakeSession()), + mock.patch("benchmark.evaluator.time.monotonic", side_effect=[10.0, 12.6]), + ): + result = await _try_entry_point(workspace, "uv run python app.py") + + self.assertEqual(result["http_status"], 200) + self.assertEqual(result["startup_seconds"], 2.6) + self.assertTrue(result["passed"]) diff --git a/tests/test_runner.py b/tests/test_runner.py index b903736..82a82cf 100644 --- a/tests/test_runner.py +++ b/tests/test_runner.py @@ -8,6 +8,7 @@ RUN_ORDER_CHOICES, RESULTS_ROOT, _build_run_plan, + _first_meaningful_edit_seconds, _new_job_id, _normalize_agent_stats_for_eval, _prepare_workspace, @@ -185,6 +186,23 @@ def test_build_run_plan_uses_plain_slug_for_single_run(self) -> None: plan = _build_run_plan([{"id": "gemma4:e4b"}], rounds=1, order="balanced", seed=None) self.assertEqual(plan[0]["run_dir_name"], "gemma4_e4b") + +class RunnerTimingTests(unittest.TestCase): + def test_first_meaningful_edit_ignores_cache_directories(self) -> None: + with TemporaryDirectory() as tmp: + workspace = Path(tmp) + cache_dir = workspace / ".venv" + cache_dir.mkdir() + (cache_dir / "ignored.txt").write_text("ignore\n") + app_path = workspace / "app.py" + app_path.write_text("print('ok')\n") + started_ns = app_path.stat().st_mtime_ns - 1_000_000 + + edit_seconds = _first_meaningful_edit_seconds(workspace, started_ns) + + self.assertEqual(edit_seconds, 0.0) + + class RunnerPropagationTests(unittest.IsolatedAsyncioTestCase): async def test_run_benchmark_passes_aider_stagnation_timeout_to_each_run(self) -> None: model = {"id": "qwen3.5:9b", "provider": "ollama"} @@ -299,3 +317,143 @@ async def test_run_one_checks_port_before_starting_model_run(self) -> None: assert_mock.assert_called_once() run_agent_mock.assert_not_called() + + +class RunnerSummaryTimingTests(unittest.IsolatedAsyncioTestCase): + async def test_run_one_records_timing_breakdown_and_lifecycle_fields(self) -> None: + model = {"id": "gemma4:e2b", "provider": "ollama"} + with TemporaryDirectory() as tmp: + results_root = Path(tmp) / "results" + workspace_base = Path(tmp) / "workspaces" + collector = mock.Mock() + + async def fake_run_agent(*args, **kwargs): + workspace = kwargs["workspace"] + (workspace / "app.py").write_text("print('ok')\n") + return { + "finish_reason": "completed", + "timed_out": False, + "error": None, + "agent_stop": None, + } + + eval_result = { + "entry_point": "uv run python app.py", + "entry_point_candidates": ["uv run python app.py"], + "entry_point_mismatch": False, + "server_started": True, + "http_status": 200, + "response_bytes": 123, + "body_has_refresh_mechanism": True, + "body_has_limerick_shape": True, + "startup_seconds": 2.7, + "passed": True, + "error": None, + } + + with ( + mock.patch("benchmark.runner.RESULTS_ROOT", results_root), + mock.patch("benchmark.runner.WORKSPACE_BASE", workspace_base), + mock.patch("benchmark.runner.MetricsCollector", return_value=collector), + mock.patch("benchmark.runner.run_agent", side_effect=fake_run_agent), + mock.patch("benchmark.runner.evaluate", new=mock.AsyncMock(return_value=eval_result)), + mock.patch( + "benchmark.runner.time.monotonic", + side_effect=[100.0, 112.4, 112.4, 115.1, 115.1], + ), + ): + summary = await _run_one( + model, + "Build the app.", + timeout=900, + aider_stagnation_timeout=420, + enable_hardware_metrics=False, + job_id="20260417.083818", + run_index=1, + total_runs=1, + round_index=1, + position_in_round=1, + total_rounds=1, + run_dir_name="gemma4_e2b", + agent_type="react", + run_label="1/1:gemma4-e2b:react", + task_name="limerick", + ) + + saved_summary = json.loads((results_root / "20260417.083818" / "gemma4_e2b" / "summary.json").read_text()) + + collector.start.assert_called_once() + collector.stop.assert_called_once() + self.assertEqual(summary["wall_seconds"], 15.1) + self.assertEqual(summary["agent_seconds"], 12.4) + self.assertEqual(summary["eval_seconds"], 2.7) + self.assertEqual(summary["startup_seconds"], 2.7) + self.assertIsInstance(summary["first_edit_seconds"], float) + self.assertGreaterEqual(summary["first_edit_seconds"], 0.0) + self.assertIsNotNone(summary["started_at"]) + self.assertIsNotNone(summary["agent_finished_at"]) + self.assertIsNotNone(summary["eval_started_at"]) + self.assertIsNotNone(summary["eval_finished_at"]) + self.assertIsNotNone(summary["finished_at"]) + self.assertTrue(summary["passed"]) + self.assertEqual(saved_summary["wall_seconds"], 15.1) + self.assertEqual(saved_summary["agent_seconds"], 12.4) + self.assertEqual(saved_summary["eval_seconds"], 2.7) + self.assertEqual(saved_summary["startup_seconds"], 2.7) + + async def test_run_one_leaves_eval_timing_empty_when_evaluation_is_skipped(self) -> None: + model = {"id": "qwen3.5:9b", "provider": "ollama"} + with TemporaryDirectory() as tmp: + results_root = Path(tmp) / "results" + workspace_base = Path(tmp) / "workspaces" + collector = mock.Mock() + with ( + mock.patch("benchmark.runner.RESULTS_ROOT", results_root), + mock.patch("benchmark.runner.WORKSPACE_BASE", workspace_base), + mock.patch("benchmark.runner.MetricsCollector", return_value=collector), + mock.patch( + "benchmark.runner.run_agent", + new=mock.AsyncMock( + return_value={ + "finish_reason": "stuck_loop", + "timed_out": False, + "error": None, + "agent_stop": { + "category": "repeating_log_cycle", + "detail": "repeating log cycle detected", + }, + } + ), + ), + mock.patch("benchmark.runner.evaluate", new=mock.AsyncMock()) as evaluate_mock, + mock.patch( + "benchmark.runner.time.monotonic", + side_effect=[200.0, 205.4, 205.4], + ), + ): + summary = await _run_one( + model, + "Build the app.", + timeout=900, + aider_stagnation_timeout=420, + enable_hardware_metrics=False, + job_id="20260417.083818", + run_index=1, + total_runs=1, + round_index=1, + position_in_round=1, + total_rounds=1, + run_dir_name="qwen3.5_9b", + agent_type="react", + run_label="1/1:qwen3.5-9b:react", + task_name="limerick", + ) + + evaluate_mock.assert_not_awaited() + self.assertEqual(summary["wall_seconds"], 5.4) + self.assertEqual(summary["agent_seconds"], 5.4) + self.assertIsNone(summary["eval_seconds"]) + self.assertIsNone(summary["eval_started_at"]) + self.assertIsNone(summary["eval_finished_at"]) + self.assertIsNone(summary["startup_seconds"]) + self.assertFalse(summary["passed"])