# Records append latency: where the time goes Harness: `scripts/measure-records-append-latency.py`. Raw numbers and cProfile output: `records-append-latency-results.json` (baseline), `records-append-latency-after.json` (after the fixes, including a 10,000-item run) and `records-storage-comparison-sqlite-prototype.json` (same directory). The first half of this page is the baseline diagnosis. The fixes, their before/after numbers, the file-versus-SQLite comparison and the recommendation follow it. ## Method - Synthetic markdown-items collection with an `item_filename` and an `item_presentation` recipe, invented data, seeded at 10 / 100 / 1,000 items in a temp vault with a temp state root. - Each measurement is one `record_memory` append through the real dispatcher (`writer_lease.invoke_command`): idempotency ledger, mutation boundary, post-commit fan-out. - 30 guarded appends per size, p50 / p95. Before each, the client-side guard refresh (`record_memory inspect`, read the container hash), timed separately. A further 30 unguarded appends per size isolate the guard's own cost. One cProfile pass over an append and one over the refresh read. - Stage timers are inclusive wall-clock wrappers (outermost entry only), so nested stages overlap and do not sum. - Limits: embeddings, CLIP and file watcher are disabled, so embedding work is unmeasured (the fan-out reports it as `accepted`, i.e. deferred). The vault holds only this collection, so costs that scale with total vault size are understated. One 4-core Linux container. ## Findings (guarded append, p50 ms) | Stage | N=10 | N=100 | N=1000 | Grows with N? | |---|---:|---:|---:|---| | **Total** | 355 | 710 | 4,600 (p95 5,078) | yes, about 4.3 ms per item | | Dispatcher outside the leaf (ledger, egress filter, digest) | 6.8 | 7.8 | 6.4 | no | | Idempotency ledger (`ledger.run` minus leaf) | 4 | 4 | 3 | no | | Mutation boundary enter / exit | 2.2 / 0.4 | 2.2 / 0.4 | 1.8 / 0.4 | no | | Request validation (`_validate_values`, twice) | 1.9 | 1.8 | 1.8 | no | | Collection resolve (3 calls) | 7.9 | 7.4 | 8.0 | no | | Manifest load + parse (parsed 9 times) | 85 | 80 | 78 | no (fixed cost) | | Container-hash guard: snapshot read (`MarkdownItemsAdapter.read`) | 19 | 80 | 733 | **yes, O(N)** | | Natural-key twins + after-hash + new item path | 0.6 | 1.9 | 15 | yes, small | | Visibility check (`require_mutation_visibility`, 2 calls) | 24 | 89 | 777 | **yes, O(N)** | | Pre-commit authorization (contains one visibility call) | 33 | 121 | 1,031 | **yes, O(N)** | | Item presentation render (`render_markdown_item`) | 0.8 | 0.8 | 0.8 | no | | `exomem-item-presentation` block alone | 0.08 | 0.09 | 0.09 | no | | `batch_atomic_write` (guard rechecks + write + fan-out) | 249 | 418 | 2,400 | **yes, O(N)** | | Post-commit fan-out inside it (index sync, self-write registration) | 133 | 125 | 133 | no | | of which `index.upsert_after_write` | 93 | 92 | 86 | no | | Due-state and sweep carriers, terminal housekeeping | 3 | 3.4 | 2.9 | no | | **Guard refresh read** (`record_memory inspect`) | 279 | 946 | 7,605 (p95 8,088) | **yes, about 7.4 ms per item** | | **Refresh + append round trip** | 634 | 1,656 | 12,205 | yes | | Unguarded append (no `expected_container_hash`) | 487 | 923 | 4,765 | same as guarded | Answers to the specific questions: - **Does the container-hash guard read or hash the whole collection?** Yes. The container hash is the digest of the full item inventory, so `MarkdownItemsAdapter.read` reads, hashes and YAML-parses every item file on each append. The guard itself is not the marginal cost: an unguarded append is as slow, because the same snapshot is taken regardless. - **Index sync.** Lexical, resolver and memory-refs sync run synchronously, about 86 ms and flat. Embeddings are `accepted` (deferred) and the graph is `registered` (deferred). Neither grows with N in this harness. - **Ledger, fast-ack, response.** Together under 10 ms and flat. Fast-ack is a closure inside the ledger run and has no separate timer; its cost sits inside that 4 ms. - **File write.** The write itself is not separable from the guard rechecks inside `batch_atomic_write`; the fan-out is 133 ms of the 2,400 ms at N=1000. - **Off-path.** The lease renewer and the graph rebuild thread run alongside back-to-back appends. Their effect on p95 was not isolated. ## Top three hot spots **1. Per-path authorization repeats policy and state resolution for every item.** `record_governance.py:936` (`_authorize`) calls `egress.py:5228` (`release_level_for_path_only`) once per item per pass. Each call reloads the governance policy (`policy.py:1292`), recomputes tombstones (`lifecycle.py:1567`) and re-derives and stats the vault state directory (`state_paths.py:303`, `:321`, `:278`). At N=1000 an append makes about 3,200 such calls, and the refresh read about 7,000 (roughly 70% of the refresh profile). Callers: `record_formats.py:203` (`_require_authorized`), `record_governance.py:2784` (`precommit_authorize_mutation`), `:2812` (`require_mutation_visibility`), `records.py:1934`. *Proposed fix:* resolve policy, tombstone set and state directory once per operation and evaluate each path against that resolved object (`full_release_filter` already returns a per-call filter that could carry it). *Expected gain (estimate):* removes most of the O(N) term in both calls, so about 4.6 s to 2 s for the append and 7.6 s to 2.5 s for the refresh at N=1000. **2. Directory censuses and guard rechecks run about 20 times per append.** `vault.py:3296` (`_bounded_directory_entries`) ran 21 times and took about a third of the profile. It classifies every entry through `reserved_paths.py:1996` (`classify_logical`, about 600k regex matches). `PathGuard.recheck` (`vault.py:1143`) re-reads and re-hashes each item file (about 12 snapshot reads per item at N=1000, `vault.py:3556`). `batch_atomic_write` (`vault.py:4618`) is 2.4 s of the 4.6 s. *Proposed fix:* take one census per operation and reuse it for the visibility check, read and pre-commit; cache classification per path within a census; recheck under the held mutation lock by stat identity (inode, size, `mtime_ns`) instead of a full re-read. *Expected gain (estimate):* `batch_atomic_write` pre-write cost from about 2.3 s to under 0.5 s at N=1000. **3. The refresh read snapshots the collection three times.** `record_governance.py:1406` (`inspect_collection`) calls `record_formats.py:395` (`read`) three times (about 19 of 22.7 profiled seconds), and `records.py:1887` (`inspect_audit_gap`) adds a further 7 s of audit-chain reads. A client pays this between every guarded append, so it is the largest single number: 7.6 s of the 12.2 s round trip. *Proposed fix:* one snapshot per inspect, shared by the inspection and the audit-gap pass; and a per-file digest and parse cache keyed by stat identity so a snapshot rebuild only reads changed files. A cheaper option for callers that only need the guard is a hash-only read. *Expected gain (estimate):* refresh about 7.6 s to 2.5 s from the single snapshot alone. Fixed cost, not O(N): about 350 ms per append at N=10. The manifest is parsed 9 times (`structured_collections.py:1061`, about 80 ms) because `records.py:2738` and `record_governance` resolve it repeatedly; passing the parsed manifest through would save about 70 ms. Index sync adds about 90 ms. ## What this does not explain The reported 24-row backfill took about 21 minutes, roughly 52 s per row. The measured round trip at 1,000 items is 12 s, and the collection cap is 2,000 items. So collection size alone, in this harness, does not reach 52 s. Candidates that this harness does not cover: a larger real vault (index and graph work that scales with vault size), embeddings enabled, slower storage, a larger policy set, or concurrent load from the graph rebuild. Reproducing on a copy of the affected collection, with `call_spans` enabled on the live service, would settle it. --- # Fixes, before and after All numbers are one append (or one guard refresh) through the real dispatcher, p50 / p95 over 30, in milliseconds, on the same container as the baseline. Each row is cumulative. The 10 and 100 item rows carry run-to-run noise of roughly 10 to 20 percent (one 657 ms p95 outlier at 10 items in the first row is a noisy sample, not a regression). "Round trip" is guard refresh plus append at p50. | Stage | Items | Append p50 | Append p95 | Refresh p50 | Refresh p95 | Round trip p50 | |---|---:|---:|---:|---:|---:|---:| | Baseline | 10 | 355 | 436 | 279 | 376 | 634 | | | 100 | 710 | 859 | 946 | 1,115 | 1,656 | | | 1,000 | 4,600 | 5,078 | 7,605 | 8,088 | 12,205 | | 1. Authorization pass | 10 | 295 | 657 | 93 | 125 | 388 | | | 100 | 575 | 650 | 336 | 376 | 911 | | | 1,000 | 3,392 | 3,611 | 2,728 | 2,959 | 6,120 | | 2. Stat-generation cache | 10 | 248 | 279 | 57 | 73 | 305 | | | 100 | 306 | 374 | 136 | 185 | 442 | | | 1,000 | 1,112 | 1,177 | 965 | 1,144 | 2,076 | | 3. Batched rechecks, deduped censuses | 10 | 254 | 352 | 55 | 78 | 309 | | | 100 | 249 | 309 | 120 | 178 | 369 | | | 1,000 | 696 | 772 | 929 | 1,047 | 1,625 | | 4. Manifest parse cache, one inspect snapshot | 10 | 156 | 175 | 34 | 46 | 190 | | | 100 | 203 | 245 | 73 | 95 | 276 | | | 1,000 | 628 | 696 | 464 | 599 | 1,093 | | 5. Cheaper recheck, access memo | 10 | 157 | 195 | 31 | 46 | 188 | | | 100 | 188 | 250 | 64 | 96 | 252 | | | 1,000 | 625 | 706 | 416 | 546 | 1,041 | | 5, collection caps lifted | 10,000 | 5,202 | 5,706 | 6,089 | 6,479 | 11,291 | What each change is, and the red-first test that guards it (all in `tests/test_record_write_scaling.py`): 1. **Authorization pass** (`record_governance.py` `authorization_pass`, `governance/egress.py` `release_level_for_path_only(tombstones=...)`, `governance/lifecycle.py` `is_tombstoned_in`). Policy and the tombstone set are read once per operation instead of per item. Test: policy loads and tombstone scans per append and per inspect must not grow from 3 to 12 items. Red was 1 policy load and 3 tombstone scans per extra item on append, 10 of each on inspect. 2. **Stat-generation cache** (new `record_item_cache.py`, `vault.py` `PathGuard` policy `generation`, `record_formats.py` `read`). An item file whose (device, inode, size, mtime, ctime) is unchanged is served from memory: no open, hash or YAML parse. Parsed frontmatter is memoised by content digest. Tests: file reads and frontmatter parses per repeat append and per repeat inspect must not grow with items; a same-size in-place edit that restores mtime still changes the container hash; an out-of-band edit makes a guarded append return `STALE_RECORD`. 3. **Guard rounds** (`vault.py` `recheck_path_guards`, `_prepare_path_guards`, `batch_atomic_write`; `record_governance.py` `require_mutation_visibility(census=...)`). Each guard round proves every shared ancestor once; guards that need no parent creation are not re-captured; identical directory censuses handed in twice are proved once; pre-commit visibility reuses the snapshot's census when it covers every child directory. Marginal filesystem probes per extra item went from about 101 to 25 (test asserts under 40). 4. **Manifest parse cache and one inspect snapshot** (`structured_collections.py` `parse_manifest_bytes`; `record_governance.py` `inspect_collection`, `records.py` `inspect_audit_gap`, `record_formats.py` `inspect_collection`). Manifest parses per append went from 12 to at most 3; an inspect reads the collection once instead of three times. The audit-gap pass still learns whether the authorizer refused any path (`snapshot_denied`), so withheld items still make the chain incomplete rather than clean. 5. **Cheaper recheck, access memo** (`vault.py` `PathGuard.recheck`, `record_governance.py` `_access_refused`). Plain string joins and one access decision per path per pass. Measured effect at 1,000 items: none beyond noise (625 ms against 628 ms p50). They are kept because they cost nothing and the profile showed the work, but they are not what moved the numbers. ## Is the target met? **No.** The target was single-append p95 under 300 ms at 1,000 items with no O(N) stage per append. - p95 at 1,000 items went from 5,078 ms to 706 ms (7.2 times), the guard refresh from 7,605 ms to 416 ms (18 times), and the round trip from 12.2 s to 1.04 s. At 100 items the append is 188 ms p50, 250 ms p95, which meets 300 ms. - **What remains at 1,000 items (p50):** about 155 ms fixed, the same at 10 items: fan-out and index sync 50 ms, manifest and collection resolution 15 ms, dispatcher 7 ms, and the rest small. On top of that about 470 ms grows with items, roughly 0.47 ms per item: the guard rechecks and directory censuses inside `batch_atomic_write` (111 ms at 10 items against 309 ms at 1,000, so +198 ms), snapshot assembly (+107 ms), visibility (+86 ms) and pre-commit authorization (+74 ms). Those four add to the 468 ms difference between the 10-item and 1,000-item totals. - **Still O(N).** No stage is O(N) in bytes read or parsed any more: unchanged items are never re-read, re-hashed or re-parsed. But several stages still touch every item once or more per append in Python and in syscalls: a `lstat` per item per guard round (about nine rounds), a census scan per directory (about ten scans), and a per-path authorization decision. At 10,000 items (caps lifted) the append is 5.2 s p50, and the fan-out itself grows from 50 ms to 351 ms there, which I did not investigate. - The product cap of 2,000 items per collection bounds the worst case: by this curve about 1.1 s p50 for an append and 0.9 s for a refresh at the cap. Racy-window note for the cache: a file whose mtime or ctime is within two seconds of being read is never trusted from the cache, so a back-to-back sequence re-reads only the last few files written. Stat generations are not trusted on Windows, where `st_ctime` does not move on a write; there every read is by content, as before. # File design against SQLite-authoritative ## What was compared 1. **Index-backed file design.** What is built above (stat-generation cache, batched guards). The Markdown items stay the source of truth. 2. **Throwaway SQLite-authoritative prototype** (`benchmarks/prototype-sqlite-records.py`, not in `src/`, not wired to anything). Rows in a per-vault SQLite table, same natural key (unique index), the guard is a per-collection generation integer, one audit row per transition in the same transaction, Markdown item files rendered from the row by the real `render_markdown_item`. WAL mode, `synchronous=FULL` (each commit is durable) unless stated. Two projection modes: **sync**, the file is rendered and atomically written with `fsync` inside the transaction before commit; **async**, the transaction commits the row plus an outbox row and a worker thread renders and writes afterwards. The prototype measures the storage layer only. It leaves out request validation, the writer lease, the idempotency ledger, governance and the index fan-out. Those are size-independent and shared by both designs. To compare like with like I add the measured fixed cost back: at 10 items the whole file-design append is 157 ms, of which about 70 ms is item-dependent storage work (snapshot 5, visibility 3, pre-commit 2, the guard and write part of `batch_atomic_write` about 60), leaving **about 90 ms** of shared cost. The composite below is that 90 ms plus the prototype number. It is an estimate; a real implementation would carry costs I have not modelled. ## Numbers (p50 / p95, ms) | Items | Design | Append (storage layer) | Append (composite est.) | Guard refresh | Projection lag | |---:|---|---:|---:|---:|---:| | 1,000 | File, index-backed | n/a | 625 / 706 | 416 / 546 | none | | 1,000 | SQLite, projection in transaction | 2.6 / 3.5 | about 93 / about 100 | 0.02 / 0.03 | none | | 1,000 | SQLite, async projection | 1.2 / 1.6 | about 91 / about 100 | 0.02 / 0.4 | 22 / 34 | | 10,000 | File, index-backed (caps lifted) | n/a | 5,202 / 5,706 | 6,089 / 6,479 | none | | 10,000 | SQLite, projection in transaction | 3.0 / 3.8 | about 93 / about 100 | 0.03 / 0.04 | none | | 10,000 | SQLite, async projection | 1.6 / 2.8 | about 92 / about 100 | 0.04 / 0.11 | 4 / 6 | With `synchronous=NORMAL` (commit not fsynced, durable to a process crash but not power loss) the sync projection is 1.8 to 2.4 ms and the async foreground append about 0.1 ms; projection lag rises to 31 to 37 ms p50. The guard refresh in the composite would still pay the dispatcher and collection resolution (about 15 to 25 ms), not 0.02 ms, because the client-visible refresh is a command. Read this as: the SQLite design is flat in the number of items and the file design is linear, and the gap is two orders of magnitude at 10,000 items. At 1,000 items the composite meets the 300 ms target with a large margin; the file design does not. At 100 items or fewer the file design is already within the target and the difference is small next to the fixed 90 to 150 ms, which neither design changes. ## Cost list for making SQLite authoritative - **Migration of existing collections.** Every collection's item files must be parsed into rows, keeping each item's UUID (`exomem_id`), its natural key and body. The audit chain is currently split across the manifest's audit head, the activity log and archived logs; it would have to be converted to audit rows keeping transition ids and parent links so the existing gap and continuity checks still hold. Client-held `expected_container_hash` values change meaning. The manifest stays a Markdown file the user edits, so authority would be split between a file (schema) and a database (rows). - **Backup and restore (restic and vault copy).** Today the vault directory is the whole truth, so a restic snapshot or a folder copy is a complete backup. With rows authoritative, the database must be in the vault (a live WAL database copied mid-write can be torn; it needs `VACUUM INTO` or a stop-the- writer snapshot before restic sees it) or in the machine-local state root, which is not part of the vault and is not backed up by copying it. Restore becomes: restore the database, then regenerate the projection. A vault copy alone would be a read-only mirror that cannot be written back to. - **Obsidian visibility.** Items remain visible as files, but read-only in effect. An edit in Obsidian is not authoritative and would be overwritten by the next projection, so either it is refused with a visible notice, or an import path turns the diff into an audited row update. Sync tools (Obsidian Sync, Syncthing) work on the projection and cannot merge the database, so two machines writing produce a conflict the current file design resolves by ordinary file conflict handling. - **Out-of-band edit handling.** Today: detected by the stat-generation cache and the container guard, and refused as stale. With SQLite: the edit lands in a file that is not authoritative, so it has to be detected on projection (hash mismatch against the row) and either reverted or ingested. That policy is a product decision the file design does not need. - **Hosted cells.** A cell already has a single writer lease, so SQLite fits, and the cell volume holds the database. Cell export, restore and import currently operate on file trees and would need a database path; evidence bundles built from items would read rows. - **Governance and withheld = absent.** Withheld items are absent because every read passes each item's path through the release filter. Rows do not remove that: each row keeps its projection path as the policy subject and the same filter applies before a query, an aggregate or an inspect returns anything, and audit rows need the same redaction. What changes is cost: evaluating policy per row on every query is O(N) unless the policy is compiled into a query predicate (path-prefix scopes map to `WHERE`; tombstones and access tiers need a join). Deletion and trash recovery today move files; they would move rows and re-project. Exactly-once still comes from the idempotency ledger, which is independent of the storage layer. - **Everything else that reads items as pages.** `find`, the graph, lexical and embedding sync, plan links, due-state and capture sweeps read the Markdown files. With an async projection they see a write only after the worker runs (22 to 34 ms here; unbounded under a stalled worker), which breaks read-your-writes for the next `find`. A synchronous projection keeps that property and still costs only about 2 to 3 ms. ## Decision **Storage authority is SQLite (owner decision, applied after review of these numbers).** The recommendation originally written here was to keep the files authoritative and add a derived sidecar; it was overruled on the grounds that a derived sidecar reintroduces two sources of truth. The migration is designed in a separate lane (`design/structured-collections-sqlite`). The cost list above is the input to that design, not a reason against it, and the prototype stays in `benchmarks/` as reference only. Rulings that apply to this change: - The index-backed file fix ships as is. 706 ms p95 at 1,000 items is accepted as an interim improvement until the SQLite work replaces the storage layer. - Content reads on Windows (stat generations not trusted there) are accepted. - Whatever the SQLite design keeps from this page: a synchronous projection preserves read-your-writes for `find`, the graph and index sync; the shared fixed cost of 90 to 150 ms is unaffected by the storage layer; withheld = absent must be evaluated per row through its projection path.