feat: per-script smoke timings as a standing dataset (#264)

autohands/aggregate_results.py

@@ -131,7 +131,14 @@ def _surface(runs: list, script_count: int) -> dict:
 
 def aggregate(results_dir: Path) -> dict:
     """Read all JSON result files and produce a consolidated report."""
-    json_files = sorted(results_dir.glob("**/*.json"))
+    # The timing dataset lives in the same directory but is not a run report —
+    # it has no ``results`` key and would enter ``runs`` as an empty phantom
+    # run, so it is excluded by name here rather than by shape.
+    from result_collector import TIMINGS_FILENAME
+
+    json_files = sorted(
+        p for p in results_dir.glob("**/*.json") if p.name != TIMINGS_FILENAME
+    )
     if not json_files:
         print(f"No JSON result files found in {results_dir}", file=sys.stderr)
         return {

autohands/build_util.py

@@ -490,6 +490,7 @@ def _classify_notebook_run(run_target, recorded, report, env, timeout_secs):
                 status=Status.TIMEOUT,
                 duration_seconds=duration,
                 error_message=message,
+                cap_seconds=timeout_secs,
             ))
             return "timeout"
         logging.exception(e)
@@ -509,6 +510,8 @@ def _classify_notebook_run(run_target, recorded, report, env, timeout_secs):
                     status=Status.PASSED,
                     duration_seconds=duration,
                     error_message="sys.exit(0) skip guard (ignored)",
+                    cap_seconds=timeout_secs,
+                    exit_code=e.returncode,
                 ))
             else:
                 print(f"  PASS (skipped via sys.exit(0), {duration:.1f}s)")
@@ -523,6 +526,8 @@ def _classify_notebook_run(run_target, recorded, report, env, timeout_secs):
                     status=Status.PASSED,
                     duration_seconds=duration,
                     error_message="InversionException (ignored)",
+                    cap_seconds=timeout_secs,
+                    exit_code=e.returncode,
                 ))
             return "passed"
 
@@ -537,6 +542,8 @@ def _classify_notebook_run(run_target, recorded, report, env, timeout_secs):
                 duration_seconds=duration,
                 error_message=str(e),
                 traceback=stderr,
+                cap_seconds=timeout_secs,
+                exit_code=e.returncode,
             ))
             return "failed"
         # stderr is captured now (see the subprocess call above), so echo it
@@ -554,6 +561,8 @@ def _classify_notebook_run(run_target, recorded, report, env, timeout_secs):
             file=recorded,
             status=Status.PASSED,
             duration_seconds=duration,
+            cap_seconds=timeout_secs,
+            exit_code=0,
         ))
     return "passed"
 
@@ -758,6 +767,7 @@ def execute_script(f, report=None, env=None, extra_args=None):
                 status=Status.TIMEOUT,
                 duration_seconds=duration,
                 error_message=message,
+                cap_seconds=timeout_secs,
             ))
             return
         logging.exception(e)
@@ -777,6 +787,8 @@ def execute_script(f, report=None, env=None, extra_args=None):
                 duration_seconds=duration,
                 error_message=str(e),
                 traceback=stderr,
+                cap_seconds=timeout_secs,
+                exit_code=e.returncode,
             ))
             return
         logging.exception(e)
@@ -790,6 +802,8 @@ def execute_script(f, report=None, env=None, extra_args=None):
             file=str(f),
             status=Status.PASSED,
             duration_seconds=duration,
+            cap_seconds=timeout_secs,
+            exit_code=0,
         ))
 
 

autohands/result_collector.py

@@ -1,10 +1,25 @@
 import dataclasses
 import datetime
 import json
+import os
+import sys
 from enum import Enum
 from pathlib import Path
 from typing import List, Optional
 
+# The consolidated per-entry timing dataset written alongside every report.
+#
+# Why a second file rather than more keys on the per-run JSON: the per-run
+# ``<project>__<dir>__<run_type>.json`` files are read by PyAutoHeart
+# (``script_timing`` globs ``*__script.json``, ``test_run`` reads the
+# aggregated ``report.json``) and by ``aggregate_results``. Their shape is a
+# published interface, so the timing dataset is emitted beside them instead —
+# one file per report DIRECTORY, merged across the legs that write into it, so
+# a run's timings are a single artifact regardless of how many runner
+# invocations produced them.
+TIMINGS_FILENAME = "smoke_timings.json"
+TIMINGS_SCHEMA = "smoke_timings/1"
+
 
 class Status(str, Enum):
     PASSED = "passed"
@@ -13,6 +28,24 @@ class Status(str, Enum):
     TIMEOUT = "timeout"
 
 
