load: a reload says what it cost and what the chunk cache did for it

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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn

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::<PendingEntryUiLoad>();
     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::<crate::loading_screen::LoadingScreen>()
+        .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

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
 }