From db6242d2d399c6d0b17142f33431829adc0d342c Mon Sep 17 00:00:00 2001 From: Brandon Thomas Date: Sun, 4 Oct 2026 15:10:18 -0400 Subject: [PATCH] Issue #37: Catalog: instrument persistence (append, snapshot stages) and whole-frame update time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Journal::stats(): last/max append time (encode + write + sync_data), snapshot count, last snapshot by stage (serialise, write+sync+rename, log reset, bytes, records), slowest snapshot. Reported by `library.info` → `persistence`; printed per write to stderr under LIGHTCRAFT_PROFILE. - UI: `perf.frame_ms` only covers layout (`LightcraftApp::ui`); `logic()` (control channel, shortcuts, render polling, `persist_if_dirty`) ran untimed. Add `logicMs`, `updateMs` (logic + layout) and `maxUpdateMs` to `ui.inspect` → perf and a "Frame update" row to Help ▸ System Info. - `crates/catalog/examples/persist_bench.rs`: synthetic 1k/10k/85k-photo catalogs (90 % Local browse records) on FsStore: append latency, compaction at the 2,000-record threshold, load. Baseline (release, load avg ~240, so absolute times are inflated; median of 3 compactions): 1k photos (3.6 MB snap): append 7 ms, compaction 31 ms (serialise 5, write+sync 12, reset 14) 10k photos (36.5 MB): append 15 ms, compaction 528 ms (serialise 463, write+sync 56) 85k photos (310 MB): append 12 ms, compaction 4.6 s (serialise 2.2-4.4 s, write+sync 0.25-0.8 s); peak RSS 963 MB; load 4.7 s Co-Authored-By: Claude Opus 5.5 --- Cargo.lock | 1 + crates/catalog/Cargo.toml | 1 + crates/catalog/examples/persist_bench.rs | 123 +++++++++++++++++++++++ crates/catalog/src/journal.rs | 83 ++++++++++++++- crates/catalog/src/lib.rs | 2 +- crates/engine/src/cmd/library.rs | 1 + crates/engine/src/tests_library.rs | 6 ++ crates/ui-egui/src/control.rs | 2 +- crates/ui-egui/src/lib.rs | 25 ++++- crates/ui-egui/src/menus.rs | 4 + 10 files changed, 243 insertions(+), 5 deletions(-) create mode 100644 crates/catalog/examples/persist_bench.rs diff --git a/Cargo.lock b/Cargo.lock index 10f38d5a..60a82a26 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2099,6 +2099,7 @@ dependencies = [ "serde", "serde_json", "thiserror 2.0.21", + "web-time", ] [[package]] diff --git a/crates/catalog/Cargo.toml b/crates/catalog/Cargo.toml index fb772703..47508359 100644 --- a/crates/catalog/Cargo.toml +++ b/crates/catalog/Cargo.toml @@ -15,6 +15,7 @@ serde_json = { workspace = true } thiserror = { workspace = true } crc32fast = { workspace = true } log = { workspace = true } +web-time = { workspace = true } [dev-dependencies] proptest = { workspace = true } diff --git a/crates/catalog/examples/persist_bench.rs b/crates/catalog/examples/persist_bench.rs new file mode 100644 index 00000000..e59f3e66 --- /dev/null +++ b/crates/catalog/examples/persist_bench.rs @@ -0,0 +1,123 @@ +//! Catalog persistence costs on large synthetic catalogs (issue #37): log append, compaction +//! (snapshot serialise / write+fsync / log reset), load, and a catalog clone. +//! +//! ```text +//! cargo run --release -p lightcraft-catalog --example persist_bench -- [photos…] +//! ``` +//! +//! `` is a scratch directory (wiped per size). Default sizes: 1000 10000 85000. 90 % of the +//! photos are Local browse records, the rest library photos with a few edits and history steps. +//! Peak memory: run under `/usr/bin/time -l` (macOS) / `-v` (Linux) with one size. + +use std::sync::Arc; +use std::time::Instant; + +use lightcraft_catalog::*; +use lightcraft_develop::DevelopSettings; + +fn ms(t: Instant) -> f64 { + t.elapsed().as_secs_f64() * 1e3 +} + +fn photo(c: &mut Catalog, i: u64) -> Photo { + let id = c.alloc_photo_id(); + let mut p = Photo::new(id, Source::File { path: format!("/Users/someone/Pictures/2026/09/{:05}/IMG_{i:05}.CR3", i / 500) }, &format!("IMG_{i:05}.CR3"), "CR3", 6000, 4000, "2026-09-30T12:00:00"); + p.kind = MediaKind::Raw; + p.file_size = 25_000_000 + i; + p.captured = Some(format!("2026-09-{:02}T10:{:02}:{:02}", 1 + i % 28, i % 60, (i / 60) % 60)); + p.content_hash = Some(format!("{:032x}", i.wrapping_mul(0x9e37_79b9_7f4a_7c15))); + p.meta.camera = "Camera Model X".into(); + p.meta.lens = "24-70mm f/2.8".into(); + p.meta.focal_mm = Some(35.0); + p.meta.aperture = Some(4.0); + p.meta.shutter = "1/250".into(); + p.meta.iso = Some(400); + p.as_shot_wb = Some((5200.0, 3.0)); + p.local = !i.is_multiple_of(10); + if !p.local { + let mut d = DevelopSettings::default(); + d.light.exposure = (i % 7) as f64 * 0.1; + let s = Arc::new(d); + p.develop = s.clone(); + p.edited = Some("2026-09-30T12:00:00".into()); + p.history = vec![HistoryStep { label: "Exposure".into(), settings: s }]; + p.rating = (i % 6) as u8; + } + p +} + +fn stats(mut v: Vec) -> String { + v.sort_by(f64::total_cmp); + let pick = |q: f64| v.get(((v.len() as f64 - 1.0) * q).round() as usize).copied().unwrap_or(0.0); + format!("median {:.2} ms, p95 {:.2} ms, max {:.2} ms", pick(0.5), pick(0.95), pick(1.0)) +} + +fn main() -> std::result::Result<(), Box> { + let mut args = std::env::args().skip(1); + let dir = std::path::PathBuf::from(args.next().ok_or("usage: persist_bench [photos…]")?); + let mut sizes: Vec = args.map(|a| a.parse()).collect::>()?; + if sizes.is_empty() { + sizes = vec![1000, 10_000, 85_000]; + } + for n in sizes { + let _ = std::fs::remove_dir_all(&dir); + let (mut j, _, _) = Journal::open(Box::new(FsStore::open(&dir)?))?; + let mut cat = Catalog::new(); + // bulk-add (as one import would) and log it, so the first compaction is an import's + for chunk in (0..n).collect::>().chunks(500) { + let ops: Vec = chunk.iter().map(|i| Op::AddPhoto { photo: Box::new(photo(&mut cat, *i)) }).collect(); + for op in &ops { + cat.apply(op.clone())?; + } + j.append(&ops)?; + } + j.snapshot(&cat)?; + let first = j.stats().last_snapshot; + println!("== {n} photos ({} local): snapshot {:.1} MB", cat.photos().filter(|p| p.local).count(), first.bytes as f64 / 1e6); + + let t = Instant::now(); + let copy = cat.clone(); + println!(" catalog clone: {:.2} ms", ms(t)); + drop(copy); + + // single-op appends (a rating change each), as commands do + let ids: Vec = cat.photos().map(|p| p.id).take(1000).collect(); + let mut appends = Vec::new(); + for k in 0..300usize { + let id = ids.get(k % ids.len().max(1)).copied().unwrap_or(PhotoId(1)); + let op = Op::SetRating { id, rating: (k % 6) as u8 }; + cat.apply(op.clone())?; + j.append(std::slice::from_ref(&op))?; + appends.push(j.stats().last_append_ms); + } + println!(" append (1 op, fsync): {}", stats(appends)); + + // compactions at the default threshold crossing + let mut totals = Vec::new(); + for _ in 0..3 { + while !j.wants_snapshot() { + let op = Op::SetRating { id: ids.first().copied().unwrap_or(PhotoId(1)), rating: (j.seq() % 6) as u8 }; + cat.apply(op.clone())?; + j.append(&[op])?; + } + j.snapshot(&cat)?; + let s = j.stats().last_snapshot; + println!( + " compaction ({} records): serialize {:.1} ms, write+sync {:.1} ms, log reset {:.1} ms, total {:.1} ms", + s.records, s.serialize_ms, s.write_sync_ms, s.reset_ms, s.total_ms + ); + totals.push(s.total_ms); + } + println!(" compaction total: {}", stats(totals)); + + drop(j); + let t = Instant::now(); + let (_, loaded, _) = Journal::open(Box::new(FsStore::open(&dir)?))?; + println!(" open (load snapshot + replay): {:.1} ms", ms(t)); + if loaded.len() != cat.len() { + return Err("reloaded catalog differs".into()); + } + } + let _ = std::fs::remove_dir_all(&dir); + Ok(()) +} diff --git a/crates/catalog/src/journal.rs b/crates/catalog/src/journal.rs index f7089c06..965fdc45 100644 --- a/crates/catalog/src/journal.rs +++ b/crates/catalog/src/journal.rs @@ -55,6 +55,52 @@ pub struct LoadReport { pub created: bool, } +/// Where persistence time goes (reported by `library.info` → `persistence`; printed to stderr +/// per write under `LIGHTCRAFT_PROFILE`). Times are wall-clock milliseconds on the calling +/// thread, i.e. how long the caller (the UI thread, for the app) was blocked. +#[derive(Clone, Copy, Debug, Default, PartialEq, serde::Serialize)] +#[serde(rename_all = "camelCase")] +pub struct PersistStats { + /// [`Journal::append`] calls that wrote something. + pub appends: u64, + /// Encode + write + `sync_data` of the last / slowest append. + pub last_append_ms: f64, + pub max_append_ms: f64, + /// Snapshots written (compactions, plus the ones on close / repair). + pub snapshots: u64, + /// The last snapshot, by stage. + pub last_snapshot: SnapshotTiming, + /// Total time of the slowest snapshot. + pub max_snapshot_ms: f64, +} + +/// One snapshot (compaction), by stage. +#[derive(Clone, Copy, Debug, Default, PartialEq, serde::Serialize)] +#[serde(rename_all = "camelCase")] +pub struct SnapshotTiming { + /// Serialising the catalog to JSON. + pub serialize_ms: f64, + /// Writing, flushing, `sync_all` and the atomic rename of `catalog.snap`. + pub write_sync_ms: f64, + /// Resetting `catalog.log` (an atomic rewrite to empty, fsynced). + pub reset_ms: f64, + pub total_ms: f64, + /// Size of `catalog.snap`. + pub bytes: u64, + /// Log records the snapshot compacted. + pub records: u64, +} + +/// `LIGHTCRAFT_PROFILE` is set: print persistence timings to stderr. +fn profiling() -> bool { + static ON: std::sync::OnceLock = std::sync::OnceLock::new(); + *ON.get_or_init(|| std::env::var_os("LIGHTCRAFT_PROFILE").is_some()) +} + +fn ms_since(t: web_time::Instant) -> f64 { + t.elapsed().as_secs_f64() * 1e3 +} + pub struct Journal { store: Box, /// `seq` of the last durable op. @@ -63,6 +109,7 @@ pub struct Journal { log_records: u64, log_bytes: u64, pub policy: SnapshotPolicy, + stats: PersistStats, } fn io(e: std::io::Error) -> CatalogError { @@ -117,7 +164,7 @@ impl Journal { None => (Catalog::new(), 0), }; report.snapshot_seq = snapshot_seq; - let mut j = Journal { store, seq: snapshot_seq, snapshot_seq, log_records: 0, log_bytes: 0, policy: SnapshotPolicy::default() }; + let mut j = Journal { store, seq: snapshot_seq, snapshot_seq, log_records: 0, log_bytes: 0, policy: SnapshotPolicy::default(), stats: PersistStats::default() }; let log = log.unwrap_or_default(); // Scan records; `good_end` is the byte offset just past the last good record. @@ -190,6 +237,7 @@ impl Journal { if ops.is_empty() { return Ok(()); } + let t0 = web_time::Instant::now(); let mut buf = String::new(); let mut seq = self.seq; for op in ops { @@ -201,22 +249,55 @@ impl Journal { self.seq = seq; self.log_records += ops.len() as u64; self.log_bytes += buf.len() as u64; + let ms = ms_since(t0); + self.stats.appends += 1; + self.stats.last_append_ms = ms; + self.stats.max_append_ms = self.stats.max_append_ms.max(ms); + if profiling() { + eprintln!("catalog: append {} op(s), {} B: {ms:.2} ms", ops.len(), buf.len()); + } Ok(()) } /// Write a snapshot of `catalog` (which must reflect every appended op) and reset the log. pub fn snapshot(&mut self, catalog: &Catalog) -> Result<()> { + let t0 = web_time::Instant::now(); let body = serde_json::to_string(catalog).map_err(|e| CatalogError::Invalid(e.to_string()))?; let file = format!("{{\"format\":\"{FORMAT}\",\"version\":{VERSION},\"seq\":{},\"catalog\":{body}}}\n", self.seq); + let serialize_ms = ms_since(t0); + let t1 = web_time::Instant::now(); self.store.write_atomic(SNAPSHOT, file.as_bytes()).map_err(io)?; + let write_sync_ms = ms_since(t1); + let t2 = web_time::Instant::now(); // A crash here leaves old records in the log; they are skipped by seq on load. self.store.write_atomic(LOG, b"").map_err(io)?; + let reset_ms = ms_since(t2); + let timing = + SnapshotTiming { serialize_ms, write_sync_ms, reset_ms, total_ms: ms_since(t0), bytes: file.len() as u64, records: self.log_records }; + self.record_snapshot(timing); self.snapshot_seq = self.seq; self.log_records = 0; self.log_bytes = 0; Ok(()) } + fn record_snapshot(&mut self, t: SnapshotTiming) { + self.stats.snapshots += 1; + self.stats.last_snapshot = t; + self.stats.max_snapshot_ms = self.stats.max_snapshot_ms.max(t.total_ms); + if profiling() { + eprintln!( + "catalog: snapshot of {} records, {} B: serialize {:.1} ms, write+sync {:.1} ms, log reset {:.1} ms, total {:.1} ms", + t.records, t.bytes, t.serialize_ms, t.write_sync_ms, t.reset_ms, t.total_ms + ); + } + } + + /// Where persistence time went so far. + pub fn stats(&self) -> PersistStats { + self.stats + } + /// The log is long enough to be worth compacting. pub fn wants_snapshot(&self) -> bool { self.log_records >= self.policy.max_records || self.log_bytes >= self.policy.max_bytes diff --git a/crates/catalog/src/lib.rs b/crates/catalog/src/lib.rs index 8241372e..cf7b7a23 100644 --- a/crates/catalog/src/lib.rs +++ b/crates/catalog/src/lib.rs @@ -21,7 +21,7 @@ use std::collections::BTreeMap; use std::sync::Arc; pub use dates::{DateRun, GroupBy}; -pub use journal::{Journal, LoadReport, SnapshotPolicy}; +pub use journal::{Journal, LoadReport, PersistStats, SnapshotPolicy, SnapshotTiming}; pub use keywords::KeywordNode; use lightcraft_develop::DevelopSettings; pub use model::*; diff --git a/crates/engine/src/cmd/library.rs b/crates/engine/src/cmd/library.rs index 35c54eff..0ba56911 100644 --- a/crates/engine/src/cmd/library.rs +++ b/crates/engine/src/cmd/library.rs @@ -866,6 +866,7 @@ pub fn specs() -> Vec { "logRecords": j.log_records(), "logBytes": j.log_bytes(), "lastError": lib.last_error, + "persistence": j.stats(), "cache": cache, "load": { "created": lib.report.created, diff --git a/crates/engine/src/tests_library.rs b/crates/engine/src/tests_library.rs index 6b8ee8d9..952c2e1e 100644 --- a/crates/engine/src/tests_library.rs +++ b/crates/engine/src/tests_library.rs @@ -121,6 +121,12 @@ fn new_library_without_seed_is_empty_and_compacts() { let info = s.execute("library.info", &json!({})).unwrap(); assert_eq!(info["logRecords"], 0); assert_eq!(info["snapshotSeq"], info["seq"]); + // persistence timings (issue #37): the append and the compaction were measured + let p = &info["persistence"]; + assert!(p["appends"].as_u64() >= Some(1), "{p}"); + assert!(p["snapshots"].as_u64() >= Some(1), "{p}"); + assert!(p["lastSnapshot"]["bytes"].as_u64() > Some(0), "{p}"); + assert!(p["lastSnapshot"]["totalMs"].as_f64() >= p["lastSnapshot"]["serializeMs"].as_f64(), "{p}"); let s2 = open(&dir, true); assert_eq!(s2.catalog.len(), 0, "an existing library is never seeded"); assert_eq!(s2.catalog.albums().count(), 1); diff --git a/crates/ui-egui/src/control.rs b/crates/ui-egui/src/control.rs index 33e64a04..ca90d323 100644 --- a/crates/ui-egui/src/control.rs +++ b/crates/ui-egui/src/control.rs @@ -78,7 +78,7 @@ pub fn inspect(app: &LightcraftApp, ctx: &egui::Context) -> Value { "selection": app.session.selection.ids.iter().map(|p| p.0).collect::>(), "activeMask": app.session.active_mask, "widgetCount": app.widgets.len(), - "perf": {"frameMs": app.perf.frame_ms, "fps": app.perf.fps, "lastRenderMs": app.renderer.last_main_ms, "renderQueue": app.renderer.queued(), "rendersInFlight": app.renderer.in_flight(), "pendingSlots": app.renderer.pending_slots(), "mergeRunning": app.merge.busy(), "lastMerge": app.merge.last_result, "rendersDone": app.renderer.completed, "thumbTextures": app.renderer.thumb_textures(), "variantTextures": app.renderer.variant_textures(), "gpu": (lightcraft_engine::gpu::ready() && lightcraft_engine::gpu::available()).then(lightcraft_engine::gpu::adapter_name).flatten()}, + "perf": {"frameMs": app.perf.frame_ms, "logicMs": app.perf.logic_ms, "updateMs": app.perf.update_ms, "maxUpdateMs": app.perf.max_update_ms, "fps": app.perf.fps, "lastRenderMs": app.renderer.last_main_ms, "renderQueue": app.renderer.queued(), "rendersInFlight": app.renderer.in_flight(), "pendingSlots": app.renderer.pending_slots(), "mergeRunning": app.merge.busy(), "lastMerge": app.merge.last_result, "rendersDone": app.renderer.completed, "thumbTextures": app.renderer.thumb_textures(), "variantTextures": app.renderer.variant_textures(), "gpu": (lightcraft_engine::gpu::ready() && lightcraft_engine::gpu::available()).then(lightcraft_engine::gpu::adapter_name).flatten()}, "loupe": app.loupe_shown.map(|(p, src)| json!({"photo": p.0, "source": src, "pending": app.renderer.is_pending(crate::render::Slot::Main)})), "hoverPreview": app.hover_preview.as_ref().map(|h| h.label.clone()), "status": app.ui.status, diff --git a/crates/ui-egui/src/lib.rs b/crates/ui-egui/src/lib.rs index 0f848c68..92bd0fd8 100644 --- a/crates/ui-egui/src/lib.rs +++ b/crates/ui-egui/src/lib.rs @@ -88,7 +88,15 @@ pub struct Services { #[derive(Clone, Copy, Debug, Default)] pub struct Perf { + /// Layout of the last frame ([`LightcraftApp::ui`], including commands run from widgets). pub frame_ms: f64, + /// Per-frame logic before layout ([`LightcraftApp::logic`]: control channel, shortcuts, + /// render polling, pending catalog persistence). + pub logic_ms: f64, + /// The whole update of the last frame: logic + layout. + pub update_ms: f64, + /// The slowest whole update since start. + pub max_update_ms: f64, pub fps: f64, } @@ -406,6 +414,12 @@ impl LightcraftApp { /// Per-frame logic before layout (control channel, renders, shortcuts, drops). pub fn logic(&mut self, ctx: &egui::Context) { + let t0 = now_ms(); + self.logic_inner(ctx); + self.perf.logic_ms = now_ms() - t0; + } + + fn logic_inner(&mut self, ctx: &egui::Context) { if !self.styled { theme::install_fonts(ctx); theme::apply(ctx); @@ -537,6 +551,13 @@ impl LightcraftApp { raw.events.extend(self.synthetic.drain(..n)); } + /// Frame timings once layout is done (`t0`: when layout started). + fn end_frame(&mut self, t0: f64) { + self.perf.frame_ms = now_ms() - t0; + self.perf.update_ms = self.perf.logic_ms + self.perf.frame_ms; + self.perf.max_update_ms = self.perf.max_update_ms.max(self.perf.update_ms); + } + /// Lay out the whole window. pub fn ui(&mut self, ui: &mut egui::Ui) { let ctx = ui.ctx().clone(); @@ -557,7 +578,7 @@ impl LightcraftApp { panels::dialogs::show(self, &ctx); panels::toast(self, &ctx); self.widgets = widgets::take_registry(&ctx); - self.perf.frame_ms = now_ms() - t0; + self.end_frame(t0); return; } // Order matters: earlier panels take the full edge (top bar spans the window; the tool strip, @@ -596,7 +617,7 @@ impl LightcraftApp { panels::grid::drag_feedback(self, &ctx); panels::toast(self, &ctx); self.widgets = widgets::take_registry(&ctx); - self.perf.frame_ms = now_ms() - t0; + self.end_frame(t0); } } diff --git a/crates/ui-egui/src/menus.rs b/crates/ui-egui/src/menus.rs index 420d77bb..4cdb85e3 100644 --- a/crates/ui-egui/src/menus.rs +++ b/crates/ui-egui/src/menus.rs @@ -867,6 +867,10 @@ pub fn run_ui_command(app: &mut LightcraftApp, id: &str, p: &Value) -> Option>()); if p.get("open").and_then(Value::as_bool).unwrap_or(true) {