+def workspace_relative(path: str) -> str:
+    """Render a recorded result path relative to the workspace root (cwd).
+
+    The runners record absolute paths (``find_scripts_in_folder`` and
+    ``files_from_list`` both build from ``Path.cwd()``). The timing dataset is
+    compared ACROSS runs and machines, where an absolute path is noise and, on
+    a GitHub runner, a different string every time. A path outside the
+    workspace, or an already-relative one, is returned unchanged.
+    """
+    p = Path(path)
+    if not p.is_absolute():
+        return str(p)
+    try:
+        return str(p.relative_to(Path.cwd()))
+    except ValueError:  # pragma: no cover - a path outside the workspace
+        return str(p)
+
+
 @dataclasses.dataclass
 class ScriptResult:
     file: str
@@ -21,8 +54,55 @@ class ScriptResult:
     error_message: Optional[str] = None
     traceback: Optional[str] = None
     skip_reason: Optional[str] = None
+    # The wall-clock cap that was in force for this entry, as resolved by
+    # ``build_util.timeout_for`` at the execution site (a profile's
+    # ``BUILD_SCRIPT_TIMEOUT`` override, else the ambient global). Only an
+    # entry that actually entered an execution carries one, so ``None`` is the
+    # marker for "never ran" — which is what keeps a skipped entry out of the
+    # timing dataset instead of being recorded as a 0-second run.
+    cap_seconds: Optional[float] = None
+    # The child's exit status. ``None`` for a timeout (the process group was
+    # killed, so there is no exit code the script chose) and for entries that
+    # never ran.
+    exit_code: Optional[int] = None
+
+    @property
+    def was_timed(self) -> bool:
+        """True when this entry actually ran and its duration is a measurement.
+
+        A SKIPPED entry never started, and a listed-but-missing entry fails
+        before any execution — both carry ``duration_seconds == 0.0`` purely as
+        the dataclass default. Recording those as "0 seconds" would put
+        fabricated rows in a dataset whose whole purpose is timing, so they are
+        emitted with a null duration instead.
+        """
+        if self.status == Status.SKIPPED:
+            return False
+        return self.cap_seconds is not None or self.duration_seconds > 0
+
+    def to_timings_entry(self) -> dict:
+        """One row of the timing dataset.
+
+        ``seconds`` is the runner's OWN measurement — the same
+        ``time.time()`` delta ``build_util`` prints on the ``PASS`` /
+        ``TIMEOUT`` line — never re-derived from timestamps elsewhere.
+        """
+        path = workspace_relative(self.file)
+        return {
+            "entry": path,
+            "kind": "notebook" if path.endswith(".ipynb") else "script",
+            "status": self.status.value,
+            "seconds": round(self.duration_seconds, 2) if self.was_timed else None,
+            "cap_s": self.cap_seconds,
+            "exit_code": self.exit_code,
+        }
 
     def to_dict(self):
