docs(sync): record fast-seek root cause and splice bench trail

Splice bench (6.5 s, O(depth) shape confirmed), FatFS cluster-chain
root cause with elm-chan/ESP-IDF references, on-device fast-seek
verification, second localization round (strict-creation refuted,
read_header 470 ms), esp_map v2 design, and the two firmware plumbing
gaps (mwindow opts + 16-FD mount).
This commit is contained in:
Julien Calixte
2026-07-13 00:02:55 +02:00
parent dd3d70cbec
commit ce3204a350
2 changed files with 220 additions and 13 deletions

View File

@@ -22,6 +22,32 @@ the toy `typoena-test` (`notes.md`) has. The repo cannot be shrunk (the 150 MB o
images serve another app — see the images note). So the fix is a **new commit
mechanism**, not a tuning knob.
> **Splice bench result (2026-07-12, later the same day): 6.5 s — do NOT wire it
> in yet.** The walk is in `git_bench` (`splice stage→tree`) and its O(depth)
> shape is confirmed on the real repo (flat pack reads, heap healthy, no OOM),
> but each of its 4 loose-object writes costs **~1.5 s** — isolated `odb.write`
> regressed 142 ms → 1.5 s vs the previous run, with **0 mmap-cache hits**.
> Projected full commit ≈ 89 s.
>
> **Root cause found the same evening (sd_bench seek op): FatFS lseek walks the
> FAT cluster chain** — seek+read(4 KB) into the 263 MB pack costs **198.7 ms at
> the end vs 5.8 ms at offset 0**, and each loose write pays ~8 such walks via
> the freshen path's small `p_mmap`s → the ~1.5 s. Fix landed in
> `sdkconfig.defaults`: `CONFIG_FATFS_USE_FASTSEEK=y` +
> `FAST_SEEK_BUFFER_SIZE=256` (O(1) lseek for read-mode files, i.e. the pack —
> see [FatFS f_lseek/CLMT](http://elm-chan.org/fsw/ff/doc/lseek.html) and the
> [ESP-IDF FatFS docs](https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/storage/fatfs.html)).
> **Verified on device: far seek 198.7 → 20.4 ms.** The A/B (splice 6.5 → 2.8 s,
> odb.write 1.5 s → 416 ms) plus new probes then localized the residual to ~78
> repeated small (~4 KB) pack reads per op that the mmap cache's 64 KB floor
> excluded (`odb.read_header(packed)` = 470 ms; the strict-object-creation
> theory was refuted — strict-off changed nothing). **esp_map.c v2 built**:
> cache admission keyed on FILE size ≥ 1 MB so the hot small windows cache, and
> evict-on-`p_munmap` to a 2 MB low-water mark fixes the 7.4 MB OOM. **Final
> `git_bench` verdict pending — if splice lands sub-second, proceed with the
> firmware plumbing below.** Full trail: the splice-bench, root-cause and
> second-localization sections of the tradeoff curve.
## The fix — O(depth) TreeBuilder walk
Rebuild only the edited file's ancestor subtree chain onto HEAD's tree. Never
@@ -70,11 +96,24 @@ tree), and path splitting on `/` (paths are repo-relative POSIX).
**Bench it first** (per the established discipline): add a `treebuilder splice→tree`
op to `firmware/src/bin/git_bench.rs` alongside the existing ones and confirm it's
sub-second cold on the real repo, with heap staying healthy (no OOM). Only then wire
it into the firmware.
it into the firmware. While in there, two bench-hygiene fixes: (a) the `edit_path`
seed block does the cold `read_tree(HEAD)` **untimed** (the 77 s number came from
log timestamps), so the `Index::new + read_tree` bench only ever measures warm —
wrap the seed in a timer so a re-run prints the cold number; (b) the "3) THE
PROPOSED FIX — index-free commit tree" comment is now stale — the real-repo run
refuted that path (77 s + OOM) and this handoff supersedes it — retitle it as the
refuted alternative.
## Firmware plumbing (after the bench validates)
1. **`firmware/src/git_sync.rs`**
- **Set the mwindow options at service start** (before the first
`Repository::open`): `git2::opts::set_mwindow_size(256 * 1024)` +
`set_mwindow_mapped_limit(4 * 1024 * 1024)`. Today only `git_bench.rs` sets
them — the shipping service runs libgit2's 32-bit defaults (**32 MB window /
256 MB mapped limit**, mwindow.c:16), so the first pack access on the 570 MB
clone would try to `git__malloc` a 32 MB window and die on the 8 MB PSRAM
heap before the walk even runs.
- Rewrite `stage_and_commit` (currently ~L271332) to the `splice`-walk above.
Drop `add_all`/`update_all`/`index.write`/`index.write_tree`. Keep the
`commit split —` timing log, the `tree unchanged → nothing to publish` check,
@@ -89,13 +128,26 @@ it into the firmware.
- The macOS-cruft filter (`skip_macos_cruft`) is no longer needed — the walk only
ever touches paths the editor explicitly hands it, so `._*`/`.DS_Store` can't
sneak in. (Keep a note; don't silently lose the Spike-14 lesson.)
- **Deliberate behavior change to record:** the walk commits *only* the
editor's dirty set. Files changed on the card outside the editor (e.g. the
card mounted on a Mac) were swept in by `add_all` before; they will now never
be committed, and the working tree will show a permanent diff against HEAD if
inspected on a desktop. Correct for the appliance (it's also what makes the
cruft filter unnecessary), but it must be intentional, not accidental.
2. **Dirty-set source — `firmware/src/persistence.rs` + `main.rs`**
- Writes funnel through `Storage::save_path` (~L296) and deletes through
`Storage::delete_path` (~L332), both `&self`. Accumulate a dirty/deleted set
- Writes funnel through `Storage::save_path` (~L316) and deletes through
`Storage::delete_path` (~L352), both `&self`. Accumulate a dirty/deleted set
(needs `RefCell` interior mutability, or move the set up to `main.rs`).
- `Effect::Publish` handler in `main.rs` (~L222) builds the `PublishRequest` from
that set and clears it on a successful `Pushed`/`UpToDate` outcome.
- **FD budget: `main.rs` (~L413) mounts with `Storage::mount()` = 4 open
files, and the git thread shares that mount.** libgit2 keeps the pack +
`.idx` (+ commit-graph) descriptors open and opens loose objects on top —
that's why `git_bench` needed `mount_for_git` (16). On the real repo the
shipping `:sync` will fail with "no free file descriptors" long before any
latency question. Either mount with the 16-file budget in `main.rs` (the
editor's 2-FD peak coexists fine) or split the budgets some other way.
3. **`esp_map.c` cache fix (same pass) — `firmware/components/libgit2/esp_map.c`**
- Bug: cached buffers are freed only lazily in `p_mmap`'s `evict_for`, so a
@@ -128,11 +180,22 @@ the toy pack understates everything by ~2 orders of magnitude.
## What's proven vs open
**Proven (2026-07-12, real repo):** `odb.write` 142 ms (mmap cache holds);
`index.write` 611 s (whole-tree re-hash via `truncate_racily_clean`, index.c:822 /
index.h:117); index-free `read_tree` 77 s cold; mmap cache OOM at 7.4 MB → zlib
crash. `Repository::open` 88 ms, odb-open ~6 s cold (maps 1.7 MB `.idx`).
**Proven (2026-07-12, real repo):** `index.write` 611 s (whole-tree re-hash via
`truncate_racily_clean`, index.c:822 / index.h:117); index-free `read_tree`
7782 s cold (reproduced across both runs); mmap cache OOM at 7.4 MB → zlib crash
(reproduced). `Repository::open` ~9099 ms, odb-open ~68 s cold (maps 1.7 MB
`.idx`). **Splice walk benched (second run): 6.5 s p50, warm ≈ cold** — O(depth)
shape confirmed (flat reads ~40 KB/write, 6.4 MB heap free), cost is 4 loose
writes × ~1.6 s. `commit(None)` 1.7 s.
**Open:** the TreeBuilder walk is **designed but not yet benched or built.** Confirm
its cold-real-repo latency and heap before wiring. Push (network half, ~6.5 s) is a
separate floor, untouched here.
**Open — the new gating question: why does one loose-object write cost ~1.5 s?**
`odb.write(blob)` measured 142 ms in the first real-repo run but 1.5 s in the
second (same `esp_map.c`, same card, **0 cache hits** the whole second run) — the
two runs are unreconciled. Suspects, cheapest first: (a) FAT free-cluster scan on
the ~740 MB-full card → re-run `sd_bench` as-is on this card; (b) loose-write
internals (filebuf tmp + rename, per-write `git_odb_refresh` readdir) under the
accumulating orphan objects from bench runs → re-provision a fresh clone and A/B;
(c) the ~10 small 4 KB `p_mmap`s per write (sub-64 KB, uncacheable) — bounded
~100 ms, secondary. Also open: whether the esp_map cache earns its keep at all
(0 hits this run), the ref/reflog-update cost on the real repo, and the push
(network ~6.5 s) floor — all untouched here.

View File

@@ -4,10 +4,19 @@
> nor an index-free `read_tree`+`write_tree` is viable on the real
> `jcalixte/notes` clone — **both are O(N_tree)** and blow up on the 570 MB pack /
> 1179-file tree (611 s hash one end, 77 s tree-read + OOM the other; see
> [Real-repo run](#real-repo-run-2026-07-12-jcalixtenotes-570 mb-pack--the-index-is-the-wrong-primitive)
> [Real-repo run](#real-repo-run-2026-07-12-jcalixtenotes-570-mb-pack--the-index-is-the-wrong-primitive)
> below). The commit must be rebuilt with an **O(depth) TreeBuilder walk** —
> patch only the edited file's ancestor subtree chain onto HEAD's tree, never
> materialise all 1179 entries. Shrinking the repo is **not** an option
> materialise all 1179 entries.
>
> **Splice-bench update (2026-07-12, later the same day):** the walk was built
> into `git_bench` and measured on the real repo — **6.5 s, failing the
> sub-second bar.** The O(depth) *shape* holds (flat pack reads, healthy heap),
> but each of its 4 loose-object writes costs **~1.5 s** (isolated `odb.write`
> regressed from the 142 ms above; the mmap cache scored **0 hits** this run).
> Localizing the loose-write cost is now the gating work — see
> [Splice bench](#splice-bench-2026-07-12-second-real-repo-run--the-walk-is-right-the-loose-object-write-is-the-new-wall).
> Shrinking the repo is **not** an option
> ([`../notes/git-sync-images-and-repo-size.md`](../notes/git-sync-images-and-repo-size.md):
> the images are load-bearing for another app), which is exactly why the O(depth)
> mechanism is the only lever left. This note records the cost model and the full
@@ -221,6 +230,139 @@ needs an evict-on-`munmap` fix (drop the cap, free past a low-water mark) so it
never again starve a downstream `git__malloc`, but with the TreeBuilder walk the
pressure it was under largely disappears.
### Splice bench (2026-07-12, second real-repo run) — the walk is right, the loose-object write is the new wall
The O(depth) splice op was added to `git_bench` (1 blob + 3 tree writes onto the
depth-3 path `.claude/commands/bsky.md`, run FIRST so its first iteration is
cold; the index ops moved last so their OOM can't cost the new data — it did
crash again, after everything was logged):
| op | result | reading |
| --- | ---: | --- |
| `splice stage→tree` (1 blob + 3 trees) | **6.5 s p50, warm ≈ cold** | O(depth) confirmed — cost is 4 loose writes × ~1.6 s |
| `commit(None)` orphan obj | 1.7 s p50 | one more loose write |
| `odb.write(blob)` | **1.5 s p50** | ⚠️ was 142 ms in the previous run |
| `repo.index()` load | 524 ms max | matches previous run |
| seed `read_tree(HEAD)` cold (now timed) | 81.6 s | reproduces the 77 s |
| `index-free stage→tree` | 💥 crash, 508 KB heap | reproduces the zlib OOM exactly |
Three readings:
1. **The splice mechanism is validated as a mechanism.** Pack reads stayed flat
(~40 KB per write; 6.4 MB heap free through splice + commit + odb.write), so
it really is O(depth) and it cannot OOM. The 6.5 s is not tree-walk cost.
2. **The wall moved to the loose-object write: ~1.5 s each, ×4 per splice.**
The isolated `odb.write(blob)` — one tiny orphan blob — took 1.5 s where the
raw FAT composite is 86 ms. Projected full commit (splice 6.5 s + commit-obj
1.7 s + ref/reflog update) ≈ **89 s**: enormously better than 611 s, still
far off the bar.
3. **The mmap cache scored 0 hits over the entire run** — the documented
862→142 ms `odb.write` win did **not reproduce** (same `esp_map.c`, same
card). Either the earlier run's conditions differed (orphan-object
population? FAT allocation state?) or the win was misattributed. Whatever the
1.5 s is, it is *not* SD data volume: each write moves ~40 KB read + ~1 KB
written.
### ROOT CAUSE FOUND (2026-07-12, `sd_bench` seek op): FatFS lseek walks the cluster chain
Two `sd_bench` re-runs on the ~740 MB-full card settled it:
1. **Free-cluster-scan hypothesis: refuted.** Raw FAT write ops are unchanged on
the full card — loose-object composite **77 ms p50** (was 86 ms), create
20 ms, rename 10 ms. The card is exonerated a second time.
2. **Long seeks are the cost.** A new op opens the repo's largest packfile
(263 MB — the "570 MB pack" was actually the whole `.git`) read-only and does
seek+read(4 KB): **@offset 0 = 5.8 ms; @end = 198.7 ms** — dead constant
across 20 iters. Without `CONFIG_FATFS_USE_FASTSEEK`, FatFS resolves lseek by
walking the file's FAT cluster chain over SPI: forward from the current
position, **from the chain head on any backward seek**. 263 MB ≈ 16.8k
clusters ≈ ~67 KB of FAT reads ≈ ~190 ms per long walk.
**Why FAT behaves this way:** FAT has no extent map or inode — a file is a
singly-linked list of clusters, and the only way to find "byte 260,000,000" is
to follow that list entry by entry through the allocation table. FatFS walks
forward from the current position when it can, but a backward seek restarts
from the chain head ([FatFS `f_lseek` docs, elm-chan.org](http://elm-chan.org/fsw/ff/doc/lseek.html)).
The fast-seek feature fixes exactly this: a pre-computed **cluster link map
table (CLMT)** per file object, "(fragments + 1) × 2" words, after which "no
FAT access is occured in subsequent f_read/f_write/f_lseek" (same page). On
esp-idf it's `CONFIG_FATFS_USE_FASTSEEK` — the official docs recommend it "for
read-heavy workloads with long backward seeks" and note it does not apply to
files opened in write mode
([ESP-IDF FatFS docs](https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/storage/fatfs.html)).
The budget closes: each loose write does ~810 small (~4 KB) `p_mmap`s (freshen
→ trailer/idx probes) interleaved with low-offset reads, so ~8 of them pay a
fresh ~190 ms walk → **~1.5 s per object**. It also explains everything the
cache couldn't: warm ≈ cold (the walk is paid inside `lseek` before any data
moves, and the maps are below the 64 KB cache floor), the 142 ms vs 1.5 s
run-1/run-2 discrepancy (run 1's `odb.write` bench ran first and hammered only
the trailer — the file position stayed there, so its seeks were forward/no-ops),
and a large slice of the 81.6 s `read_tree` (133 windows × backward seeks ≈ 25 s
of walking on top of the 25 MB of data).
**Fix (config, not code): `CONFIG_FATFS_USE_FASTSEEK=y` +
`CONFIG_FATFS_FAST_SEEK_BUFFER_SIZE=256`** (landed in `sdkconfig.defaults`
2026-07-12). Fast seek builds an in-memory cluster-link map per read-mode file —
exactly how the pack is opened — making lseek O(1); write-mode files fall back
to the walk transparently. 256 words = 1 KB per open read-only file, covering
~127 fragments (default 64 covers ~31; a fragmented pack would silently fall
back to slow seeks, so the headroom matters).
**A/B measured (same evening): a 2.3× partial win, not a full one.**
| op | fast-seek off | fast-seek on |
| --- | ---: | ---: |
| `splice stage→tree` | 6.5 s | **2.81 s** |
| `odb.write(blob)` | 1.5 s | **416 ms** |
| `commit(None)` | 1.7 s | **1.72 s — unchanged** |
`odb.write` dropped by almost exactly the ~6 chain walks the model predicted —
the seek theory holds — but two residuals remain: **~400 ms per loose write**
(vs the 77 ms raw-FAT floor) and **`commit(None)`'s ~1.3 s premium over a plain
write, which was never seek-bound at all**. Prime suspect for the commit
premium: strict object creation makes `git_commit_create` validate its parent +
tree OIDs with pack header resolves, and `git_treebuilder_insert` does the same
per inserted entry — `git_bench` grew `odb.read_header(packed)` /
`odb.exists(missing)` probes and strict-off re-benches to test it.
### Second localization round (2026-07-12, run 3b + sd_bench re-run)
**Fast-seek verified on the metal:** re-running the sd_bench seek op with
`CONFIG_FATFS_USE_FASTSEEK=y` dropped `pack seek+read 4KB @end` from
**198.7 ms → 20.4 ms** (the CLMT fits the pack in the 256-word buffer — the
pack is not too fragmented). A far seek is now ~15 ms, i.e. effectively fixed.
**The strict-creation theory is refuted; the probes found the real unit cost:**
| op | p50 | reading |
| --- | ---: | --- |
| `odb.read_header(packed)` | **470 ms** | ONE pack header resolve costs ~½ s |
| `odb.exists(missing)` | **968 ms** (±0.1 ms) | miss path (scan → refresh → rescan) ≈ 2× |
| `commit(None)` strict OFF | 1.80 s | vs 1.93 s strict on — validation is NOT the premium |
| `splice` strict OFF | 5.7 s | noise-worse; also not validation |
The ±0.1 ms constancy of `exists(missing)` = a fixed, deterministic SD-op
sequence. The map counters identify it: **~78 small (~4 KB) `p_mmap` reads per
op** — pack trailer probes, idx fanout reads and delta-base windows, repeated
at the *same offsets* on every freshen/refresh. Post-fast-seek those cost
~20 ms each (~150 ms/op); the rest of `read_header`'s 470 ms is CPU-side
delta-chain inflation on the 160 MHz core plus repeated re-reads. Two other
observations from run 3b: the loose-object orphan population from bench runs
is creeping costs upward (splice 2.81 s → 3.21 s between consecutive
fast-seek runs — a re-provision resets it), and the mmap cache STILL scored 0
hits — because its 64 KB map-length floor excluded exactly these hot small
maps.
**Fix built (esp_map.c v2, pending re-bench):** cache admission re-keyed from
map length to **file size ≥ 1 MB** — the pack/idx's small repeated windows now
cache (RAM hits after first touch) while small mutable working-tree files stay
excluded — plus **evict-on-`p_munmap` down to a 2 MB low-water mark**, fixing
the 7.4 MB OOM from the first real-repo run (released windows are actually
returned to `git__malloc`, so `MWINDOW_MAPPED_LIMIT` stays honest). Expected:
`read_header` collapses toward CPU-only, `odb.write` toward ~150250 ms,
splice at or under the sub-second bar, and no end-of-run zlib OOM.
### The walk is ~1.4 s even at N ≈ 2
Mostly fixed cost — the worktree-diff setup and the second (`update_all`) pass —
@@ -245,7 +387,9 @@ work, ranked:
flat in repo size, small heap, images carried forward untouched. Replaces
`stage_and_commit`'s `add_all`/`update_all`/`index.write`/`write_tree`. Needs the
editor's dirty set (+ deleted set) plumbed to the git service — the editor
already knows both. **Bench the walk on the real repo before wiring it in.**
already knows both. **Benched 2026-07-12: 6.5 s — the shape is right but it
fails the sub-second bar**; wiring it in is blocked on localizing the ~1.5 s
loose-object write (see the splice-bench section above).
2. **Fix the `esp_map.c` cache so it can't OOM (do it alongside #1).** It grew to
7.4 MB resident past its 4 MB cap and starved zlib. Evict on `p_munmap` (not
only lazily on the next `p_mmap`) down to a low-water mark, and lower the cap, so