Record time as well as money for every non-free run (#143)

[jonfroehlich]

Closes #143 (except the Tillicum back-fill — see Blocked below).

We recorded money for paid APIs and nothing else. This adds the other three quadrants:
time for paid legs, time for free GPU legs, and money+time for cluster compute — and fixes
the defect the comment on #143 identified, which was actively losing data.

The bug that was live

DEFAULT_USAGE_LOG derived from REPO_ROOT, which in a linked worktree is the worktree. A
leg run from a scratch worktree wrote its ledger there and lost it when the worktree was
removed. That is how the #139 claude-opus-5 leg spent $70.41 and left no row.

#119's guard cannot see this, and the reason matters: it proves a log path was accepted,
never that the file it wrote survives. The operator followed the rule and lost the record
anyway, so promoting the rule into CLAUDE.md would not have caught it either.

Both ledgers now resolve through git rev-parse --git-common-dir, which every worktree of a
repo shares, so they all append to one canonical file in the main checkout. An explicit
--usage-log into a worktree warns; each logged leg prints the absolute path and the
running total; and it falls back to the local checkout when git can't answer (a tarball, an HF
clone) — bookkeeping must never be why a run refuses to start.

What else changed

Time is measured. There was no perf_counter anywhere in the harness. score_model now
fills a caller-owned timing dict (model-load / inference / panos actually called) and main
stops the clock in the finally, so a leg that dies partway still reports what it spent.
panos_called counts attempts — a call that raised burnt wall-clock and, on a paid provider,
still billed.

Free legs are no longer invisible. report_usage returned early whenever a detector had no
usage dict — i.e. OWLv2, Grounding DINO, Qwen, Molmo, YOLO, the entire GPU half of the
roster. They now write the same row with paid: false. Two legs deliberately write nothing: a
fully cached re-score, and --models rampnet, which replays committed detections rather than
running a model.

#139's recovered $70.41 is in the ledger, as a row marked kind: "recovered" carrying the
billed total minus what the surviving rows already account for. Cost totals include it —
omitting it under-reported this benchmark's Claude spend by ~200x — while reconciliation never
counts it as a measurement.

A compute ledger. scripts/analysis/slurm_usage.py → analysis_out/compute_log.jsonl,
priced from a new verified-only COMPUTE_PRICING in pricing.py. Back-filled from a real
sacct pull: 3,991 allocations, 2,684.4 GPU-hours on klone since 2026-07-02, with the raw
dump committed so it re-derives without a cluster account.

Reconciliation. vertex_usage.py --reconcile compares the committed ledger against Cloud
Monitoring per model. This is the only check that catches a silent no-write. On the real #139
numbers, before the recovery row existed it reports claude-opus-5 UNDER with 11,940,249
input tokens unexplained — the two richmond smoke legs (48,744 tokens) are logged — and with
that row committed it reports ok (1 recovered). A recovered row is still never counted as a
measurement; it is totalled in its own column and subtracted before the verdict, so the one gap
this PR closes is not re-raised as an emergency on every run.

The rule is now repo-level, in CLAUDE.md beside replication and record-in-GitHub: both
units, both cost types, ledgers committed into the main checkout.

Finding: sacct -D is worth 4.35x

96% of our klone allocations end in PREEMPTED (3,780 of 3,991), so the default sacct view —
last incarnation only — discards nearly everything:

#51 YOLO baseline	rows	GPU-hours
sacct -D	3,857	2,046.9
without -D	27	470.5

It validates the one figure the repo already had. docs/tillicum.md records 496.5
GPU-hours as of 2026-07-30; summing this ledger over jobs ending from 07-24, the running
total crosses 496.5 at 2026-07-29T21:17 — the evening before that line was written.

Blocked

• Tillicum is not back-filled. Duo-gated and the control master was down. One command once
  it's up; the gap is stated in docs/compute_cost.md next to the numbers, not left implicit.

Overlap

Touches the same section of docs/model_comparison.md as
data/claude-opus-5-nine-splits-139, in a different hunk (that branch narrates the incident;
this one documents the mechanism and the fix). Should merge clean.

Tests

