diff --git a/toolchain/mfc/bench.py b/toolchain/mfc/bench.py index 85a182742..a1d4e09b5 100644 --- a/toolchain/mfc/bench.py +++ b/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