[MEDIUM] perf(approve): batch approval-log and HMAC-ledger writes per commit

[elhoim]

BLUF

• Committing 1000 dispositions drops from 27.78 s to 0.11 s (254x) on ext4 — approvals.jsonl 14.47 s -> 0.046 s (311x), HMAC ledger 13.30 s -> 0.046 s (291x).
• Growth driver is N = items disposed in one commit, not ledger length: vhir approve --review reads pending-reviews.json uncapped and adds auto-coupled timeline events and cascaded IOCs, so a portal sweep commits hundreds to thousands at once.
• The old code paid ~7 syscalls per line (exists + chmod 0o644 + open + write + flush + fsync + chmod 0o444) on approvals.jsonl, and the identical pattern again on the HMAC ledger — 2*N fsyncs where 2 suffice.
• Fix: write_approval_log_batch() and write_ledger_entries() do one unlock/open/fsync/lock cycle per batch; the eight approval-log loops in approve.py, the four in reject.py and the ledger loop now accumulate and make one call each. Single-entry functions stay as one-element wrappers.
• Trade-off for the maintainer: durability granularity. A SIGKILL between the data save and the batch's single fsync now loses that commit's whole log block rather than a prefix. Data-first ordering and the best-effort labelling are unchanged.
• Behaviour-preserving otherwise: same lines, same fields, same order; 428 existing tests pass untouched on py3.10 and py3.12, plus 9 new tests.
• Re-checked on current main @ b2324ac (2026-10-05): the bug is still present — write_approval_log and _write_verification_entries are unchanged on main and still do per-item work. The branch now has main merged in.

Priority: MEDIUM

Opened as a draft on purpose. This change trades away a property you may care about. The trade-off is stated below; it should be accepted deliberately, not merged by accident.

The hot construct

write_approval_log (case_io.py:294-307) does a full durability cycle for one JSONL line:

    try:
        if log_file.exists():
            os.chmod(log_file, 0o644)
    except OSError:
        pass
    try:
        with open(log_file, "a", encoding="utf-8") as f:
            f.write(json.dumps(entry) + "\n")
            f.flush()
            os.fsync(f.fileno())

It is called from eight loops in approve.py (:223, :479, :492, :504, :518, :1310, :1324, :1330) and four in reject.py (:153, :298, :307, :322). write_ledger_entry (verification.py:45-54) repeats the same pattern on the HMAC ledger, once per approved item, from _write_verification_entries — so a commit pays 2*N fsyncs, not N.

Why it costs what it costs

fsync() is a device round-trip, ~10-15 ms on a spinning-rust-backed or LVM-on-ext4 volume, and nothing about it amortises: the cost is per call, not per byte. N is the number of dispositions in one commit, not the length of the ledger — appending stays O(1) even as approvals.jsonl reaches 100k lines. _review_mode reads pending-reviews.json wholesale with no cap, and approved_ids additionally accumulates auto-created timeline events and cascaded IOCs, so a realistic portal sweep is a few hundred to a few thousand items in a single commit. That is seconds to tens of seconds of pure durability stalls, on the tool's most-run write path, while the examiner watches.

The correct cost is two fsyncs total. The surrounding code already treats the batch as the consistency unit: Step 1 saves findings/timeline/iocs through a single _atomic_write with one fsync before any log line is written, and the log block is explicitly labelled best-effort with failures merely collected into log_failures.

The fix

• case_io.write_approval_log_batch(case_dir, records) — serialises every record before the file is opened (so a malformed record cannot leave a half-written batch), then one chmod 0o644, one open(..., "a"), one write, one flush, one fsync, one chmod 0o444.
• verification.write_ledger_entries(case_id, entries) — same shape, one mkdir, one open/fsync, one chmod 0o600.
• write_approval_log and write_ledger_entry remain, as one-element wrappers, so every existing caller and test keeps working.
• The twelve call-site loops accumulate records in their original order and make one batch call each; _write_verification_entries builds its entry list and makes one ledger call.

No new module, no new dependency, no shared framework.

Measurement

N = 1000 dispositions, median of 3 timed runs after one warm-up, time.perf_counter, ext4/LVM (not tmpfs), run through uv run --with-editable with case_io.__file__ printed to prove worktree code.

