diff --git a/docs/notes/sync-latency.md b/docs/notes/sync-latency.md index 536bde3..b242835 100644 --- a/docs/notes/sync-latency.md +++ b/docs/notes/sync-latency.md @@ -75,10 +75,12 @@ The big rocks are physics or protocol, not slack: - **TLS handshake ~2.4 s** and **push negotiate/upload ~4.4 s** are inherent to libgit2-over-mbedTLS on this part; the payload is tiny, so there's little to shave. -- **stage + commit ~3.1 s** is the one soft spot: staging `notes.md` directly - instead of `add_all(["*"])` would skip the SD/FAT tree walk (likely → - sub-second), at the cost of the file-agnostic design that a future multi-file - publish wants. Deferred, on purpose. +- **stage + commit ~3.1 s** is the one soft spot: staging over the editor's dirty + set (`add_path`) instead of `add_all(["*"])` would skip the SD/FAT tree walk + (likely → sub-second) *without* losing multi-file — the dirty set is the file + list. Whether the walk actually dominates the ~4 s commit is now being measured + by the `commit split —` log line; the cost model and the rule it decides live in + [`../tradeoff-curves/sync-commit-staging.md`](../tradeoff-curves/sync-commit-staging.md). **Conclusion:** ~16 s cold / ~10 s warm is close to the floor for "commit to FAT + one TLS push over Wi-Fi with a fresh clock." It reads as slow only if you wait on diff --git a/docs/tradeoff-curves/README.md b/docs/tradeoff-curves/README.md index d25d382..7915d75 100644 --- a/docs/tradeoff-curves/README.md +++ b/docs/tradeoff-curves/README.md @@ -11,3 +11,4 @@ | --- | --- | | [`wifi-auto-sync.md`](wifi-auto-sync.md) | `auto_sync` interval vs Wi-Fi energy (a `1/T` hyperbola) — why the default is 10 min and opportunistic, not a wall-clock timer. | | [`epd-refresh-latency.md`](epd-refresh-latency.md) | E-ink refresh latency vs rows driven — the full / full-area-partial / windowed-Y cost model behind typing responsiveness and the boot splash→editor swap. | +| [`sync-commit-staging.md`](sync-commit-staging.md) | Commit-staging strategy vs working-tree size — `add_all(["*"])` (O(tree) FAT walk) vs explicit-path (O(churn)); the walk-vs-writes split that decides whether explicit staging is worth it. | diff --git a/docs/tradeoff-curves/sync-commit-staging.md b/docs/tradeoff-curves/sync-commit-staging.md new file mode 100644 index 0000000..e39112f --- /dev/null +++ b/docs/tradeoff-curves/sync-commit-staging.md @@ -0,0 +1,179 @@ +# Commit-staging cost vs working-tree size + +> **Decision (pending measurement):** keep the file-agnostic `add_all(["*"])` +> staging, or switch to explicit-path staging (`add_path` over the editor's dirty +> set)? The fork is worth taking **only if the FAT working-tree walk dominates the +> ~4 s commit** — which the split-timer added to +> [`../../firmware/src/git_sync.rs`](../../firmware/src/git_sync.rs) +> (`stage_and_commit`, the `commit split —` log line) resolves. This note records +> the cost model and the rule the measurement decides. +> +> Tradeoff-curves index: [`README.md`](README.md). Docs index: +> [`../README.md`](../README.md). Where the whole sync goes: +> [`../notes/sync-latency.md`](../notes/sync-latency.md). Sibling curve on the +> radio cost of *how often* we sync: [`wifi-auto-sync.md`](wifi-auto-sync.md). + +## The model + +`:sync` commits the working tree on the SD/FAT card before it pushes. The commit +is two kinds of work against the card over SPI (10 MHz today, ADR-012): + +``` + stage write + ─────────────────────────────── ───────────────────────────── + add_all(["*"]) + update_all(["*"]) index.write + write_tree + commit-obj + → stat() every file in the tree, → serialise the index and three loose + hash the ones whose stat moved objects, each a FAT create+write+fsync + cost ∝ tree size (O(N_tree)) cost ∝ churn (O(N_changed)) + fixed +``` + +The two have different curves against **N = files in `/sd/repo`**: + +- **Walk** rises with N. `add_all(["*"])` visits the whole working tree every + sync regardless of how little changed, and each visit is a FAT `stat` (and a + re-hash when the entry looks dirty) over SPI. This is the term explicit-path + staging removes: the editor already knows which buffers are dirty and which + were `:delete`d, so `index.add_path(p)` / `index.remove_path(p)` over that set + touches `N_changed` files (≈1 for a writing appliance), not `N`. +- **Write** is flat in N. A text commit is the index + a blob + a tree + a commit + object — a handful of small FAT writes whose cost is set by SPI clock and + `fsync`, not by tree size. Explicit-path staging cannot shave this; only a + faster card bus (SD 10 → 20 MHz on a clean PCB, `persistence.rs`) does. + +``` + Commit latency vs working-tree size two staging strategies + + ms + | walk-all: add_all(["*"]) + 4000 | . * stat()s every file in the + | . * tree each sync → O(N) + | . * + 3000 | . * + | . * + 2000 | . * + | * + 1000 |····································· explicit-path: add_path(dirty) + | FAT object-write floor → O(churn); flat in N. The gap + 0 +----+----+----+----+----+----+----+---→ up to walk-all is the avoidable + 10 50 100 200 400 800 1179 per-sync tree walk. + └── jcalixte/notes today (N files) +``` + +The gap between the lines at a given N is exactly what switching buys, and it +**grows without bound** as the notes tree fills. + +### The real operating point (measured 2026-07-12, `jcalixte/notes`) + +The device syncs into a clone of the actual notes repo, not a `notes.md` toy. Its +working tree is **not small**: + +| | count | working-tree bytes | +| --- | ---: | ---: | +| Markdown (`.md`) | 875 | ~1.5 MB | +| Images (png/jpg/webp/bmp/gif) | ~260 | **~150 MB** | +| Other (json/ts/pdf/…) | ~44 | ~20 MB | +| **Total (N)** | **1179 files, 158 dirs** | **~170 MB** | +| `.git` history | | ~570 MB | + +So `add_all(["*"])` walks **1179 files across 158 directories every sync** — and +~260 of them are images that a text edit never changes. That does two things the +toy-repo baseline hides: + +1. **The walk term is large and paid on every sync** — 1179 `stat`s + 158 dir + reads over SPI, for a one-line note change. This is the O(N) cost the curve + above predicts, at N ≈ 1179 rather than N ≈ 2. +2. **Re-hash risk.** libgit2 decides a file is unchanged from `stat` metadata + (mtime/size). FAT's coarse mtime and lack of a stable inode can make entries + look racy, forcing a content re-hash. If even a slice of the ~150 MB of images + gets re-hashed over a 10 MHz SPI bus, the commit balloons far past 4 s. The + `walk` timer will show it; explicit-path staging sidesteps it entirely by never + visiting the images. + +## Measurement (2026-07-12, toy `notes.md` tree, N ≈ 2) + +Split from two back-to-back `:sync`es on the small test repo (commits `95ac56ef` +cold, `ab260bde` warm), via the `commit split —` log lines: + +| Sub-phase | Kind | Cold (ms) | Warm (ms) | +| --- | --- | ---: | ---: | +| `walk(add_all+update_all)` | scan (O(N)) + likely 1 blob write | 1402 | 1456 | +| `index.write` | FAT write | 204 | 204 | +| `write_tree` | **1 tree object → FAT** | 710 | 715 | +| `parent-load` | FAT read | 102 | 105 | +| `commit-obj` | **1 commit object + ref → FAT** | 914 | 924 | +| **commit total** | | **3332** | **3404** | + +### It is not the card — it's libgit2 (`sd_bench`, 2026-07-12) + +My first read of the table was "a loose-object write to this SD card costs +~700–900 ms." **That was wrong.** `sd_bench` (`firmware/src/bin/sd_bench.rs`) times +the raw FAT primitives on the same card at the same 10 MHz: + +| Raw FAT op (200-byte payload) | p50 | +| --- | ---: | +| create + write + close | 21.7 ms | +| rename | 12.8 ms | +| stat (hit / miss) | ~5 ms | +| remove | 14.9 ms | +| **loose-object composite** (stat + create + write + rename) | **86 ms** | + +The card does a *complete* loose-object write in **~86 ms**. Yet `write_tree` +(one tree object) took **710 ms** and `commit-obj` **914 ms** — an **~8× gap that +is pure libgit2 overhead, not FAT I/O.** So the earlier "object-write floor / SD +write amplification / better card / SPI-clock" framing is refuted: **the SD card is +not the bottleneck.** fsync is still confirmed off; the extra ~600 ms/op is CPU or +repeated `.git` I/O *inside* libgit2 (candidates: ODB refresh scanning +`objects/`, the treebuilder's per-entry `git_odb_exists`, ref-lock + reflog writes, +config/attributes re-reads). `git_bench` (`firmware/src/bin/git_bench.rs`) times +`odb.write` / `index.write` / `write_tree` in isolation to localize it — **run +pending.** + +### The walk is ~1.4 s even at N ≈ 2 + +Mostly fixed cost — the worktree-diff setup and the second (`update_all`) pass — +not per-file `stat` (one raw `stat` is ~5 ms, so N ≈ 2 can't be the 1.4 s). The +O(N) slope only bites on the real `jcalixte/notes` clone (N ≈ 1179), which this run +did **not** exercise. That slope is still unmeasured. + +For orientation: `publish(commit+push)` was 9846 ms cold, so the **network half is +~6.5 s** — still the biggest single block of a warm sync (10.1 s total), a separate +floor ([`../notes/sync-latency.md`](../notes/sync-latency.md)). + +## The verdict (provisional — pending `git_bench`) + +Two things are now settled and one is open: + +- **Settled: the card is fast.** The SD-clock and better-card levers are off the + table — they target I/O that costs ~86 ms, not the ~700 ms we see. Do not spend + the PCB's 20 MHz budget expecting a commit-latency win here. +- **Settled: explicit-path staging is still worth doing** — but on *design + + big-repo* grounds, not toy-repo latency (its measured payoff there is ~0.7 s). It + **caps the O(N) walk on the 1179-file target**, **never visits the ~260 images** + (150 MB it would otherwise scan), lets us **drop the macOS-cruft filter**, and + aligns the git layer with what the editor changed. +- **Open: the ~600 ms/op libgit2 overhead** is now the largest single mystery in + the commit and likely the highest-value fix — if it's ODB refresh or reflog + writes, it may be a cheap config/flag change that speeds up *every* commit + regardless of repo size or staging. `git_bench` decides. **Localize it before + committing effort to (a).** + +**Recommendation:** run `git_bench` to pin the libgit2 overhead; then implement +explicit-path staging for the design + big-repo reasons; the SD/card levers are +retired. + +## Adjacent lever: should the images be on the card at all? + +Explicit-path staging makes the walk skip the images, but they still cost 150 MB +of SD space, inflate the 570 MB clone, and slow provisioning + the pull-before-push +paths. Whether the device should carry image blobs at all — vs. markdown-only, or +Git-LFS-style pointers — is a separate decision tracked in +[`../notes/git-sync-images-and-repo-size.md`](../notes/git-sync-images-and-repo-size.md). +That lever shrinks N and the clone; this one stops the walk from paying for N. They +compose. + +## What this does *not* touch + +The network half of `:sync` (TLS handshake + push round-trips, ~6.5 s of the warm +path) is a separate floor covered in [`sync-latency.md`](../notes/sync-latency.md); +this curve is only about the local commit. Radio *frequency* (how often we pay any +sync at all) is [`wifi-auto-sync.md`](wifi-auto-sync.md). diff --git a/firmware/Cargo.toml b/firmware/Cargo.toml index 0bb9b32..9daf44d 100644 --- a/firmware/Cargo.toml +++ b/firmware/Cargo.toml @@ -36,6 +36,22 @@ name = "sd_fat" path = "src/bin/sd_fat.rs" harness = false +# SD/FAT primitive-op micro-benchmark — attributes the ~700 ms/loose-object write +# floor (see docs/tradeoff-curves/sync-commit-staging.md). Pure SD, no git feature. +# Flash with `just flash-bench`. +[[bin]] +name = "sd_bench" +path = "src/bin/sd_bench.rs" +harness = false + +# git-level micro-benchmark — localizes the ~700 ms/object libgit2 overhead (see +# docs/tradeoff-curves/sync-commit-staging.md). Needs the `git` feature. +[[bin]] +name = "git_bench" +path = "src/bin/git_bench.rs" +harness = false +required-features = ["git"] + # Spike 9 — boot splash. Standalone bench program that paints the Typoena # wordmark-in-a-circle on the EPD. No git, no SD, no Wi-Fi. Flash with # `just flash-splash`. diff --git a/firmware/justfile b/firmware/justfile index 5ee8c09..2d63c1f 100644 --- a/firmware/justfile +++ b/firmware/justfile @@ -80,6 +80,32 @@ flash-sd: monitor-sd: espflash monitor --elf {{elf_sd}} +# SD primitive-op micro-benchmark — attributes the ~700 ms/loose-object write +# floor (docs/tradeoff-curves/sync-commit-staging.md). Writes only to /sd/sdbench. +build-bench: + {{esp_env}} cargo build --release --bin sd_bench + +# build + flash + monitor the SD bench +flash-bench: + {{esp_env}} cargo run --release --bin sd_bench + +# serial monitor for the SD bench, with decoded backtraces +monitor-bench: + espflash monitor --elf target/xtensa-esp32s3-espidf/release/sd_bench + +# git-level micro-benchmark — localizes the ~700 ms/object libgit2 overhead +# (docs/tradeoff-curves/sync-commit-staging.md). Read-mostly on /sd/repo. +build-gitbench: + {{esp_env}} {{git_env}} cargo build --release --bin git_bench --features git + +# build + flash + monitor the git-level bench +flash-gitbench: + {{esp_env}} {{git_env}} cargo run --release --bin git_bench --features git + +# serial monitor for the git-level bench, with decoded backtraces +monitor-gitbench: + espflash monitor --elf target/xtensa-esp32s3-espidf/release/git_bench + # Spike 9 — build the boot splash spike (no .env needed) build-splash: {{esp_env}} cargo build --release --bin splash diff --git a/firmware/src/bin/git_bench.rs b/firmware/src/bin/git_bench.rs new file mode 100644 index 0000000..ff730dd --- /dev/null +++ b/firmware/src/bin/git_bench.rs @@ -0,0 +1,118 @@ +//! git-level micro-benchmark — localizes the ~700 ms/object libgit2 overhead the +//! `:sync` commit split showed (2026-07-12), now that `sd_bench` proved the raw +//! card does a *full* loose-object write (stat+create+write+rename) in ~86 ms. +//! The ~8× gap between that and `write_tree`'s 710 ms lives inside libgit2, not +//! FAT — this bench times the git2 ODB/index primitives in isolation to find it. +//! +//! Read-mostly on `/sd/repo`: the only writes are unreferenced ("orphan") loose +//! blobs — never reachable from a ref, so never pushed, and gc-able — plus +//! rewrites of the existing index/tree (idempotent). Safe on the test card. +//! +//! Flash with `just flash-gitbench` (needs the `git` feature; env in the recipe). + +use std::time::Instant; + +use anyhow::{Context, Result}; +use esp_idf_svc::hal::delay::FreeRtos; +use git2::{IndexEntry, IndexTime, ObjectType, Oid, Repository, Signature}; + +use firmware::git_sync::GIT_STACK; +use firmware::persistence::{Storage, REPO_DIR}; + +const BUILD_TAG: &str = concat!("build ", env!("BUILD_TIME"), " @", env!("BUILD_GIT")); + +/// Iterations per op. Small — some ops write to the card, and the first vs rest +/// spread (min vs max) is itself the signal (e.g. write vs freshen-skip). +const N: usize = 10; + +fn main() -> Result<()> { + esp_idf_svc::sys::link_patches(); + esp_idf_svc::log::EspLogger::initialize_default(); + log::info!("Typoena — git-level bench, {BUILD_TAG}"); + + // libgit2 nests ~67 KB of GIT_PATH_MAX stack buffers (postmortem #3), so the + // git work must run on the same 96 KB stack the real git service uses. On the + // small main-task stack `index.write()` overflows → nested panic → boot loop. + let handle = std::thread::Builder::new() + .name("git_bench".into()) + .stack_size(GIT_STACK) + .spawn(run) + .expect("spawn git_bench thread"); + match handle.join() { + Ok(Ok(())) => log::info!("git_bench: done"), + Ok(Err(e)) => log::error!("git_bench failed: {e:?}"), + Err(_) => log::error!("git_bench thread panicked"), + } + loop { + FreeRtos::delay_ms(1000); + } +} + +fn run() -> Result<()> { + let _sd = Storage::mount().context("mounting SD")?; + + // Repository open — one-time, but shows the cost of scanning .git (config, + // refs, ODB backends/packs) which every later op may implicitly refresh. + let t = Instant::now(); + let repo = Repository::open(REPO_DIR) + .with_context(|| format!("opening git repo at {REPO_DIR}"))?; + log::info!("Repository::open {:.1} ms", t.elapsed().as_micros() as f64 / 1000.0); + + // 1) odb.write(blob) in isolation — unique content each iter forces a real + // write (no freshen-skip). This is the single number that localizes it: if + // ~86 ms the ODB write path is fine and the cost is in the tree/ref layer; + // if ~700 ms the cost is inside the ODB write itself (deflate/sha/freshen). + let odb = repo.odb().context("opening odb")?; + summarize("odb.write(blob)", time_each(|i| { + let data = format!("typoena git_bench orphan blob #{i} — unique so the write is real\n"); + odb.write(ObjectType::Blob, data.as_bytes()) + .map(|_| ()) + .context("odb.write") + })?); + + // 2) repo.index() — cost of loading the index from the card each time. + summarize("repo.index() open", time_each(|_| { + repo.index().map(|_| ()).context("index open") + })?); + + // 3) index.write() — serialize + checksum + filebuf (index.lock → rename). + let mut idx = repo.index().context("opening index")?; + summarize("index.write()", time_each(|_| { + idx.write().context("index.write") + })?); + + // 4) index.write_tree() — build tree(s) from the index and write to the ODB. + // First call writes the tree; later calls find it exists (freshen-skip), so + // min≈build+exists and max≈build+write — the spread separates the two. + summarize("index.write_tree()", time_each(|_| { + idx.write_tree().map(|_| ()).context("write_tree") + })?); + + Ok(()) +} + +/// Run `op(i)` for `i in 0..N`, returning each call's wall time in microseconds. +fn time_each Result<()>>(mut op: F) -> Result> { + let mut times = Vec::with_capacity(N); + for i in 0..N { + let t = Instant::now(); + op(i)?; + times.push(t.elapsed().as_micros() as u64); + } + Ok(times) +} + +/// Log min / p50 / mean / max in ms for a set of per-call microsecond timings. +fn summarize(label: &str, mut times: Vec) { + times.sort_unstable(); + let n = times.len(); + let mean = times.iter().sum::() / n as u64; + let ms = |us: u64| us as f64 / 1000.0; + log::info!( + "{label:<26} min {:>6.1} p50 {:>6.1} mean {:>6.1} max {:>6.1} ms", + ms(times[0]), + ms(times[n / 2]), + ms(mean), + ms(times[n - 1]), + ); +} diff --git a/firmware/src/bin/sd_bench.rs b/firmware/src/bin/sd_bench.rs new file mode 100644 index 0000000..86fd648 --- /dev/null +++ b/firmware/src/bin/sd_bench.rs @@ -0,0 +1,148 @@ +//! SD/FAT primitive-op micro-benchmark — investigating the ~700 ms-per-loose- +//! object write floor found in the `:sync` commit split (2026-07-12, see +//! `docs/tradeoff-curves/sync-commit-staging.md`). +//! +//! The split showed a single small git loose object (`write_tree` = one tree +//! object) takes ~710 ms to land on the card, and it is **not** fsync +//! (`GIT_OPT_ENABLE_FSYNC_GITDIR` is off). libgit2's loose-object write +//! (`odb_loose.c` `loose_backend__write` → `git_filebuf_commit_at`) is, per object: +//! +//! stat(final) — freshen probe, misses (our `utimes` stub → `stat`) +//! open+write+close — a temp file (`GIT_FILEBUF_TEMPORARY`) +//! [mkdir objects/xx once per fan-out] +//! p_rename — our stub: remove(final) [ENOENT] + rename(temp → final) +//! +//! i.e. **two directory-mutating writes** (temp create + rename) per object. This +//! bench times each FAT primitive in isolation, then a composite that mirrors the +//! sequence above, so we can attribute the ~700 ms to specific ops and get a +//! baseline to compare an A1/A2 card or a 20 MHz bus against. It never touches +//! `/sd/repo` — all work is in `/sd/sdbench`, cleaned up at the end. +//! +//! Flash with `just flash-bench`. Needs no `.env`, no `git` feature (pure SD). + +use std::fs::{self, File}; +use std::io::Write; +use std::time::Instant; + +use anyhow::{Context, Result}; +use esp_idf_svc::hal::delay::FreeRtos; + +use firmware::persistence::Storage; + +/// Injected by build.rs so serial output identifies the exact build. +const BUILD_TAG: &str = concat!("build ", env!("BUILD_TIME"), " @", env!("BUILD_GIT")); + +/// Scratch dir on the card ROOT — outside `/sd/repo`, so a later `:sync` never +/// stages it and the user's notes are never touched. +const BENCH_DIR: &str = "/sd/sdbench"; +/// Iterations per op: enough to read min/p50/mean past controller jitter, few +/// enough that total write volume stays tiny. +const N: usize = 20; +/// ~ the size of a small deflated git loose object (blob/tree/commit). +const PAYLOAD: [u8; 200] = [b'x'; 200]; + +fn main() -> Result<()> { + // Required once before any esp-idf-svc call (see esp-idf-template#71). + esp_idf_svc::sys::link_patches(); + esp_idf_svc::log::EspLogger::initialize_default(); + log::info!("Typoena — SD primitive bench, {BUILD_TAG}"); + match run() { + Ok(()) => log::info!("sd_bench: done"), + Err(e) => log::error!("sd_bench failed: {e:?}"), + } + loop { + FreeRtos::delay_ms(1000); + } +} + +fn run() -> Result<()> { + let sd = Storage::mount().context("mounting SD")?; + let (max_khz, real_khz) = sd.negotiated_khz(); + log::info!("bus: max {max_khz} kHz, negotiated {real_khz} kHz — {N} iters, {}-byte payload", PAYLOAD.len()); + + // Fresh scratch dir. + let _ = fs::remove_dir_all(BENCH_DIR); + fs::create_dir_all(BENCH_DIR).with_context(|| format!("creating {BENCH_DIR}"))?; + + // Warm-up: the first write after mount pays one-time settling — don't measure it. + { + let mut f = File::create(format!("{BENCH_DIR}/warmup"))?; + f.write_all(&PAYLOAD)?; + } + + // 1) create + write(200B) + close, a fresh unique file each time. The drop at + // the block's end is the close (FatFS f_close flushes dir entry + data). + summarize("create+write(200B)+close", time_each(|i| { + let mut f = File::create(format!("{BENCH_DIR}/c{i}"))?; + f.write_all(&PAYLOAD)?; + Ok(()) + })?); + + // 2) rename c{i} -> o{i}. Sources exist from step 1 (untimed setup). + summarize("rename", time_each(|i| { + fs::rename(format!("{BENCH_DIR}/c{i}"), format!("{BENCH_DIR}/o{i}")) + .map_err(Into::into) + })?); + + // 3) stat, hit. + summarize("stat (hit)", time_each(|i| { + fs::metadata(format!("{BENCH_DIR}/o{i}")).map(|_| ()).map_err(Into::into) + })?); + + // 4) stat, miss (ENOENT) — the freshen-probe analogue. A read, expected cheap. + summarize("stat (miss/ENOENT)", time_each(|i| { + let _ = fs::metadata(format!("{BENCH_DIR}/nope{i}")); + Ok(()) + })?); + + // 5) remove o{i}. + summarize("remove", time_each(|i| { + fs::remove_file(format!("{BENCH_DIR}/o{i}")).map_err(Into::into) + })?); + + // 6) Composite: the exact loose-object write sequence libgit2 performs, with a + // git-length (38-hex) final name so LFN directory-entry cost is included. + // If the model is right this lands near the ~700 ms/object from the split. + summarize("loose-object composite", time_each(|i| { + let tmp = format!("{BENCH_DIR}/tmp_obj{i}"); + let fin = format!("{BENCH_DIR}/{i:038x}"); + let _ = fs::metadata(&fin); // freshen probe, misses + { + let mut f = File::create(&tmp)?; // temp create + write + close + f.write_all(&PAYLOAD)?; + } + let _ = fs::remove_file(&fin); // p_rename's remove(to) — ENOENT + fs::rename(&tmp, &fin)?; // temp -> final + Ok(()) + })?); + + // Clean up so the card is left as we found it. + fs::remove_dir_all(BENCH_DIR).with_context(|| format!("removing {BENCH_DIR}"))?; + Ok(()) +} + +/// Run `op(i)` for `i in 0..N`, returning each call's wall time in microseconds. +fn time_each Result<()>>(mut op: F) -> Result> { + let mut times = Vec::with_capacity(N); + for i in 0..N { + let t = Instant::now(); + op(i)?; + times.push(t.elapsed().as_micros() as u64); + } + Ok(times) +} + +/// Log min / p50 / mean / max in ms for a set of per-call microsecond timings. +fn summarize(label: &str, mut times: Vec) { + times.sort_unstable(); + let n = times.len(); + let mean = times.iter().sum::() / n as u64; + let ms = |us: u64| us as f64 / 1000.0; + log::info!( + "{label:<26} min {:>6.1} p50 {:>6.1} mean {:>6.1} max {:>6.1} ms", + ms(times[0]), + ms(times[n / 2]), + ms(mean), + ms(times[n - 1]), + ); +} diff --git a/firmware/src/git_sync.rs b/firmware/src/git_sync.rs index 5e8f115..2a0d2c6 100644 --- a/firmware/src/git_sync.rs +++ b/firmware/src/git_sync.rs @@ -276,6 +276,13 @@ fn stage_and_commit(repo: &Repository) -> Result> { _ => 0, // add } }; + // Split the commit window into its sub-phases so we can tell the FAT + // working-tree *walk* (`add_all`/`update_all` stat every file over SPI) apart + // from the FAT object *writes* (index/tree/commit). This decides whether + // explicit-path staging is worth it: the walk is O(tree size) and avoidable + // (the editor knows the dirty paths), the writes are O(churn) and a floor. + // See docs/tradeoff-curves/sync-commit-staging.md. + let t_walk = Instant::now(); index .add_all(["*"], IndexAddOption::DEFAULT, Some(&mut skip_macos_cruft)) .context("staging new/modified (add --all)")?; @@ -284,11 +291,23 @@ fn stage_and_commit(repo: &Repository) -> Result> { index .update_all(["*"], Some(&mut skip_macos_cruft)) .context("staging deletions (add -u)")?; + let walk_ms = t_walk.elapsed().as_millis(); + + let t_index = Instant::now(); index.write().context("writing index")?; + let index_ms = t_index.elapsed().as_millis(); + + let t_tree = Instant::now(); let tree = repo.find_tree(index.write_tree().context("writing tree")?)?; + let tree_ms = t_tree.elapsed().as_millis(); // Commit on top of the current branch tip (None on an empty/unborn remote). + let t_parent = Instant::now(); let parent = repo.head().ok().and_then(|h| h.peel_to_commit().ok()); + let parent_ms = t_parent.elapsed().as_millis(); + log::info!( + "commit split — walk(add_all+update_all) {walk_ms}ms, index.write {index_ms}ms, write_tree {tree_ms}ms, parent-load {parent_ms}ms" + ); if let Some(p) = &parent { if p.tree_id() == tree.id() { log::info!("nothing to publish — tree unchanged @ {}", short(p.id())); @@ -299,10 +318,16 @@ fn stage_and_commit(repo: &Repository) -> Result> { let sig = Signature::now(AUTHOR_NAME, AUTHOR_EMAIL).context("building signature")?; let message = format!("Typoena publish — unix {}", now_unix()); let parents: Vec<&Commit> = parent.iter().collect(); + let t_commit = Instant::now(); let oid = repo .commit(Some("HEAD"), &sig, &sig, &message, &tree, &parents) .context("creating commit")?; - log::info!("committed {} — free heap {}", short(oid), free_heap()); + let commit_ms = t_commit.elapsed().as_millis(); + log::info!( + "commit split — commit-obj {commit_ms}ms; committed {} — free heap {}", + short(oid), + free_heap() + ); Ok(Some(oid)) }