Measure where the Frontier benchmark's time actually goes

toolchain/mfc/bench.py

@@ -43,6 +43,51 @@ def bench_failure_report(log_filepath: str) -> str:
     return summary or log_tail(log_filepath)
 
 
+def _report_case_wall(slug: str, log_filepath: str, t_launch: float, t_returned: float) -> None:
+    """Print where a case's wall time goes: startup, the run itself, and exit.
+
+    mfc.sh run brackets its own work with a Start-time and an End-time, so those two
+    stamps split the interval this process measures into three. Worth having because
+    the split is not where it looks: on Frontier a case takes ~17 min of which the
+    solver is ~3, and the first measurement of this put essentially all the remainder
+    before Start-time -- in startup, not in the exit it had been attributed to.
+    """
+    import datetime
+    import re
+
+    wall = t_returned - t_launch
+    started = ended = None
+    try:
+        with open(log_filepath, encoding="utf-8", errors="replace") as f:
+            for line in f:
+                m = re.search(r"Start-time\s+(\d\d):(\d\d):(\d\d)", line)
+                if m:
+                    started = tuple(int(x) for x in m.groups())
+                m = re.search(r"End-time:\s+(\d\d):(\d\d):(\d\d)", line)
+                if m:
+                    ended = tuple(int(x) for x in m.groups())
+    except OSError:
+        pass
+
+    if started is None or ended is None:
+        cons.print(f"> Wall:    [bold]{wall:.0f}s[/bold] launch to return (no Start/End-time in log)")
+        return
+
+    returned = datetime.datetime.fromtimestamp(t_returned)
+
+    def _before_return(clock):
+        stamp = returned.replace(hour=clock[0], minute=clock[1], second=clock[2], microsecond=0)
+        if stamp > returned:  # the stamp fell before midnight, the return after it
+            stamp -= datetime.timedelta(days=1)
+        return stamp
+
+    begin, finish = _before_return(started), _before_return(ended)
+    startup = (begin - datetime.datetime.fromtimestamp(t_launch)).total_seconds()
+    solver = (finish - begin).total_seconds()
+    exiting = (returned - finish).total_seconds()
+    cons.print(f"> Wall:    [bold]{wall:.0f}s[/bold] = [bold]{startup:.0f}s[/bold] startup " f"+ {solver:.0f}s run + {exiting:.0f}s exit")
+
+
 def bench(targets=None):
     if targets is None:
         targets = ARG("targets")
@@ -91,6 +136,7 @@ def bench(targets=None):
             try:
                 for attempt in range(1, max_attempts + 1):
                     try:
+                        t_launch = time.time()
                         with open(log_filepath, "w") as log_file:
                             result = system(
                                 ["./mfc.sh", "run", case.path] + ["--targets"] + [t.name for t in targets] + ["--output-summary", summary_filepath] + case.args + ["--", "--gbpp", str(ARG("mem"))],
@@ -101,6 +147,14 @@ def bench(targets=None):
                                 # was previously reported as a bare address.
                                 env=fault_diagnostic_env(dict(os.environ)),
                             )
+                        t_returned = time.time()
+
+                        # Where a case's wall time actually goes. On Frontier since
+                        # 2026-09-16 each case takes ~17 min of wall time against ~3 min
+                        # of solver, and no log covers the difference. The run brackets
+                        # itself with Start-time and End-time, which splits the interval
+                        # into startup, run and exit.
+                        _report_case_wall(case.slug, log_filepath, t_launch, t_returned)
 
                         # Check return code (handle CompletedProcess or int defensively)
                         rc = result.returncode if hasattr(result, "returncode") else result