julien/typewriter
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

perf(sync): instrument and benchmark commit-staging latency

Browse Source 
Break the stage+commit window into sub-phases (FAT working-tree walk vs
object writes) via `commit split —` log lines, and add two micro-benchmarks
(sd_bench for SD/FAT primitive ops, git_bench for libgit2 object overhead)
with justfile recipes. Documents the walk-vs-writes cost model in
tradeoff-curves/sync-commit-staging.md to decide whether explicit-path
staging over the editor's dirty set is worth replacing add_all(["*"]).
This commit is contained in:
Julien Calixte
2026-07-12 12:24:50 +02:00
parent beb11eda5e
commit 456c4c43e7
8 changed files with 520 additions and 5 deletions
Download Patch File Download Diff File Expand all files Collapse all files

118
firmware/src/bin/git_bench.rs Normal file
View File

@@ -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<F: FnMut(usize) -> Result<()>>(mut op: F) -> Result<Vec<u64>> {
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<u64>) {
times.sort_unstable();
let n = times.len();
let mean = times.iter().sum::<u64>() / 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]),
);
}

148
firmware/src/bin/sd_bench.rs Normal file
View File

@@ -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<F: FnMut(usize) -> Result<()>>(mut op: F) -> Result<Vec<u64>> {
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<u64>) {
times.sort_unstable();
let n = times.len();
let mean = times.iter().sum::<u64>() / 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]),
);
}

27
firmware/src/git_sync.rs
View File

@@ -276,6 +276,13 @@ fn stage_and_commit(repo: &Repository) -> Result<Option<git2::Oid>> {
_ => 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<Option<git2::Oid>> {
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<Option<git2::Oid>> {
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))
}