Issue #37: Catalog: instrument persistence (append, snapshot stages) and whole-frame update time

- 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 <noreply@anthropic.com>
This commit is contained in:
Brandon Thomas 2026-10-04 15:10:18 -04:00
parent 840b294e23
commit db6242d2d3
10 changed files with 243 additions and 5 deletions

1
Cargo.lock generated
View File

@ -2099,6 +2099,7 @@ dependencies = [
"serde",
"serde_json",
"thiserror 2.0.21",
"web-time",
]
[[package]]

View File

@ -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 }

View File

@ -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 -- <dir> [photos…]
//! ```
//!
//! `<dir>` 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<f64>) -> 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<dyn std::error::Error>> {
let mut args = std::env::args().skip(1);
let dir = std::path::PathBuf::from(args.next().ok_or("usage: persist_bench <scratch dir> [photos…]")?);
let mut sizes: Vec<u64> = args.map(|a| a.parse()).collect::<std::result::Result<_, _>>()?;
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::<Vec<_>>().chunks(500) {
let ops: Vec<Op> = 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<PhotoId> = 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(())
}

View File

@ -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<bool> = 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<dyn Store>,
/// `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

View File

@ -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::*;

View File

@ -866,6 +866,7 @@ pub fn specs() -> Vec<CommandSpec> {
"logRecords": j.log_records(),
"logBytes": j.log_bytes(),
"lastError": lib.last_error,
"persistence": j.stats(),
"cache": cache,
"load": {
"created": lib.report.created,

View File

@ -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);

View File

@ -78,7 +78,7 @@ pub fn inspect(app: &LightcraftApp, ctx: &egui::Context) -> Value {
"selection": app.session.selection.ids.iter().map(|p| p.0).collect::<Vec<_>>(),
"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,

View File

@ -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);
}
}

View File

@ -867,6 +867,10 @@ pub fn run_ui_command(app: &mut LightcraftApp, id: &str, p: &Value) -> Option<Re
rows.push(("Library".into(), dir.to_string()));
}
rows.push(("Frame time".into(), format!("{:.1} ms ({:.0} fps)", app.perf.frame_ms, app.perf.fps)));
rows.push((
"Frame update".into(),
format!("{:.1} ms (logic {:.1} ms; slowest {:.0} ms)", app.perf.update_ms, app.perf.logic_ms, app.perf.max_update_ms),
));
rows.push(("Last loupe render".into(), format!("{:.0} ms", app.renderer.last_main_ms)));
let r = json!(rows.iter().map(|(k, v)| json!({"label": k, "value": v})).collect::<Vec<_>>());
if p.get("open").and_then(Value::as_bool).unwrap_or(true) {