From b7ddc18782ff16529b5b20d11214fb6b8f1f1f23 Mon Sep 17 00:00:00 2001 From: grom Date: Mon, 19 Oct 2026 07:59:45 -0600 Subject: [PATCH] load: a reload says what it cost and what the chunk cache did for it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Both lines sat on the world-entry path, so the load the player actually waits through — the `/reload` — reported nothing at all. His 2026-10-19 session has two of them, 4,981 ms and 6,276 ms against the 7.5-9 s he started from, and the log cannot say where either went or whether the bytecode cache was hit, although the cache directory proves it was: 1,585 entries written at first load, 14 added across both reloads. `report_load` now runs on both roots and names which one. The reload's clock starts before the saved-variable writes, because those are part of the one blocked frame he sees, which is also what the `frame hitch` warn measures. `chunk_cache_line` resets its counters on read, so each line is that load's own work rather than a running total in which a warm reload hides behind the cold login before it. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-app/src/ui_script/lifecycle.rs | 24 ++++++++++++++----- crates/benilla-ui/src/script/mod.rs | 12 ++++++---- 2 files changed, 26 insertions(+), 10 deletions(-) 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 }