Correct where babel-slurm-resources gets its wall times, and what a retry does to them

[gaurav]

docs/tools/Resources.md said babel-slurm-resources reads "elapsed wall time" from the SLURM efficiency report, and that the per-rule logs' start/end timestamps feed the sizing. Checking the code, neither is true.

Every duration the report prints — the runtime-fit percentage, the recommendation, the "slowest rule still on the default" line, the tables and the CSV — comes from Benchmark.seconds, which read_benchmarks() takes from the benchmark TSV's s column (per-column worst case across a rule's rows). EfficiencyRow.elapsed_sec is parsed and merged across shards but read by nobody; the logs contribute their declared resources: line and nothing else.

The distinction is not cosmetic, and getting it right took measuring rather than reasoning. A run records a job's duration over three different spans: the benchmark's s (the rule's execution, timed from inside the job), sacct's Elapsed_sec (job start → end), and babel-slurm-errors' figure (submit → finish, so it includes time spent pending in the queue). Across the run under data/: Elapsed_sec ≥ s for 57 of 57 rules, median +5s — job setup and teardown; and submit→finish exceeded Elapsed_sec by a median of 35s, max 306s, over 60s for 15 rules. --time polices Elapsed, so sizing from s understates the policed span slightly, which is an argument against trimming a runtime to a hair above the benchmark.

What a retry, or a second run, does to each number

A Babel build takes several sbatch runs and retries rules inside each, so "how long did this rule take" has three answers. Measured across the 2026jul22 and babel-1.17 builds (21 rules there have both failed and successful attempts):

• Benchmarks — the last successful execution, nothing else. Snakemake rewrites the TSV per execution (all 355 files in 2026jul22 hold one row) and writes none at all for a failed job: the two rules whose every attempt failed left no file. A rule that died at 30s and then succeeded in 2h reports 2h, with no averaging. leftover_umls on babel-1.17: failed at 9885s, 17254s, 2148s, succeeded at ~2367s, benchmark 2292s. The per-column max in read_benchmarks() therefore only fires for repeat().
• Two consequences for a multi-run build: the benchmark set is a mixture (each rule's numbers come from whichever run last succeeded at it), and a success is sticky — a rule that succeeded in run 1 and failed in run 3 still reports run 1's numbers.
• Efficiency report — per-column max over every attempt, failures included. Rows are per job step (53155.0, .1, …), several per attempt, and no state column is consulted. Harmless for the two fields consumed, and one more reason Elapsed_sec is the wrong source for a duration: a job killed at its time limit would win the max.
• babel-slurm-errors — one entry per attempt, marked failed or not; the only one of the three that can say a rule failed twice before it worked.

This turned up a real bug in that third tool — a failed attempt's reported duration is the time from submit to the end of the whole run (process_ec_ids: died in 39s, reported 84,260s), because Snakemake logs Error in rule a second time in its end-of-run summary and parse_job_events() keeps the later timestamp. Fixed separately in #1020; nothing in this PR depends on it.

What changed

• The docs now say what the code does, in the three places that were wrong: the artifacts list (the logs bullet), "Why the benchmark TSVs, not the efficiency report" (the efficiency report supplies RequestedMem_MB and NCPUS, those two columns and no others), and a new "Three clocks, and which one a time limit polices" section giving the table above with its measured gaps — so the next person comparing a babel-slurm-errors duration against an Elapsed_sec knows why they differ. src/tools/slurm/CLAUDE.md gets the one-line version, since that is where someone touching the parser looks first.
• EfficiencyRow.elapsed_sec is kept, and now explains itself. An earlier commit on this branch deleted it as dead data; that was the wrong lever. The docs drifted because they claimed the field was used, not because it existed, and the column is reliable (unlike MaxRSS/TotalCPU here) with a meaning worth keeping wired up. EfficiencyRow's docstring now states which two fields are consumed and why each of the others is deliberately kept — max_rss_mb/total_cpu_sec read 0 on a cluster without per-step accounting, so a non-zero one is the signal that Hatteras started recording it.
• A second new section, "What a retry, or a second run, does to each number", records the multi-run findings above, with the same points condensed onto read_benchmarks() and read_efficiency_report() — those docstrings are where someone lands when they wonder whether a number survived a retry.
• A test pins the real source: test_wall_time_comes_from_the_benchmark_not_the_efficiency_report builds a run whose efficiency report disagrees with the benchmark by two orders of magnitude (99999s vs 100s) and asserts the recommendation reports 100.

Unread data is not automatically dead, but it isn't automatically safe either

Two kinds, and this PR treats them differently:

• Named columns read into a float — elapsed_sec, max_rss_mb, total_cpu_sec on EfficiencyRow. These cannot quietly start meaning something else, and if the cluster begins populating the usage columns they are already correct. Kept, with a docstring saying which two fields are consumed and why each of the rest earns its line.
• Regexes over free-form log text — RuleLog.start/end/failed, from _BRACKET_TS_RE and _FAILURE_RE. These rot silently when Snakemake changes its output, and no test can prevent it: a fixture pins the format it was copied from, not the one the cluster emits next year. Removed, and replaced by a comment above RuleLog giving the recipe — the bracketed-timestamp format and the fact that the span is the job's own execution (so it tracks s, not Elapsed), the three failure markers and the fact that they must be checked in every attempt's log rather than the newest, a real log to look at, and a pointer to parse_job_events() as the better source anyway.

Deleting them takes _BRACKET_TS_RE, _FAILURE_RE and _parse_bracket_timestamps() with them — no other caller — and lets read_rule_logs() read one log per rule instead of every retry's log in full, which it was doing solely to compute the unread failed flag.

The rule-log test keeps its verbatim fixture from logs/rule_process_ec_ids/52504.log (babel-1.18, 2026-07-13), because the point it proves is still live: a real resources: line reads disk_mb=50000, disk=50 GB, disk_mib=47684, mem_mb=16000, mem=16 GB, mem_mib=15259, so mem_mib and disk_mb sit right beside the value _MEM_RE has to pick out. The fixture it replaced had neither. Re-verified after the change: all 5 real logs under data/logs parse with mem_mb populated.

Checks

uv run pytest -m unit -q — 507 passed. ruff check, ruff format --check, rumdl check clean.

🤖 Generated with Claude Code

[Copilot]

Pull request overview

Corrects SLURM resource-sizing documentation and removes unused elapsed-time parsing.

Changes:

• Documents benchmark TSVs as the wall-time source.
• Removes EfficiencyRow.elapsed_sec.
• Adds regression coverage for wall-time selection.

Reviewed changes

Copilot reviewed 4 out of 4 changed files in this pull request and generated 3 comments.

File	Description
docs/tools/Resources.md	Clarifies timing sources and semantics.
src/tools/slurm/CLAUDE.md	Updates maintainer guidance.
src/tools/slurm/parse.py	Removes unused elapsed-time parsing.
tests/tools/slurm/test_resources.py	Tests benchmark-derived wall time.

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[Copilot]

Pull request overview

Copilot reviewed 5 out of 5 changed files in this pull request and generated no new comments.

Suppressed comments (2)

tests/tools/slurm/test_resources.py:55

• This docstring contradicts both the implementation and the new documentation: sacct's Elapsed_sec excludes queue time, and read_efficiency_report() still parses it into EfficiencyRow. Please describe the allocation span and the deliberately retained field accurately.

    The two measure different things -- Snakemake times the job from the inside, SLURM times the
    allocation -- so a report mixing them would size a time limit against a number that includes
    queue time. The docs claimed the efficiency report's elapsed column was used; it never was, and
    it is no longer even parsed.

src/tools/slurm/CLAUDE.md:11

• This still leaves contradictory guidance in two places: read_efficiency_report() parses five report columns, so these are only the two columns it consumes, while src/tools/slurm/__init__.py:15 retains the old claim that elapsed wall time is consumed from the efficiency report. Please change “reads” to “consumes” here and correct the package docstring as part of this documentation fix.

columns. Wall time too: every duration `babel-slurm-resources` reports is the benchmark's `s`
column, and the only efficiency-report columns it reads are `RequestedMem_MB` and `NCPUS`.