+        # ``cap_seconds`` / ``exit_code`` are deliberately NOT emitted here.
+        # This dict is the per-run JSON that PyAutoHeart's ``script_timing``
+        # and ``test_run`` checks and ``aggregate_results`` read; it stays
+        # byte-compatible, and the new fields reach consumers through
+        # ``to_timings_entry`` instead.
         d = {
             "file": self.file,
             "status": self.status.value,
@@ -144,6 +224,154 @@ def to_markdown(self) -> str:
 
         return "\n".join(lines)
 
+    # --- the timing dataset (one file per report dir) -------------------------
+
+    def _leg(self) -> dict:
+        """This report's identity within a shared report directory.
+
+        A report dir can receive several runner invocations — the script leg
+        and the notebook leg of one smoke gate, or every directory of every
+        workspace in the ``run_all`` mega-run. Each is a *leg*, and the merged
+        timing file records them all so the dataset states what produced it.
+        """
+        return {
+            "project": self.project,
+            "directory": self.directory,
+            "run_type": self.run_type,
+            "env_profile": self.env_profile,
+            "ts": self.completed_at or self.started_at,
+            "entries": len(self.results),
+        }
+
+    def to_timings(self) -> dict:
+        """The timing dataset for THIS report, before merging."""
+        return {
+            "schema": TIMINGS_SCHEMA,
+            "project": self.project,
+            "directory": self.directory,
+            "run_type": self.run_type,
+            "env_profile": self.env_profile,
+            "python": f"{sys.version_info.major}.{sys.version_info.minor}",
+            "ts": self.completed_at or self.started_at,
+            "entries": [r.to_timings_entry() for r in self.results],
+            "legs": [self._leg()],
+        }
+
+    def merge_timings(self, existing: Optional[dict]) -> dict:
+        """Fold this report's entries into an already-written timing dataset.
+
+        The merge key is the workspace-relative entry path: the script leg and
+        the notebook leg contribute disjoint paths, so both survive, while
+        re-running the SAME leg replaces its own rows rather than duplicating
+        them (a runner invoked twice into one report dir must not double-count).
+
+        The top-level metadata describes the leg that wrote last; ``legs``
+        carries every contributing leg, which is what a report dir spanning
+        more than one project (the ``run_all`` mega-run) needs in order to be
+        read back honestly.
+
+        An unreadable or foreign file is replaced rather than merged — a
+        corrupt sidecar must not take the run down or silently poison the
+        dataset.
+        """
+        fresh = self.to_timings()
+        if not isinstance(existing, dict) or existing.get("schema") != TIMINGS_SCHEMA:
+            return fresh
+
+        mine = {e["entry"] for e in fresh["entries"]}
+        prior = [
+            e
+            for e in existing.get("entries", [])
+            if isinstance(e, dict) and e.get("entry") not in mine
+        ]
+        fresh["entries"] = prior + fresh["entries"]
+
+        def key(leg):
+            return (leg.get("project"), leg.get("directory"), leg.get("run_type"))
+
+        mine_key = key(self._leg())
+        prior_legs = [
+            leg
+            for leg in existing.get("legs", [])
+            if isinstance(leg, dict) and key(leg) != mine_key
+        ]
+        fresh["legs"] = prior_legs + fresh["legs"]
+        return fresh
+
+    def write_timings(self, output_dir: Path) -> Path:
+        path = output_dir / TIMINGS_FILENAME
+        existing = None
+        if path.exists():
+            try:
+                existing = json.loads(path.read_text())
+            except (json.JSONDecodeError, OSError, UnicodeDecodeError):
+                existing = None
+        with open(path, "w") as f:
+            json.dump(self.merge_timings(existing), f, indent=2)
+        return path
+
+    def timings_markdown(self) -> str:
+        """A slowest-first timing table for the GitHub Actions step summary.
+
+        Only this report's own entries: the step summary is append-only, so a
+        second leg adds its own table rather than restating the first's.
+        """
+        timed = [r for r in self.results if r.was_timed]
+        untimed = [r for r in self.results if not r.was_timed]
+        timed.sort(key=lambda r: r.duration_seconds, reverse=True)
+
+        total = round(sum(r.duration_seconds for r in timed), 1)
+        lines = [
+            "",
+            f"### Smoke timings — {self.project} / {self.directory} "
+            f"({self.run_type}, Python "
+            f"{sys.version_info.major}.{sys.version_info.minor})",
+            "",
+            "| Entry | Status | Seconds | Cap |",
+            "|---|---|---:|---:|",
+        ]
+        for r in timed + untimed:
+            entry = workspace_relative(r.file)
+            seconds = f"{r.duration_seconds:.1f}" if r.was_timed else "—"
+            # The cap is only informative where it BOUND the entry: on a
+            # passing script it is the same number on every row and reads as
+            # noise, while on a timeout it is the whole story.
+            cap = (
+                f"{r.cap_seconds:.0f}s"
+                if r.status == Status.TIMEOUT and r.cap_seconds is not None
+                else ""
+            )
+            lines.append(
+                f"| `{entry}` | {r.status.value} | {seconds} | {cap} |"
+            )
+        lines.append("")
+        count = len(self.results)
+        lines.append(
+            f"**{count} {'entry' if count == 1 else 'entries'}** | "
+            f"{len(timed)} timed | {total}s total"
+        )
+        lines.append("")
+        return "\n".join(lines)
+
+    def append_step_summary(self) -> bool:
+        """Append the timing table to ``$GITHUB_STEP_SUMMARY`` when in Actions.
+
+        Returns False (and changes nothing) off CI, so a local run is
+        byte-identical to before. A write failure is reported and swallowed:
+        the summary is a convenience, and losing it must not fail a run whose
+        scripts all passed.
+        """
+        target = os.environ.get("GITHUB_STEP_SUMMARY")
+        if not target:
+            return False
+        try:
+            with open(target, "a") as f:
+                f.write(self.timings_markdown())
+        except OSError as exc:
+            print(f"  [smoke timings] step summary not written: {exc}")
+            return False
+        return True
+
     def write(self, output_dir: Path):
         self.completed_at = datetime.datetime.now().isoformat()
         output_dir.mkdir(parents=True, exist_ok=True)
@@ -158,6 +386,12 @@ def write(self, output_dir: Path):
         with open(md_path, "w") as f:
             f.write(self.to_markdown())
 
+        # Every report contributes to the standing timing dataset, and to the
+        # Actions step summary when there is one. Both legs (run_python.py and
+        # run.py) reach this same call, so neither needs its own emission.
+        self.write_timings(output_dir)
+        self.append_step_summary()
+
         return json_path
 
 

autohands/run.py

@@ -123,6 +123,13 @@
             project=project,
             directory=directory,
             run_type="notebook",
+            # Same surface statement the script leg has recorded since
+            # PyAutoHeart#83 §5.3. It was missing here, so every notebook
+            # report claimed env_profile "unknown" while running under a
+            # resolved profile — and the timing dataset (PyAutoHands#264)
+            # inherits this field, where an unknown surface makes two runs
+            # incomparable for exactly the reason _surface exists.
+            env_profile=(env_config_path.name if env_config_path else "none"),
         )
         # Only when the policy file exists: with an explicit list it may be
         # absent, and there are then no skip reasons to parse.