From a8b32aa94209d432b5dd20132cd337980856d43e Mon Sep 17 00:00:00 2001 From: Spencer Bryngelson Date: Fri, 18 Sep 2026 00:49:26 -0400 Subject: [PATCH 1/2] Keep Darshan out of the Frontier benchmark, and time where each case goes The Frontier bench has failed on every PR since 2026-09-16, killed by the 2 h limit partway through its seven cases. It is not a workload problem. Comparing a run that passed on 09-15 with one that failed on 09-17, per-target solver times are identical -- ibm simulation 129.1 s against 128.9 s -- and each case still finishes in about 3 minutes. What changed is the gap between one case ending and the next starting: 4 s on 09-15, 14 min 15 s on 09-17, the same to the second on every case. A fixed stall, silent in every log. Nothing in the window explains it: no change to the toolchain run path, the walltime, the modules, or the nodes. Darshan does. Frontier preloads it into every MPI job and it flushes its log in MPI_Finalize, and on the same day its heatmap module asserted in exactly that phase and killed a syscheck outright (seen on #1866). A benchmark has no use for I/O profiling, so this turns it off for frontier and frontier_amd. bench.py now prints, per case, the wall time from launch to return and how much of it fell after the run printed its own End-time. That interval is the one the existing logs never showed, and it distinguishes a slow solver from a process that has finished and is stuck exiting -- so the next such regression is legible whatever its cause, and this one is measurable rather than inferred. An earlier attempt at this sharded the case list across concurrent SLURM jobs to fit the walltime. That was wrong twice over: it treats the symptom, and both shards of a tree build into the same staging directory, so they raced on the generated sources and the build died with FyppFatalError before any benchmark ran. Diagnosing the stall has to come first. --- .github/workflows/common/bench.sh | 15 +++++++++++ toolchain/mfc/bench.py | 44 +++++++++++++++++++++++++++++++ 2 files changed, 59 insertions(+) diff --git a/.github/workflows/common/bench.sh b/.github/workflows/common/bench.sh index 5d108a2a6..0c1ae06b9 100644 --- a/.github/workflows/common/bench.sh +++ b/.github/workflows/common/bench.sh @@ -53,6 +53,21 @@ else bench_cluster="$job_cluster" fi +# --- Frontier: keep Darshan out of the benchmark --- +# Since 2026-09-16 every Frontier bench case has taken ~3 min of solver time and +# ~17 min of wall time, and the job dies on the 2 h limit partway through the list. +# The gap is not in the solver: per-target exec times are identical to runs that +# passed before that date, and bench.py now prints how much of each case's wall +# time falls after the run printed its own End-time. That points at process exit, +# and Frontier preloads Darshan into every MPI job, which flushes its log in +# MPI_Finalize -- the same phase where its heatmap module asserted and killed a +# syscheck the same day. The benchmark has no use for I/O profiling, so turn it +# off here and let the timing say whether that was it. +if [ "$job_cluster" = "frontier" ] || [ "$job_cluster" = "frontier_amd" ]; then + export DARSHAN_DISABLE=1 + echo "Darshan disabled for this benchmark (see bench.sh)." +fi + # --- Run benchmark --- if [ "$job_device" = "gpu" ]; then ./mfc.sh bench --mem 4 -o "$job_slug.yaml" -- -c $bench_cluster $device_opts -n $n_ranks diff --git a/toolchain/mfc/bench.py b/toolchain/mfc/bench.py index 85a182742..5cc667b13 100644 --- a/toolchain/mfc/bench.py +++ b/toolchain/mfc/bench.py @@ -43,6 +43,40 @@ 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 how a case's wall time splits between the run and its exit. + + mfc.sh run prints its own End-time; the difference between that and the moment + the child returned to this process is time spent after the solver was done -- in + MPI_Finalize, a profiler's log flush, or srun step teardown. That interval shows + up nowhere else, which is why a 14-minute stall per case went unexplained. + """ + import datetime + import re + + wall = t_returned - t_launch + ended = None + try: + with open(log_filepath, encoding="utf-8", errors="replace") as f: + for line in f: + 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 ended is None: + cons.print(f"> Wall: [bold]{wall:.0f}s[/bold] launch to return (no End-time in log)") + return + + returned = datetime.datetime.fromtimestamp(t_returned) + end = returned.replace(hour=ended[0], minute=ended[1], second=ended[2], microsecond=0) + if end > returned: # End-time fell before midnight, the return after it + end -= datetime.timedelta(days=1) + after_exit = (returned - end).total_seconds() + cons.print(f"> Wall: [bold]{wall:.0f}s[/bold] launch to return, [bold]{after_exit:.0f}s[/bold] of it after the run printed End-time") + + def bench(targets=None): if targets is None: targets = ARG("targets") @@ -91,6 +125,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 +136,15 @@ 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 ~3 min of solver time and ~17 min + # of wall time, and nothing in any log covers the gap. The run + # prints its own End-time, so the difference between that and + # the moment this call returns separates a slow solver from a + # process that has finished and is stuck exiting. + _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 From 0317d8f50ed10e975cf8399427d5cb61fad1777e Mon Sep 17 00:00:00 2001 From: Spencer Bryngelson Date: Fri, 18 Sep 2026 09:56:43 -0400 Subject: [PATCH 2/2] Measure the Frontier bench stall as startup, not exit The first real measurement refuted the hypothesis this branch started from. Disabling Darshan changed nothing -- the job still died on the time limit at case 6 of 7 -- and the timing showed why it never could have: > Wall: 1037s launch to return, 0s of it after the run printed End-time Darshan flushes its log in MPI_Finalize, which is exit, and exit is 0 s. The missing time is not there. It is before the run starts. Cross-checking the 09-17 logs: ibm.out brackets itself Start-time 14:11:37 to End-time 14:14:43, 186 s, while the bench log shows 1044 s between case starts. I attributed that 858 s difference to process exit on the strength of a figure that came from a synthetic test of my own reporting code, not from Frontier. Measured, it falls before Start-time. So the Darshan change comes out, and the timing now splits three ways rather than two: > Wall: 1037s = 851s startup + 186s run + 0s exit which is where the next question starts: mfc.sh run calls build() on every invocation, and bench.py invokes it once per case, so a per-run build check over Lustre is the first thing to rule in or out -- along with venv and toolchain imports on that filesystem, and srun step launch. --- .github/workflows/common/bench.sh | 15 ---------- toolchain/mfc/bench.py | 46 +++++++++++++++++++------------ 2 files changed, 28 insertions(+), 33 deletions(-) diff --git a/.github/workflows/common/bench.sh b/.github/workflows/common/bench.sh index 0c1ae06b9..5d108a2a6 100644 --- a/.github/workflows/common/bench.sh +++ b/.github/workflows/common/bench.sh @@ -53,21 +53,6 @@ else bench_cluster="$job_cluster" fi -# --- Frontier: keep Darshan out of the benchmark --- -# Since 2026-09-16 every Frontier bench case has taken ~3 min of solver time and -# ~17 min of wall time, and the job dies on the 2 h limit partway through the list. -# The gap is not in the solver: per-target exec times are identical to runs that -# passed before that date, and bench.py now prints how much of each case's wall -# time falls after the run printed its own End-time. That points at process exit, -# and Frontier preloads Darshan into every MPI job, which flushes its log in -# MPI_Finalize -- the same phase where its heatmap module asserted and killed a -# syscheck the same day. The benchmark has no use for I/O profiling, so turn it -# off here and let the timing say whether that was it. -if [ "$job_cluster" = "frontier" ] || [ "$job_cluster" = "frontier_amd" ]; then - export DARSHAN_DISABLE=1 - echo "Darshan disabled for this benchmark (see bench.sh)." -fi - # --- Run benchmark --- if [ "$job_device" = "gpu" ]; then ./mfc.sh bench --mem 4 -o "$job_slug.yaml" -- -c $bench_cluster $device_opts -n $n_ranks diff --git a/toolchain/mfc/bench.py b/toolchain/mfc/bench.py index 5cc667b13..a1d4e09b5 100644 --- a/toolchain/mfc/bench.py +++ b/toolchain/mfc/bench.py @@ -44,37 +44,48 @@ def bench_failure_report(log_filepath: str) -> str: def _report_case_wall(slug: str, log_filepath: str, t_launch: float, t_returned: float) -> None: - """Print how a case's wall time splits between the run and its exit. + """Print where a case's wall time goes: startup, the run itself, and exit. - mfc.sh run prints its own End-time; the difference between that and the moment - the child returned to this process is time spent after the solver was done -- in - MPI_Finalize, a profiler's log flush, or srun step teardown. That interval shows - up nowhere else, which is why a 14-minute stall per case went unexplained. + 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 - ended = None + 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 ended is None: - cons.print(f"> Wall: [bold]{wall:.0f}s[/bold] launch to return (no End-time in log)") + 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) - end = returned.replace(hour=ended[0], minute=ended[1], second=ended[2], microsecond=0) - if end > returned: # End-time fell before midnight, the return after it - end -= datetime.timedelta(days=1) - after_exit = (returned - end).total_seconds() - cons.print(f"> Wall: [bold]{wall:.0f}s[/bold] launch to return, [bold]{after_exit:.0f}s[/bold] of it after the run printed End-time") + + 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): @@ -139,11 +150,10 @@ def bench(targets=None): t_returned = time.time() # Where a case's wall time actually goes. On Frontier since - # 2026-09-16 each case takes ~3 min of solver time and ~17 min - # of wall time, and nothing in any log covers the gap. The run - # prints its own End-time, so the difference between that and - # the moment this call returns separates a slow solver from a - # process that has finished and is stuck exiting. + # 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)