44 new, 1,340 passing (1 skipped), still CPU-only and network-free. The reconciliation tests
use the real #139 numbers; the compute tests are checked against docs/tillicum.md's
independently-derived $4.20 / 4.67 GPU-h.

🤖 Generated with Claude Code (claude-opus-5[1m])

[jonfroehlich]

Deep review

Re-ran everything from the branch head (37b7faa) in a clean detached worktree on Windows. The mechanism is right and the artifacts reproduce. Three independent checks came back clean:

• Full suite: 1335 passed, 1 skipped (the body says 1,334; the last commit added one).
• analysis_out/compute_log.jsonl regenerates byte-for-byte from the committed sacct_klone_2026-08-19.txt once recorded_at is re-stamped (3,991 rows, LF only, zero duplicate (cluster, job id, start) keys). Every number in docs/compute_cost.md re-derives: 2,684.4 GPU-h; 3,780/3,991 PREEMPTED; YOLO 3,857 rows / 2,046.9 GPU-h vs 27 / 470.5 without -D = 4.35x; GPU types 2,194 / 1,285 / 456 / 23 / 6 / 1 by allocation; 28 sal-*/arch_* rows = 34.3 GPU-h = 1.28%; RampNet-only 2,650.0; the 496.5 GPU-h running total crosses at 2026-07-29T21:17:10. All exact.
• canonical_repo_root traced from the main checkout root (git prints .git), a main subdirectory (../.git), a scratchpad worktree root and subdirectory, and a .claude/worktrees/ nested worktree (all print the absolute common dir): every one resolves to D:\Git\RampNet. A non-git temp dir, a nonexistent path, and an empty PATH all fall back to start without raising.
• Merging this branch onto main, onto data/claude-opus-5-nine-splits-139 (claude-opus-5 on nine splits: the annapolis displacement does not generalise (#139) #146), and onto main + claude-opus-5 on nine splits: the annapolis displacement does not generalise (#139) #146 in sequence: all three clean, no conflict in docs/model_comparison.md.

So what follows is about the half of the design the code does not yet implement, and about text that went stale between commits.

---

1. Medium — the compute ledger's idempotency is half-implemented: superseded rows are re-appended but never de-duplicated by any reader

slurm_usage.py:38-40 and new_rows (line 173) promise: "A job first recorded while RUNNING is re-appended once it reaches a terminal state; readers take the last row per key." No reader does. summarize (189), print_by_name (206), main's "Ledger now holds" (322) and ledger.ledger_totals (106) sum every row.

Reproduced with the test fixture's own shapes: a job parsed RUNNING at 3,600 s, then COMPLETED at 18,000 s → new_rows correctly re-appends → summarize(existing + fresh) reports 6.0 GPU-h for a 5.0 GPU-h job. The committed ledger is unaffected today only because the 2026-08-19 pull happened to contain no RUNNING rows (one PENDING row, 38640313, at start=Unknown, 0 GPU-h, which will get a new key when it starts and so never collides). The first re-pull after any job is caught mid-run double counts it in every total the script prints.

Fix: a latest_rows(rows) in slurm_usage.py that keeps the last row per row_key, applied in summarize, print_by_name and before the "Ledger now holds" summary. Do not put the dedupe in ledger.ledger_totals keyed on row_key: usage_log.jsonl rows have no job_id, so they would all collapse to one key. Add a test that asserts 5.0.

2. Medium — once a recovery row exists, --reconcile reports the recovered gap as an unexplained emergency, forever

ledger_totals_by_model skips RECOVERED rows by design (vertex_usage.py:117), and the docstring's reason is right: a recovered row must not make the bill agree with itself. But the output does not distinguish "billed more than we measured, and nobody has looked" from "billed more than we measured, and the gap is already in the ledger as a recovery." Run against the committed ledger on this branch with the real #139 bill:

claude-opus-5   billed 11,988,993   logged 48,744   rows 2   UNDER — ledger short
1 model(s) billed more than the ledger records (11,940,249 input tokens unaccounted for).
A missing layer-1 row is an emergency with a deadline ...

That 11,940,249 is exactly the recovered row's input_tokens. The check the PR adds will say "emergency" about the one gap this PR closed, every time it is run inside the window. An operator will learn to ignore it, which defeats the check.

Fix: have ledger_totals_by_model also total input/output of RECOVERED rows per model under a separate key (recovered_input), keep them out of logged_input, and have reconcile compute unexplained = billed − logged − recovered. Verdict ok (N recovered) when the remainder is within tolerance, UNDER only on the unexplained part; print_reconciliation prints the recovered column and totals the unexplained gap. The existing asymmetry and the "never compare the bill to itself" rule both survive: measured rows still have to account for the bill minus what was explicitly written down as unmeasured.

3. Medium-low — the read side of the worktree fix was not done: .env is still loaded from the worktree

Both entry points still read the repo-root .env from the running file's checkout: compare.py:836 (load_dotenv(str(REPO_ROOT))) and vertex_usage.py:54 (load_dotenv(str(REPO))). #146's write-up already documents the consequence: "Run vertex_usage.py from a worktree and it exits with 'no project'". So the tool that recovers a lost spend still cannot find the project id from the place a leg is most likely to have been run, and a Gemini/Claude leg from a worktree finds no key unless the operator copies .env. The PR body says "Both ledgers now resolve through git rev-parse --git-common-dir"; the credentials do not.

Fix: load .env from canonical_repo_root() as well as REPO_ROOT (the loader's setdefault semantics make loading both harmless; worktree first so a deliberate local override still wins). One line in each file, one test using the same git worktree add fixture as test_the_ledger_resolves_to_the_main_checkout_from_a_worktree.

4. Low — REQUEUED is a finished incarnation but is classed as non-terminal

TERMINAL_STATES (line 72) omits REQUEUED. The committed dump has 59 REQUEUED rows, all with an End time and elapsed > 0, carrying 848.5 GPU-h (e.g. 37745358, 29,072 s, 1 GPU). They are counted correctly today because they were first seen in that state. The path that goes wrong: a job recorded while RUNNING, then requeued rather than preempted, is never re-appended, so its row keeps the understated elapsed. Fix: add REQUEUED to TERMINAL_STATES; the (job id, start) key already separates it from the next incarnation.

5. Low — the PR body is stale relative to its own last commit, and one claim in it is wrong

• "Blocked: Run claude-opus-5 (effort low) on the nine remaining splits: the only model that ever beat the top challenger has 1/10 coverage #139's recovered $70.41 is not in the ledger as a row" — 37b7faa added it (usage_log.jsonl line 4, kind: "recovered").
• "on the real Run claude-opus-5 (effort low) on the nine remaining splits: the only model that ever beat the top challenger has 1/10 coverage #139 numbers it reports claude-opus-5 MISSING with 11,988,993 input tokens unaccounted for" — against the committed ledger it reports UNDER with 11,940,249, because the two richmond smoke legs (48,744 tokens) were logged. MISSING is only what the test fixture with no opus rows produces.
• "39 new, 1,334 passing" — 1,335 on the head.

Fix: edit the body (gh pr edit 147 --body-file), moving the recovery row out of "Blocked" and correcting the verdict and the count.

6. Low — two doc lines aged between commits

• docs/replication.md:20: "back-fill pending" — klone is back-filled on this branch (3,991 rows); only Tillicum is pending. Say which.
• docs/compute_cost.md:52: rampnet_cosine_rung_135 "still in flight" — true of the 2026-08-19 pull, not of the ledger as a statement. Add "as of the 2026-08-19 pull", or the sentence will read as wrong the day the rung finishes (it has, on analysis/run-b-power-135).

7. Low — CLAUDE.md overstates the token pricing table

Line 66: rates carry "the date it was checked and the page it came from". The COMPUTE_PRICING entries do carry a source; the token PRICING rows carry as_of and a note, no source. Either add source to the token rows or say "date checked" only.

8. Low — one phrase not in the repo's register

rampnet/ledger.py:34: "the difference is load-bearing". Say what it is: "the difference matters for reconciliation".

---

Decisions for Jon, not fixes

• The ledger now lands in whatever branch the main checkout has checked out. That is the point of the fix, but it has a consequence the doc does not state: the row is safe from deletion yet is written into an uncommitted working tree on whatever unrelated branch the main checkout happens to be on. The experiment's own PR has to carry that row, so the finishing step is "copy the new line(s) into the experiment branch and commit", not "commit the ledger". Worth one sentence in CLAUDE.md's "A ledger is not a commit" bullet.
• The recovered row's est_cost_usd (70.095) is the token delta priced at list, not billed_usd − already_logged_usd (70.0975). The ledger sums to $70.4375 against a $70.44 bill. Immaterial, but the row's note says "the BILLED total minus what the surviving rows already account for" and that is true of the tokens, not the dollars. Your call whether to leave it.
• Whether the report_usage totals line should count free-leg hours. ledger now: … 0.0 h will start climbing once GPU legs write rows; it mixes API wall-clock and GPU wall-clock in one number. Fine as a visibility line, not a cost figure.

What holds up

• The bug is real and the fix is the right shape. --git-common-dir is the one thing every worktree shares; the fallback to start on any failure means bookkeeping cannot stop a run; the warning on an explicit --usage-log into a worktree fires only when the two roots differ.
• Timing is measured where it has to be. The clock stops in main's finally, so a leg that raised after paying still records; panos_called increments in a finally inside the loop so continue and break are both counted; a fully cached leg and --models rampnet are the only silent cases and both are tested.
• sacct -D is worth 4.35x, and the 496.5 cross-check is exact to the minute. The generic-over-typed GPU count is correct for this dump (3,965 rows report both forms, 26 report neither), and no (cluster, job id, start) key collides.
• Recovered rows are excluded from reconciliation for a correct reason — the fix in finding 2 keeps that reason and changes only what the report says about a gap that is already written down.
• The compute pricing is sourced (Tillicum page + provisioning email + sacctmgr, with the debug/hyakusage disagreement carried in the row's note rather than dropped).
• Clean merge onto main, onto claude-opus-5 on nine splits: the annapolis displacement does not generalise (#139) #146, and onto both in sequence.

Fix list

• [F1] Medium — slurm_usage.py: add latest_rows() (last row per row_key), use it in summarize, print_by_name and before the "Ledger now holds" summary; test that RUNNING→COMPLETED sums to 5.0 not 6.0. Keep ledger.ledger_totals as is (usage rows have no job_id). — files: scripts/analysis/slurm_usage.py, tests/test_slurm_usage.py
• [F2] Medium — vertex_usage.py: total RECOVERED rows per model separately (recovered_input/recovered_output), keep them out of logged_*, compute unexplained = billed − logged − recovered, verdict ok (N recovered) when the remainder is within tolerance, and print the recovered column and the unexplained gap; update test_a_recovered_row_counts_toward_cost_but_never_toward_reconciliation and test_vertex_usage.py to assert the real committed-ledger outcome (UNDER 11,940,249 without the row; ok-with-recovery once it is written). Update the "Reconcile" paragraph in docs/model_comparison.md and the CLAUDE.md bullet to say the check distinguishes an unexplained gap from a recorded recovery. — files: scripts/analysis/vertex_usage.py, tests/test_vertex_usage.py, tests/test_model_comparison.py, docs/model_comparison.md, CLAUDE.md
• [F3] Medium-low — load .env from canonical_repo_root() after REPO_ROOT in compare.py:836 and from ledger.canonical_repo_root(REPO) in vertex_usage.py:_load_dotenv; one test with the worktree fixture. Mention in docs/model_comparison.md "The ledger has to outlive the run" that credentials resolve the same way now. — files: scripts/model_comparison/compare.py, scripts/analysis/vertex_usage.py, tests/test_model_comparison.py, docs/model_comparison.md
• [F4] Low — add REQUEUED to TERMINAL_STATES; assert is_terminal("REQUEUED") in the terminal-states test. — files: scripts/analysis/slurm_usage.py, tests/test_slurm_usage.py
• [F5] Low — gh pr edit 147 --body-file: move the $70.41 row out of "Blocked" (it is in as kind: recovered, commit 37b7faa), change "MISSING with 11,988,993" to "UNDER with 11,940,249 (the two richmond smoke legs are logged)", and the test count to whatever the suite reports after F1–F4. — files: PR body only
• [F6] Low — docs/replication.md:20 → "klone back-filled 2026-08-19 (3,991 rows); Tillicum pending"; docs/compute_cost.md:52 → "still in flight as of the 2026-08-19 pull". — files: docs/replication.md, docs/compute_cost.md
• [F7] Low — CLAUDE.md:66: "the date it was checked and, for compute, the page it came from" (or add source to the token PRICING rows in pricing.py). — files: CLAUDE.md (or scripts/model_comparison/pricing.py)
• [F8] Low — rampnet/ledger.py:34: replace "the difference is load-bearing" with "the difference matters for reconciliation". — files: rampnet/ledger.py

🤖 Generated with Claude Code (claude-fable-5-1)

[jonfroehlich]

Review fixes

• F1 — fixed in b190da0. latest_rows() keeps the last row per (cluster, job id, start), and summarize() and print_by_name() now read through it, so the "Ledger now holds" summary does too. Without it a job first recorded RUNNING and re-appended once finished was billed twice: 6.0 GPU-hours for a 5.0-hour job. ledger.ledger_totals is unchanged, as the review asked — usage_log.jsonl rows carry no job_id. Regenerating analysis_out/compute_log.jsonl from the committed sacct dump gives the same 3,991 rows, identical apart from the recorded_at stamp the script re-writes, so the committed ledger is untouched.
• F2 — fixed in 749d345. ledger_totals_by_model totals RECOVERED rows under recovered_input/recovered_output/recovered_rows, still outside logged_*; reconcile verdicts on billed − logged − recovered and reports ok (N recovered) when the remainder is inside tolerance; print_reconciliation prints a recovered column and totals the unexplained gap. Against the committed ledger and the real Run claude-opus-5 (effort low) on the nine remaining splits: the only model that ever beat the top challenger has 1/10 coverage #139 bill this now reads ok (1 recovered) instead of raising the same 11,940,249-token emergency on every run. The rule that a recovered row never makes the bill agree with itself is unchanged — it is not counted as a measurement. docs/model_comparison.md and the CLAUDE.md bullet say so, and the rampnet/ledger.py docstring was brought in step in aa4a142.
• F3 — fixed in baf0b49. New compare.load_dotenv_for_run() loads .env from the running checkout and then from canonical_repo_root(); compare.main and vertex_usage._load_dotenv both use it. setdefault semantics mean the worktree's own file is read first and still wins. Tested with the same git worktree add fixture, now factored into a _main_and_worktree helper, and noted in docs/model_comparison.md under "The ledger has to outlive the run".
• F4 — fixed in b190da0. REQUEUED added to TERMINAL_STATES with is_terminal("REQUEUED") asserted. The 59 REQUEUED rows in the committed dump (848.5 GPU-hours) were already counted correctly; the path this closes is a job recorded while RUNNING and then requeued, which was never re-appended and kept its understated elapsed.
• F5 — done: PR body edited. The recovered row moved out of Blocked, the reconciliation verdict corrected, and the test count updated. The verdict sentence states both cases, because F2 changed what the check says: UNDER with 11,940,249 before the recovery row existed (the two richmond smoke legs, 48,744 tokens, are logged), ok (1 recovered) with it committed.
• F6 — fixed in fbba3b7. docs/replication.md now says klone back-filled 2026-08-19 (3,991 rows), Tillicum pending; docs/compute_cost.md dates the cosine rung's status to the 2026-08-19 pull.
• F7 — fixed in fbba3b7. CLAUDE.md now says "the date it was checked and, for compute, the page it came from" — only COMPUTE_PRICING carries a source.
• F8 — fixed in fbba3b7, with the surrounding paragraph reflowed in aa4a142.

Nothing was skipped; every finding held up when checked against the code. Full suite: 1,340 passed, 1 skipped (was 1,335/1), CPU-only and network-free.

🤖 Generated with Claude Code (claude-opus-5)