Path	Before	After	Speedup
approvals.jsonl	14.4715 s	0.0465 s	311x
HMAC ledger	13.3038 s	0.0457 s	291x
Combined commit	27.7754 s	0.1094 s	254x

Behaviour preservation

• 428 existing tests pass unchanged on Python 3.10 and 3.12. No existing test was edited or deleted.
• 9 new tests (437 total): batch fsyncs once, records land in list order, a batched record is byte-identical to a write_approval_log record (ts excluded), an empty batch creates no file, the log is relocked to 0o444 after each batch; and the same for the ledger at 0o600.
• One end-to-end regression test drives the real cmd_reject path with 20 findings and counts fsyncs against approvals.jsonl's own (st_dev, st_ino). Red on the original code:

FAILED tests/test_approve_reject.py::TestReject::test_reject_batch_fsyncs_log_once - assert 20 == 1

• ruff check . clean, ruff format --check . clean (63 files).

Trade-off the maintainer should decide on deliberately

Durability granularity. Previously each log line was individually fsynced, so a SIGKILL mid-commit left every already-written line durable. Now the batch is durable only after its single fsync, so the same kill loses the whole commit's log block instead of a prefix. The invariant that matters is unchanged — case data is still saved and fsynced first, and in both the old and new code a crash mid-commit leaves the log incomplete relative to the data — but the granularity is coarser, and on a chain-of-custody tool that is the maintainer's call, not mine.

Two smaller observable changes:

1. A failing batch now reports every id in it as unlogged, rather than only those at or after the failure. This over-reports a custody-log gap rather than under-reporting it, which is the safe direction, and the consequence is only the WARNING: Approval log failed for: ... line.
2. ts values within one commit now cluster within microseconds instead of being spread out by per-line fsync latency (previously ~15 s of drift across 1000 items). Values remain non-decreasing and in the same order.

Independent review notes

This change was reviewed adversarially by a second pass that re-ran the benchmarks. Where that review contradicted or qualified the account above, it is recorded here rather than quietly edited out:

• The commit message says "One observable change"; there are three things to know. Besides the
  failure-reporting granularity it names, ts values within a commit now cluster within microseconds
  instead of being spread by per-line fsync latency (order and monotonicity unchanged), and the
  durability granularity below is not mentioned in the commit message at all.
• Durability granularity is genuinely weakened. Previously each log line was individually fsynced,
  so a SIGKILL mid-commit left every already-written line durable. Now the batch is durable only at its
  single fsync, so the same interruption loses the whole commit's log block rather than a prefix. Case
  data is still saved and fsynced first, and the log block was already labelled best-effort — but on a
  chain-of-custody tool this is the maintainer's call, which is why this PR is a draft.

Deliberately not done here

A shared _append_jsonl_once(path, lines, unlock_mode, lock_mode) helper would subsume both new batch functions and also the audit-trail append in execute.py:150-178 (open(..., "a") per exec record), collapsing three copies of the unlock/open/write/fsync/relock idiom into one. I deliberately did NOT build it: a new shared module or utility would make this PR a prerequisite for every other PR that used it, which destroys the maintainer's ability to cherry-pick these findings independently and in any order. The two batch functions here are local to the modules that already own those files.

Separately, if the maintainer ever wants bounded loss on very large commits, chunked fsync (every K records) is a one-line change inside write_approval_log_batch and keeps most of the 254x.

---

CI status

The checks on this PR will show action_required: GitHub gates workflow runs on pull requests from
first-time fork contributors until a maintainer approves them. They need an Approve and run click.

The CI job was reproduced locally after merging main @ b2324ac (761 tests on main), using the same steps as .github/workflows/ci.yml:

Step	Result
pip install -e ".[dev]" && pytest tests/ — Python 3.10	771 passed
pip install -e ".[dev]" && pytest tests/ — Python 3.11	771 passed
pip install -e ".[dev]" && pytest tests/ — Python 3.12	771 passed
ruff check . + ruff format --check . (latest ruff, unpinned as in CI)	check + format clean

🤖 Generated with Claude Code

[elhoim]

This PR is a draft because it needs a decision on the durability-granularity trade-off. That decision is written up on its own, with the options laid out, in #51 — probably the better place to discuss it than this diff.