fix(sync): survive push heap exhaustion and instrument the push path

Run 4 (2026-07-13): remote.push() consumed ~6 MB of PSRAM over 66 s and
the UI thread aborted on Frame::new_white's per-draw vec![0xFF; 26928].
Run 5 confirmed the UI now survives, but the push still exhausts both
pools (a ~7 KB inflateInit fails inside the pack build) and the heap
telemetry never fired — hence the telemetry rework.

- display/editor: Editor::draw_into() renders into a caller-owned
  Frame; main.rs keeps two boot-time frames (shown/back) and mem::swaps
  on success, so steady-state repaints never allocate.
- git_sync: odb cache capped at 1 MB via raw libgit2-sys opts (git2
  0.20 doesn't wrap the total cap); log_push_heap at pre-push,
  post-push and push-failure with largest-PSRAM-block and per-pool
  min-evers; pack_progress logging is now time-gated (2 s) — the
  count gate (+256 objects) never fired because AddingObjects reports
  total=0 and a small push inserts only dozens of objects.
- editor: empty/whitespace snippets file parses as 0 snippets instead
  of a JSON error at boot.
- build.rs: refuse a git-feature build with unset TW_* publish vars —
  a bare `cargo build --features git` baked empty creds and produced a
  firmware whose :sync could never work.
This commit is contained in:
Julien Calixte
2026-07-13 21:04:18 +02:00
parent 05706478a2
commit f79d13453a
6 changed files with 182 additions and 23 deletions

View File

@@ -110,7 +110,7 @@ esp-idf-svc = { git = "https://github.com/esp-rs/esp-idf-svc.git" }
# do; `build-light` doesn't, so the component is an empty no-op). git2/libgit2-sys
# run in system mode (LIBGIT2_NO_VENDOR=1) purely for the Rust bindings, with
# default features off to avoid dragging in openssl-sys/libssh2-sys.
git = ["dep:git2"]
git = ["dep:git2", "dep:libgit2-sys"]
[dependencies]
anyhow = "1"
@@ -124,6 +124,11 @@ keymap = { path = "../keymap" }
editor = { path = "../editor" }
display = { path = "../display" }
git2 = { version = "0.20", default-features = false, optional = true }
# Already in the tree under git2 (same system-mode build); named directly for
# the raw `git_libgit2_opts` calls git2 doesn't wrap — the odb-cache cap
# (GIT_OPT_SET_CACHE_MAX_SIZE) and cache telemetry (GIT_OPT_GET_CACHED_MEMORY)
# that git_sync sets against the run-4 push OOM (2026-07-13).
libgit2-sys = { version = "0.18", default-features = false, optional = true }
esp-idf-svc = { version = "0.52.1", features = ["critical-section", "embassy-time-driver", "embassy-sync"] }
# Remove `generic-queue-8` if you plan to use `embassy-time` WITH `embassy-executor`
embassy-time = { version = "0.5", features = ["generic-queue-8"] }

View File

@@ -47,6 +47,30 @@ fn main() {
println!("cargo:rerun-if-env-changed={var}");
}
// A git-feature build with an empty publish config can only ever fail at
// runtime (git_sync's publish_cycle guard), so refuse it here instead.
// env!() bakes the values at compile time and only `just` dotenv-loads
// firmware/.env — a plain `cargo build --features git` in a bare shell
// silently produced a firmware whose `:sync` could never work (bit the
// 2026-07-13 flash). TW_WIFI_PASS may be legitimately empty (open network)
// and TW_AUTHOR_* have runtime defaults, so only the four required vars
// are checked.
if std::env::var("CARGO_FEATURE_GIT").is_ok() {
let missing: Vec<&str> = ["TW_WIFI_SSID", "TW_REMOTE_URL", "TW_GH_USER", "TW_PAT"]
.into_iter()
.filter(|v| std::env::var(v).map_or(true, |val| val.is_empty()))
.collect();
if !missing.is_empty() {
panic!(
"git-feature build without publish config: {} unset/empty. \
Build through `just build` (dotenv-loads firmware/.env), or \
source firmware/.env into this shell. For a no-git editor \
build use `just build-light` (drops --features git).",
missing.join(", ")
);
}
}
// Pointing rerun-if-changed at a file that never exists forces this
// script to rerun on every build, keeping BUILD_TIME fresh.
println!("cargo:rerun-if-changed=.force-build-stamp");

View File

@@ -81,6 +81,15 @@ const SNTP_TIMEOUT: Duration = Duration::from_secs(20);
/// now also runs here, but it's shallow next to libgit2's path-buffer nesting.
pub const GIT_STACK: usize = 96 * 1024;
/// Cap on libgit2's odb object cache (default max: 256 MB — unbounded on this
/// device). Run 4 (2026-07-13): the real-repo push ground through pack-building
/// for 66 s and PSRAM hit the floor — the UI aborted on a 27 KB framebuffer
/// alloc. Every tree/commit the push's walks read lands in this cache, and
/// nothing bounded it. 1 MB still holds the whole tree set the push's two
/// full-tree walks share (mark-uninteresting over origin's tip, then the insert
/// over ours — near-identical trees), so the second walk stays off the SD card.
const ODB_CACHE_MAX_BYTES: isize = 1024 * 1024;
/// A request to publish. The UI task has already saved every dirty buffer to
/// the card before sending this; `paths` is `Storage::take_dirty`'s snapshot —
/// the repo-relative paths saved or `:delete`d since the last confirmed
@@ -130,6 +139,15 @@ pub fn run_git_service(
if let Err(e) = git2::opts::set_mwindow_mapped_limit(4 * 1024 * 1024) {
log::error!("set_mwindow_mapped_limit failed ({e}); first pack access may OOM");
}
// Odb cache cap (see ODB_CACHE_MAX_BYTES). git2 0.20 wraps only the
// per-object-type limit, not the total, so this one is a raw call.
let rc = libgit2_sys::git_libgit2_opts(
libgit2_sys::GIT_OPT_SET_CACHE_MAX_SIZE as i32,
ODB_CACHE_MAX_BYTES,
);
if rc < 0 {
log::error!("set cache_max_size failed (rc {rc}); a push may exhaust the heap");
}
}
// Lazily initialised on the first request, then reused across publishes.
@@ -507,9 +525,34 @@ fn try_push(repo: &Repository, refspec: &str) -> Result<(), PushFailure> {
Ok(())
});
}
// Progress + heap tracing through the otherwise-silent stretch between the
// TLS verify and the first byte sent (66 s in runs 4 and 5, OOM both times).
{
// Time-gated, NOT count-gated: during AddingObjects libgit2 reports
// `total` = 0 and `current` = objects inserted so far, and a two-commit
// push only inserts a few dozen objects — run 5's `current >= last+256`
// gate swallowed every callback and the grind stayed silent. libgit2
// already rate-limits to ~2/s (MIN_PROGRESS_UPDATE_INTERVAL); gate to
// ~1 line per 2 s on top of that.
let mut last: Option<Instant> = None;
cbs.pack_progress(move |stage, current, total| {
if last.is_none_or(|t| t.elapsed() >= Duration::from_secs(2)) {
last = Some(Instant::now());
log_push_heap(&format!("pack {stage:?} {current}/{total}"));
}
});
let mut next_bytes: usize = 0;
cbs.push_transfer_progress(move |current, total, bytes| {
if bytes >= next_bytes || (total > 0 && current == total) {
next_bytes = bytes + 64 * 1024;
log_push_heap(&format!("send {current}/{total} objects, {bytes} B"));
}
});
}
let mut opts = PushOptions::new();
opts.remote_callbacks(cbs);
log_push_heap("pre-push");
// A non-fast-forward can also surface here, not just via the callback:
// libgit2 compares against origin's advertised tips during negotiation and
// errors out of push() with ErrorCode::NotFastForward before sending
@@ -518,6 +561,11 @@ fn try_push(repo: &Repository, refspec: &str) -> Result<(), PushFailure> {
// (bit the 2026-07-13 run 3: the real-repo rejection surfaced as "push
// transport" and skipped the reconcile built for it).
remote.push(&[refspec], Some(&mut opts)).map_err(|e| {
// Heap post-mortem: run 5 died on a ~7 KB inflateInit inside the pack
// build ("failed to init zlib stream on unpack") — the min-ever lines
// here say which pool zeroed and whether it was exhaustion or
// fragmentation, even when no progress callback got a chance to fire.
log_push_heap("push failed");
if e.code() == git2::ErrorCode::NotFastForward {
PushFailure::Rejected(format!("{refspec}: {}", e.message()))
} else {
@@ -528,6 +576,7 @@ fn try_push(repo: &Repository, refspec: &str) -> Result<(), PushFailure> {
if let Some(msg) = rejection.borrow().clone() {
return Err(PushFailure::Rejected(msg));
}
log_push_heap("post-push");
log::info!("push accepted by remote");
Ok(())
}
@@ -661,3 +710,39 @@ fn internal_free_heap() -> u32 {
fn min_free_heap() -> u32 {
unsafe { sys::esp_get_minimum_free_heap_size() }
}
/// One-line heap + odb-cache snapshot for the push path. Runs 4 and 5
/// (2026-07-13) each spent ~65 s inside `remote.push()` while something
/// consumed ~6 MB of PSRAM (run 4: the UI aborted on a framebuffer alloc;
/// run 5: a ~7 KB inflateInit failed inside the pack build). These lines
/// exist to name the consumer: `largest PSRAM` distinguishes exhaustion from
/// fragmentation, and the per-pool min-evers survive to the failure log even
/// when the spike itself fell between two callbacks.
fn log_push_heap(stage: &str) {
let (mut cached, mut allowed): (isize, isize) = (0, 0);
// SAFETY: GET_CACHED_MEMORY only writes the two out-params.
unsafe {
libgit2_sys::git_libgit2_opts(
libgit2_sys::GIT_OPT_GET_CACHED_MEMORY as i32,
&mut cached as *mut isize,
&mut allowed as *mut isize,
);
}
let (largest_psram, min_psram, min_internal) = unsafe {
(
sys::heap_caps_get_largest_free_block(sys::MALLOC_CAP_SPIRAM),
sys::heap_caps_get_minimum_free_size(sys::MALLOC_CAP_SPIRAM),
sys::heap_caps_get_minimum_free_size(sys::MALLOC_CAP_INTERNAL),
)
};
log::info!(
"push heap [{stage}]: free {} ({} internal), largest PSRAM {}, min-ever PSRAM {} / internal {}, odb cache {}/{} KB",
free_heap(),
internal_free_heap(),
largest_psram,
min_psram,
min_internal,
cached / 1024,
allowed / 1024
);
}

View File

@@ -186,6 +186,13 @@ fn main() -> anyhow::Result<()> {
// (every FULL_REFRESH_EVERY updates) clears any residue.
let mut shown = ed.draw(true);
epd.display_frame_partial_window(shown.bytes(), 0, epd::HEIGHT)?;
// The only two framebuffers the loop ever uses, both allocated here at
// boot: every repaint below renders into `back` (`draw_into` reuses its
// allocation) and swaps it with `shown` on success. A repaint must never
// allocate — a background `:sync` push can take the heap to the floor, and
// a failed `Vec` alloc aborts the whole app (the 2026-07-13 OOM: 66 s into
// the push, one HalfPageUp repaint died on a 27 KB framebuffer).
let mut back = Frame::new_white();
// Boot-time measurement (the ≤ 5 s v0.1 / ≤ 3 s v1.0 target). Two clocks, and
// they disagree by ~1.4 s here, so report both. `esp_log_timestamp()` counts
@@ -292,26 +299,26 @@ fn main() -> anyhow::Result<()> {
UpToDate => "up to date".to_string(),
Failed(reason) => reason,
});
let f = ed.draw(true);
if let Err(e) = epd.display_frame_partial_window(f.bytes(), 0, epd::HEIGHT) {
ed.draw_into(&mut back, true);
if let Err(e) = epd.display_frame_partial_window(back.bytes(), 0, epd::HEIGHT) {
log::warn!("sync-notice repaint FAILED ({e}); full refresh next");
force_full = true;
continue;
}
shown = f;
std::mem::swap(&mut shown, &mut back);
cursor_shown = true;
continue;
}
// A connect/disconnect while idle must still repaint the panel flag —
// no keystroke will arrive to trigger it otherwise.
if kbd_changed {
let f = ed.draw(true);
if let Err(e) = epd.display_frame_partial_window(f.bytes(), 0, epd::HEIGHT) {
ed.draw_into(&mut back, true);
if let Err(e) = epd.display_frame_partial_window(back.bytes(), 0, epd::HEIGHT) {
log::warn!("kbd-flag repaint FAILED ({e}); full refresh next");
force_full = true;
continue;
}
shown = f;
std::mem::swap(&mut shown, &mut back);
cursor_shown = true;
log::info!("keyboard {}", if kbd { "connected" } else { "disconnected" });
continue;
@@ -348,12 +355,12 @@ fn main() -> anyhow::Result<()> {
&& last_activity.elapsed().as_millis() >= CURSOR_DEBOUNCE_MS
{
ed.refresh_stats();
let f = ed.draw(true);
if let Err(e) = epd.display_frame_partial_window(f.bytes(), 0, epd::HEIGHT) {
ed.draw_into(&mut back, true);
if let Err(e) = epd.display_frame_partial_window(back.bytes(), 0, epd::HEIGHT) {
log::warn!("caret repaint FAILED ({e}); full refresh next");
force_full = true;
} else {
shown = f;
std::mem::swap(&mut shown, &mut back);
cursor_shown = true;
log::info!("caret shown");
}
@@ -375,14 +382,13 @@ fn main() -> anyhow::Result<()> {
// and View render their caret regardless of this flag.
let insert_cursor_on = ed.mode() != Mode::Insert;
let prev_scroll = ed.scroll_top();
let frame = ed.draw(insert_cursor_on);
ed.draw_into(&mut back, insert_cursor_on);
let scrolled = ed.scroll_top() != prev_scroll;
// Only the rows that changed since the last shown frame need updating.
let Some((y0, y1)) = changed_rows(shown.bytes(), frame.bytes()) else {
shown = frame;
let Some((y0, y1)) = changed_rows(shown.bytes(), back.bytes()) else {
cursor_shown = ed.mode() != Mode::Insert;
continue; // no visible change
continue; // no visible change (the frames are identical — no swap needed)
};
// Snap the band to whole text lines so a partial-window boundary never
// lands mid-glyph — otherwise the boundary gate crops tall characters.
@@ -398,18 +404,18 @@ fn main() -> anyhow::Result<()> {
let periodic = updates % FULL_REFRESH_EVERY == 0;
let additive = ed.mode() == Mode::Insert
&& !scrolled
&& only_adds_ink(shown.bytes(), frame.bytes(), y0, y1);
&& only_adds_ink(shown.bytes(), back.bytes(), y0, y1);
let t0 = Instant::now();
// `force_full` promotes to a full refresh after a failed paint: it
// rewrites both RAM banks, recovering from a partial that may have died
// mid-transfer and desynced them.
let (result, refresh) = if periodic || force_full {
(epd.display_frame(frame.bytes()), "FULL")
(epd.display_frame(back.bytes()), "FULL")
} else if additive {
(epd.display_frame_partial_window(frame.bytes(), y0, y1 - y0 + 1), "windowed")
(epd.display_frame_partial_window(back.bytes(), y0, y1 - y0 + 1), "windowed")
} else {
(epd.display_frame_partial_window(frame.bytes(), 0, epd::HEIGHT), "full-area")
(epd.display_frame_partial_window(back.bytes(), 0, epd::HEIGHT), "full-area")
};
let ms = t0.elapsed().as_millis();
if let Err(e) = result {
@@ -428,7 +434,7 @@ fn main() -> anyhow::Result<()> {
"{refresh} refresh #{updates} [{:?}]: {ms} ms (rows {y0}..={y1}, {keys} key(s))",
ed.mode()
);
shown = frame;
std::mem::swap(&mut shown, &mut back);
cursor_shown = ed.mode() != Mode::Insert;
}
}