feat: time each step in the pipeline summary

scripts/pipeline.py

@@ -62,6 +62,27 @@ from common import (
 from refresh_data_dirs import hold_data_dirs
 
 
+class StepResults(dict):
+    """The outcome of each step, and how long it took.
+
+    A step's time runs from the previous step's outcome to its own, so the
+    in-process steps (consistency, the truth diff) are timed like the ones
+    run() launches. The summary prints it: finding the slow step in a
+    twenty-minute run meant reading the whole log.
+    """
+
+    def __init__(self, start: float) -> None:
+        super().__init__()
+        self.seconds: dict[str, float] = {}
+        self._mark = start
+
+    def __setitem__(self, step: str, outcome: object) -> None:
+        now = time.monotonic()
+        self.seconds[step] = self.seconds.get(step, 0.0) + now - self._mark
+        self._mark = now
+        super().__setitem__(step, outcome)
+
+
 def run(cmd: list[str], label: str) -> tuple[bool, str]:
     """Run a command, echoing its output as it comes. Returns (success, output).
 
@@ -384,9 +405,9 @@ def main() -> None:
             print(f"ERROR: {exc}")
             sys.exit(1)
 
-    results = {}
     all_ok = True
     total_start = time.monotonic()
+    results = StepResults(total_start)
 
     # Step 1: Generate database
     ok, out = run(
@@ -709,10 +730,10 @@ def main() -> None:
     print(f"\n{'=' * 60}")
     for step, outcome in results.items():
         if outcome is SKIPPED:
-            label = "SKIPPED"
-        else:
-            label = "OK" if outcome else "FAILED"
-        print(f"  {step:.<40} {label}")
+            print(f"  {step:.<40} SKIPPED")
+            continue
+        label = "OK" if outcome else "FAILED"
+        print(f"  {step:.<40} {label:<7}{results.seconds[step]:>8.1f}s")
     print(f"  {'total':.<40} {total_elapsed:.1f}s")
     print(f"{'=' * 60}")
     print(f"  Pipeline {'COMPLETE' if all_ok else 'FINISHED WITH ERRORS'}")

tests/test_audit_regressions.py

@@ -5100,5 +5100,23 @@ class TheGroundTruthFooterSaysWhatItCounts(unittest.TestCase):
         self.assertNotIn("0/81", text)
 
 
+class ThePipelineSummaryTimesEachStep(unittest.TestCase):
+    """The summary gave OK per step and one total: the slow step of a
+    twenty-minute run could only be found by reading the log."""
+
+    def test_each_outcome_carries_its_time(self):
+        from unittest import mock
+
+        clock = iter([10.0, 12.5, 12.5, 20.0])
+        with mock.patch.object(pipeline.time, "monotonic", lambda: next(clock)):
+            results = pipeline.StepResults(pipeline.time.monotonic())
+            results["generate_db"] = True
+            results["refresh_data"] = pipeline.SKIPPED
+            results["verify"] = True
+        self.assertEqual(results.seconds, {"generate_db": 2.5, "refresh_data": 0.0, "verify": 7.5})
+        self.assertEqual(dict(results), {"generate_db": True, "refresh_data": pipeline.SKIPPED,
+                                         "verify": True})
+
+
 if __name__ == "__main__":
     unittest.main()