diff --git a/crates/benilla-app/src/ui_script/lifecycle.rs b/crates/benilla-app/src/ui_script/lifecycle.rs index 7828d93c..c9f17758 100644 --- a/crates/benilla-app/src/ui_script/lifecycle.rs +++ b/crates/benilla-app/src/ui_script/lifecycle.rs @@ -366,14 +366,20 @@ pub(crate) fn run_pending_entry_load(world: &mut World) { world.remove_resource::(); let start = std::time::Instant::now(); load_ingame_ui_on_world_entry(world); - // What the chunk cache did for this load, beside the load's own cost: a cache that is - // installed and a cache that is working are different claims, and this is the line that tells - // them apart on the player's machine. + report_load(world, start, covering, "world entry"); +} + +/// What a load cost and what the chunk cache did for it. Both roots that build the in-game UI +/// report, because a `/reload` is the one the player waits through and it used to say nothing at +/// all: the cache line sat on the entry path only, so the load that benefits most from a warm +/// cache was the one with no evidence it had one. +fn report_load(world: &World, start: std::time::Instant, covering: bool, root: &str) { + // A cache that is installed and a cache that is working are different claims, and this is the + // line that tells them apart on the player's machine. info!("ui_script: {}", benilla_ui::script::chunk_cache_line()); - // Every entry logs the load's cost, whether the cover hid it, and the session every - // `VmMemo` keys on. + // The load's cost, whether a cover hid it, and the session every `VmMemo` keys on. info!( - "ui_script: in-game UI up in {:.0} ms (behind the cover: {}, vm session: {})", + "ui_script: in-game UI up in {:.0} ms ({root}, behind the cover: {}, vm session: {})", start.elapsed().as_secs_f32() * 1000.0, covering, world @@ -803,6 +809,8 @@ pub(crate) fn run_pending_reload(world: &mut World) { return; } info!("ui_script: ReloadUI — ending the UI session and building a new one"); + // From here, because the saved-variable writes are part of the blocked frame the player sees. + let start = std::time::Instant::now(); // One VM for the reload, not two. The boot VM [`end_ui_session`] leaves is for the roots that // stop there (leaving the world, quitting); here [`load_ingame_ui_on_world_entry`] mints its // own at once in [`mint_entry_vm`], so building one in between only to drop it unused paid for @@ -822,6 +830,10 @@ pub(crate) fn run_pending_reload(world: &mut World) { }; end_session(world, after); load_ingame_ui_on_world_entry(world); + let covering = world + .get_resource::() + .is_some_and(|s| s.covering()); + report_load(world, start, covering, "reload"); } /// `AppExit`, the quit roots, read as a message because a quit from in-world never leaves diff --git a/crates/benilla-ui/src/script/mod.rs b/crates/benilla-ui/src/script/mod.rs index 74d5ca11..9ef33ec7 100644 --- a/crates/benilla-ui/src/script/mod.rs +++ b/crates/benilla-ui/src/script/mod.rs @@ -1518,15 +1518,19 @@ fn chunk_stats() -> std::sync::MutexGuard<'static, ChunkStats> { .unwrap_or_else(|p| p.into_inner()) } -/// One line naming what the cache saved, for a harness or a load edge to print. +/// One line naming what the cache saved **since this was last asked**, and the counters reset: +/// a load edge asks once per load, so every line is that load's own work rather than a running +/// total in which a warm `/reload` would hide behind the cold login before it. pub fn chunk_cache_line() -> String { - let s = chunk_stats(); - format!( + let mut s = chunk_stats(); + let line = format!( "lua chunks: {} compiled in {:.0} ms, {} loaded from cache in {:.0} ms, keys {:.0} ms", s.misses, s.miss_ns as f64 / 1e6, s.hits, s.hit_ns as f64 / 1e6, s.key_ns as f64 / 1e6, - ) + ); + *s = ChunkStats::default(); + line }