Make the long-running steps narrate themselves: memory, progress, and validate's start line

[gaurav]

Summary

Diagnoses the load's apparently-leaking memory, and makes every long-running step say enough about itself to size the next srun from its own log: load and export gained rate/elapsed/current-RSS on their progress lines (a minute apart, not ten seconds), and validate — previously ~11 minutes of silence — gained a start line, byte-based progress with an ETA, and per-phase lines.

The "memory leak" is two things, neither a leak in our code

A long load was reaching peak RSS 42.1 GiB by file 1201, well above the ~8 GiB slurm/README.md predicted.

1. peak_rss_gib reads ru_maxrss, a high-water mark that only ever rises. Logged once per file it is the maximum over the whole run so far, not that file's footprint — so it climbs by construction and says nothing about what the process currently holds. (Verified: it does not drop after freeing 400 MB.) The docs presented it as a per-file figure, which is only true for the first file.

Each file now logs current RSS beside it, which can fall and is the number that shows real growth:

loaded pubmed26n1201.xml.gz: 30000 articles, 0 deletions, 0 failed to parse (RSS 12.4 GiB, peak 42.1 GiB)

2. DuckDB sizes its buffer pool from the machine, not the allocation. It sets memory_limit to ~80% of physical RAM — 12.7 GiB of a 16 GiB laptop, and hundreds of GB on a cluster node, regardless of --mem=64G. This is the same mistake --threads makes with core count, but more expensive: exceeding a cgroup is an OOM kill, not contention. As the database grows DuckDB caches more of it, RSS climbs run-long, and the job eventually dies with nothing to show for it.

Adds a group-level --memory-limit (PUBMED2DB_DUCKDB_MEMORY_LIMIT) alongside --threads and --temp-dir.

Progress lines size the next job

Previously an ETA and nothing else. Now the rate (what scales to the remaining work) and elapsed (what you compare against the limit you asked for):

progress: 4/360 files this run, 356 remaining · 89.7 s/file · elapsed 5m 59s · ~8h 52m to go
progress: 33,385,000/40,901,984 documents (81.6%) · 29.8k docs/s · elapsed 18m 40s · RSS 187.2 GiB · ~4m 14s remaining

Export gained current RSS too — it is the job that gets OOM-killed, so watching the ramp during the run is what tells you the next --mem.

They also come a tenth as often: the export's gate was 10 s, which over a ~15-minute full-corpus run is ~90 near-identical lines. It is now 60 s, still a dozen-odd points to read the RSS ramp and the rate off.

tqdm was considered and rejected: its \r updates are noise in a Slurm log, and logging already carries the timestamps you'd correlate against sacct.

validate now narrates itself too

It was ~11 minutes of silence, and the two things a run is silently misconfigured on — no database, no API key — only surfaced in the report at the end, by which time an anonymous run has already crawled at 3 req/s:

starting validation: 16 shard(s) in data/json, 42.3 GiB · database available · online with an NCBI API key (10 req/s)
reading shards (structure check)...
progress: 12,480,391 record(s), shard 5/16, 30.4% of 42.3 GiB read · elapsed 3m 04s · RSS 3.1 GiB · ~7m 02s remaining
read 40,901,984 record(s) in 9m 58s (peak RSS 5.2 GiB)
validation finished in 10m 51s (peak RSS 5.2 GiB)

The key itself is never logged, only that one was found. Progress is counted in bytes of shard consumed, not records — the record total is what that pass is computing, and counting shards alone would print nothing at all for the default single-shard export; reading through a raw binary handle keeps the position in the units st_size is in, for gzipped shards as well as plain. Each phase after the read is announced, which is what distinguishes "still reading shards" (local, CPU-bound) from "hung on an NCBI call".

Docs

slurm/README.md gains a Running validate section — sized from what it actually does (one pass over the shards plus a PMID set: measured at 7m 57s and peak RSS 5.2 GiB on the full corpus, so --mem=16G, not the export's 256 GB — and 7m 38s of that 7m 57s is the shard read, which is why issue #13 exists), plus the Slurm-specific parts: the online checks need outbound HTTPS from the compute node, the exit status is what gates a batch script, and the manifest has to be kept between runs. It also gets the real command (--mem=64G --time=24:00:00), a section on reading the two memory figures, and why the memory limit is the knob to lower rather than raising --mem. Root README.md and CLAUDE.md list the third knob.

Also closes a known coverage gap

--limit's newest-N slice and the --verify gating had no tests, because _sync_kind needs _ensure_urls, requests.get and ensure_module.ensure all stubbed. Both are covered now, and both were mutation-tested: reverting the slice to urls[:limit] or un-gating verify fails the respective test.

Verification

• 107 tests pass, 1 skipped (the /proc current-RSS check, which is expected to skip on macOS and always runs on the cluster).
• New tests/test_util.py pins the peak-vs-current distinction directly: that peak_rss_gib does not fall after memory is freed, and that current_rss_gib is either None or a plausible value at or below the high-water mark.
• --memory-limit is asserted to actually shrink DuckDB's default rather than sit alongside it, comparing parsed byte values (DuckDB reports 1GB back as 953.6 MiB).

Not verified

The DuckDB explanation is a strong inference from its documented default plus the 12.7-of-16 GiB reading locally — it has not been confirmed on the cluster. Running SELECT current_setting('memory_limit') inside a job would settle it: if it comes back sized to the node rather than to --mem, the diagnosis holds. The suggested 48GB under --mem=64G is a starting point, not a measured optimum — too low trades OOM risk for spilling, which shows up as a collapsed s/file rate.

TODO

• Confirm DuckDB's memory_limit on the cluster. The "Not verified" section above rests on this. Inside a real job: uv run python -c "import duckdb; print(duckdb.connect().execute(\"SELECT current_setting('memory_limit')\").fetchone())". If it comes back sized to the node rather than to --mem, the diagnosis holds and the --memory-limit default guidance is right. If it already reflects the cgroup, the memory story here needs rethinking before merge.
• Tune PUBMED2DB_DUCKDB_MEMORY_LIMIT against a real load. 48GB under --mem=64G is a starting point, not a measurement. Watch the new RSS figure: if it plateaus below the cap and the s/file rate holds, it is about right; if the rate collapses, DuckDB is spilling and the cap is too low.

🤖 Generated with Claude Code