From c1a56f98ab7bd6a67f76813ba16c61c8c29c6cd9 Mon Sep 17 00:00:00 2001 From: grom Date: Tue, 20 Oct 2026 19:17:44 -0600 Subject: [PATCH] layout: name the write that asks for a whole-graph derivation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `[ui-phases]` could say a window paid for 61 whole-graph derivations. It could not say which of the forty-odd `touch_layout` sites asked for them, and that is the half a fix has to be aimed at. Measured on the player's interface, one derivation costs ~15.5 ms — from two directions: the derivation count explains total resolve time at r = +0.977 across twenty windows (solve count: r = -0.33, so solves are free and derivations are everything), and 26 of 78 worst-single-call figures over 1 ms land in the 15-16 ms bin across eleven unrelated handlers by six authors, two of which fired exactly once for their whole window. Eleven handlers cannot each independently be 15.5 ms slow; it is one shared charge landing on whoever reads the graph first, which is also why the same session shows `resolve` p99 at 14.4 ms and worst frames "mostly tick". One defect, two accounts. So `#[track_caller]` down the naming chain and a tally of `file:line`, printed in the report. Not a backtrace: `WOW_LAYOUT_DERIVE_TRACE` already captures those and has to be rationed to `n` prints because of what they cost. This is a `(&'static str, u32)` key off `Location::caller()`, cheap enough to leave armed, and take-and-rearm so a window reports its own rows and a VM replaced by `/rl` re-arms without anybody noticing it was replaced. Also a `[churn]` window in tick_bench, which records a negative: a plate roster turning over 4-in-40 every ten frames costs **zero** derivations on the player's own interface. `sync_nameplates` pools the plate frames, so a new key rewrites an existing plate and mints nothing. With `resolve_bench`'s hover-sweep, tooltip-content and moving-region tests all asserting zero, four candidate triggers are now ruled out offline and the live tally is what names the real one. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- .../src/addon_harness/tick_bench_tests.rs | 109 ++++++++++++++++++ .../benilla-app/src/ui_script/cost_report.rs | 20 +++- crates/benilla-ui/src/script/mod.rs | 23 ++++ crates/benilla-ui/src/script/model.rs | 36 +++++- .../src/script/tests/layout_gate.rs | 77 +++++++++++++ 5 files changed, 259 insertions(+), 6 deletions(-) diff --git a/crates/benilla-app/src/addon_harness/tick_bench_tests.rs b/crates/benilla-app/src/addon_harness/tick_bench_tests.rs index 8260f8a2..3034af52 100644 --- a/crates/benilla-app/src/addon_harness/tick_bench_tests.rs +++ b/crates/benilla-app/src/addon_harness/tick_bench_tests.rs @@ -29,6 +29,12 @@ const PLATES: u32 = 40; /// Frames per timed window. const FRAMES: u32 = 240; +/// How many of the forty plates turn over at a time, and how often. Four every ten frames is a +/// sixth of a second between arrivals — brisk for a pull, and deliberately so: the question is +/// what one arrival costs, and a rate that makes them countable answers it. +const CHURN_WIDTH: u32 = 4; +const CHURN_EVERY: u32 = 10; + fn ms(t: Instant) -> f64 { t.elapsed().as_secs_f64() * 1000.0 } @@ -90,6 +96,37 @@ fn plate_feeds() -> Vec { .collect() } +/// A derivation count as a divisor. +#[allow(clippy::cast_precision_loss)] +fn per_derive(derives: u64) -> f64 { + derives as f64 +} + +/// The same pull with the roster turning over, which is what a fight is: a mob dies, another +/// walks into range, the camera turns and four plates the engine had never seen appear at once. +/// +/// This is the shape a fixed plate set cannot measure, and the one grom's combat sessions are made +/// of. A plate with a key the model has not minted before creates frames and regions, and +/// `Model::frame_id`/`region_id` call `touch_layout()` on every mint — "a new frame always opens +/// the layout gate" — which gives up naming and makes the next resolve derive the **whole** graph. +/// On his 80-addon interface that graph is ~42,000 regions. +/// +/// `cohort` rotates the key space, so every `CHURN_EVERY` frames `CHURN_WIDTH` of the forty plates +/// are strangers. Everything else is held still: same geometry, same count, same screen positions, +/// so a difference against the static window is the churn and nothing else. +fn plate_feeds_churning(cohort: u32) -> Vec { + let mut feeds = plate_feeds(); + for i in 0..CHURN_WIDTH.min(PLATES) { + // A key no previous cohort used, so the model has to mint for it. + let key = 0x4000 + u64::from(cohort) * u64::from(CHURN_WIDTH) + u64::from(i); + let f = &mut feeds[i as usize]; + f.state.key = key; + f.state.name = format!("Defias Recruit {key:x}"); + f.unit = live(key, "Defias Recruit"); + } + feeds +} + /// Which of the app's unit tokens this frame's feed fills. `Grouped` is the crowded pull every /// token answers for; `Solo` is one player alone with nothing targeted, which is most of a real /// session and the shape a grouped feed cannot measure: a handler that asks about a token nobody @@ -561,6 +598,78 @@ fn tick_bench() { } } + // ── What a turning-over plate roster costs ────────────────────────────────────────────── + // + // The three windows above hold forty plates still, which is a settled interface — and that is + // why they never reproduced the thing the player reports. A combat session's plates arrive and + // leave, every arrival mints frame and region ids, every mint calls `Model::touch_layout()`, + // and that gives up naming so the next resolve derives the whole graph instead of a named + // subtree. The measured cost of one such derivation on the shipped UI alone is 2.84 ms + // (`ui_script::resolve_bench`); this is the same question asked of the player's real graph, + // which is an order of magnitude bigger. + // + // Static first and churning second, back to back, everything but the keys held equal: same + // plate count, same geometry, same positions, same feed. + { + let mut row = |label: &str, churn: bool| { + for _ in 0..30 { + feed_units(&mut s, Company::Grouped); + s.sync_nameplates(GEOMETRY, &plates); + s.tick(1.0 / 60.0); + answer_measures(&mut s); + s.resolve(); + } + let _ = s.take_errors(); + let (solves, derives) = (s.layout_solves(), s.layout_derivations()); + let (mut resolve_ms, mut tick_ms, mut worst_ms) = (0.0, 0.0, 0.0_f64); + for frame in 0..FRAMES { + feed_units(&mut s, Company::Grouped); + if churn { + s.sync_nameplates(GEOMETRY, &plate_feeds_churning(frame / CHURN_EVERY)); + } else { + s.sync_nameplates(GEOMETRY, &plates); + } + let a = Instant::now(); + s.tick(1.0 / 60.0); + tick_ms += ms(a); + let b = Instant::now(); + answer_measures(&mut s); + s.resolve(); + let this = ms(b); + resolve_ms += this; + worst_ms = worst_ms.max(this); + } + let derives = s.layout_derivations() - derives; + println!( + "[churn] {label:<8} resolve {:.3} ms/f (worst frame {worst_ms:.1} ms) · \ + vm-tick {:.3} ms/f · {:.2} solves/f · {:.3} derivations/f \ + ({derives} in {FRAMES} frames){}", + resolve_ms / per, + tick_ms / per, + (s.layout_solves() - solves) as f64 / per, + f64::from(u32::try_from(derives).unwrap_or(u32::MAX)) / per, + if derives > 0 { + format!(" → {:.2} ms each", resolve_ms / per_derive(derives)) + } else { + String::new() + }, + ); + for (site, n) in s.take_layout_derive_sites().iter().take(4) { + println!("[churn] {label:<8} {n:5} from {site}"); + } + }; + row("static", false); + row("churning", true); + // Measured 2026-10-20 on the player's own 92-addon interface: **zero** derivations in both + // windows, resolve 0.005 ms/f. So a plate roster that turns over is not what makes his + // combat sessions derive the graph 1.8-61 times every five seconds — `sync_nameplates` + // pools the plate frames, a new key rewrites an existing plate, and nothing is minted. + // Kept because that negative is worth holding on to: with `a_hover_sweep_across_owners`, + // `a_tooltip_content_change` and `a_region_moving_every_frame` in `resolve_bench` all + // asserting zero, four of the obvious triggers are now ruled out offline, and the live + // `[ui-phases]` site tally is what names the real one. + } + // ── What one addon bug costs a frame ──────────────────────────────────────────────────── // // mlua's protected call installs a message handler that, for every stack level, searches the diff --git a/crates/benilla-app/src/ui_script/cost_report.rs b/crates/benilla-app/src/ui_script/cost_report.rs index 1c929c77..d44f8f54 100644 --- a/crates/benilla-app/src/ui_script/cost_report.rs +++ b/crates/benilla-app/src/ui_script/cost_report.rs @@ -199,7 +199,12 @@ fn summarize(win: &Window) -> Summary { /// `Option>` for the mesh cost: it belongs to `ui_pass`, and an instrument must not be the /// reason a configuration that builds one plugin without the other fails to start. Absent, the /// mesh row reads zero, which is also what it reads on a frame that rebuilt nothing. -fn report(cost: Res, mesh: Option>, mut win: ResMut) { +fn report( + cost: Res, + mesh: Option>, + script: Option>, + mut win: ResMut, +) { let mesh = mesh.map(|m| (m.rebuilt, m.total, m.runs, m.rewrites)); let (mesh_rebuilt, mesh_total, mesh_runs, mesh_rewrites) = mesh.unwrap_or((false, 0, 0, 0)); // `stamped` and not `pass.live`: the pass can be live and still return before the paint wrote @@ -270,6 +275,19 @@ fn report(cost: Res, mesh: Option>, mut win: ResMut rate(win.mesh_runs, per), rate(win.mesh_rewrites, per), ); + // Where those derivations came from: a `derives` figure with no site list is a number nobody + // can act on. The first take arms the tally, so the first window reports no sites and every + // later one reports its own; `derives` itself is right from frame one. + if let Some(script) = script { + let sites = script.take_layout_derive_sites(); + if !sites.is_empty() { + let total: u64 = sites.iter().map(|(_, n)| n).sum(); + eprintln!("[ui-phases] {total} whole-graph derivations asked for, by write site:"); + for (site, n) in sites.iter().take(6) { + eprintln!("[ui-phases] {n:6} {site}"); + } + } + } win.clear(); } diff --git a/crates/benilla-ui/src/script/mod.rs b/crates/benilla-ui/src/script/mod.rs index d73c604c..4e450b84 100644 --- a/crates/benilla-ui/src/script/mod.rs +++ b/crates/benilla-ui/src/script/mod.rs @@ -1301,6 +1301,29 @@ impl UiScript { self.model_ref().layout_derives } + /// **Where** those derivations were asked for: `(file:line, count)` since the last take, + /// costliest first. The site is the write's own line, carried by `#[track_caller]` down the + /// naming chain rather than a backtrace, so this is cheap enough to leave on. + /// + /// Take-and-rearm, and the first take is what arms it — a caller that asks every window gets + /// that window's rows, a VM nobody asks pays one branch per derivation, and a VM replaced by + /// `/rl` re-arms on the next ask without anybody having to notice it was replaced. + pub fn take_layout_derive_sites(&self) -> Vec<(String, u64)> { + let mut model = self.model_mut(); + let taken = model + .layout_derive_sites + .replace(std::collections::HashMap::new()); + let Some(sites) = taken else { + return Vec::new(); + }; + let mut rows: Vec<(String, u64)> = sites + .into_iter() + .map(|((file, line), n)| (format!("{file}:{line}"), n)) + .collect(); + rows.sort_by(|a, b| b.1.cmp(&a.1).then_with(|| a.0.cmp(&b.0))); + rows + } + /// Fixpoint rounds across every solve; over [`Self::layout_solves`], the per-pass depth. pub fn layout_rounds(&self) -> u64 { self.model_ref().layout_rounds diff --git a/crates/benilla-ui/src/script/model.rs b/crates/benilla-ui/src/script/model.rs index 0355a279..95a76781 100644 --- a/crates/benilla-ui/src/script/model.rs +++ b/crates/benilla-ui/src/script/model.rs @@ -389,6 +389,12 @@ pub(crate) struct Model { /// Full layout-graph derivations: 0 on a steady UI, so a rise means a write fell back to /// `touch_layout`. The `WOW_LAYOUT_VERIFY` re-run's derivation is not counted. pub(crate) layout_derives: u64, + /// Where the writes that force a whole-graph derivation came from: `file:line` of the Lua + /// binding or engine site, to a count. The derivation count on its own says a frame paid for + /// one and not which of the forty-odd `touch_layout` sites asked; this is that half, and it is + /// what a fix has to be aimed at. Populated only while [`Self::layout_derive_sites`] has been + /// asked for, so a session that does not look pays one branch. + pub(crate) layout_derive_sites: Option>, /// The last solve's width, `(frames solved, regions swept)`. pub(crate) layout_last_scope: (usize, usize), /// Fixpoint rounds run across all solves. @@ -1610,6 +1616,7 @@ impl Model { msg_lines_hashed: 0, layout_verify_recheck: false, layout_derives: 0, + layout_derive_sites: None, layout_scope: super::layout::LayoutScope::default(), layout_last_scope: (0, 0), layout_epoch_resolved: None, @@ -2072,6 +2079,7 @@ impl Model { /// A layout write that names no node. The resolve's tooltip pre-pass must not call this, or /// the gate never closes; a missed call is caught by `WOW_LAYOUT_VERIFY`. + #[track_caller] pub(crate) fn touch_layout(&mut self) { // Naming nothing, the next resolve derives the graph in full: slow, never wrong. self.give_up_naming(); @@ -2168,6 +2176,7 @@ impl Model { /// Names a frame without bumping the epoch, for the resolve's own tooltip pre-pass: a bump /// inside a resolve would hold the gate open for good, yet an unnamed write could go stale. + #[track_caller] pub(crate) fn note_layout_frame_write(&mut self, h: FrameHandle) { if self.layout_touched.is_some() { match self.frame_to_id.get(&h) { @@ -2183,6 +2192,7 @@ impl Model { } /// `note_layout_frame_write` for a region. + #[track_caller] pub(crate) fn note_layout_region_write(&mut self, rh: RegionHandle) { if self.layout_touched.is_some() { match self.region_to_id.get(&rh) { @@ -2198,6 +2208,7 @@ impl Model { } /// Names `id` as what this write moved, if the cached graph has it and naming is still on. + #[track_caller] fn touch_layout_node(&mut self, id: u32) { let in_graph = self.layout_scope.has_node(id); match &mut self.layout_touched { @@ -2211,12 +2222,27 @@ impl Model { /// Every write that gives up naming comes through here, so the next resolve derives in full. /// `WOW_LAYOUT_DERIVE_TRACE=:` backtraces the first `n` of these after `secs`. + #[track_caller] fn give_up_naming(&mut self) { - if self.layout_touched.is_some() && derive_trace_armed() { - eprintln!( - "[layout-derive] the ledger gave up naming, at:\n{}", - std::backtrace::Backtrace::force_capture() - ); + if self.layout_touched.is_some() { + if derive_trace_armed() { + eprintln!( + "[layout-derive] the ledger gave up naming, at:\n{}", + std::backtrace::Backtrace::force_capture() + ); + } + // `#[track_caller]` all the way down this chain, so the location is the write site — + // one of the forty-odd `touch_layout` callers — and not this function. A backtrace + // says the same thing and costs a thousand times as much, which is why the trace above + // has to be rationed to `n` prints and this does not. + if let Some(sites) = self.layout_derive_sites.as_mut() { + // `(&'static str, u32)`, not a formatted `String`: `Location::caller()` hands back + // a `&'static Location`, so the file is already static and the key costs nothing. + // This path runs thousands of times a session; formatting it would be the + // instrument's own cost showing up in the measurement. + let at = std::panic::Location::caller(); + *sites.entry((at.file(), at.line())).or_insert(0) += 1; + } } self.layout_touched = None; } diff --git a/crates/benilla-ui/src/script/tests/layout_gate.rs b/crates/benilla-ui/src/script/tests/layout_gate.rs index 08878298..57c6cb7e 100644 --- a/crates/benilla-ui/src/script/tests/layout_gate.rs +++ b/crates/benilla-ui/src/script/tests/layout_gate.rs @@ -488,3 +488,80 @@ fn a_retargeted_anchor_follows_its_new_target() { "the plate must not follow its OLD target any more (310), got {plate_now}" ); } + +/// A derivation count says a frame paid for a whole-graph derive; it never said which of the +/// forty-odd `touch_layout` sites asked, and that is the half a fix has to be aimed at. +/// +/// So the site tally, carried by `#[track_caller]` down the naming chain rather than by a +/// backtrace. Asserted here as a relation, not a line number: the recorded site must be a real +/// source position in this crate's own layout code, and must **not** be `model.rs`'s +/// `give_up_naming` itself — which is what a missing `#[track_caller]` anywhere in the chain +/// collapses every row to, making the whole tally useless while still looking populated. +#[test] +fn a_derivation_names_the_write_site_and_not_the_bookkeeper() { + let mut s = script(); + // A ledger has to exist before a write can give up naming it, and a resolve is what opens one. + // `give_up_naming` tallies only the transition out of a live ledger, which is also why the + // counts sum to the derivation count rather than to the number of writes. + s.run(r#"seed = CreateFrame("Frame", "Seed", nil)"#) + .expect("seed"); + s.resolve(); + s.resolve(); + // The first take arms it; nothing before this is counted. + assert!( + s.take_layout_derive_sites().is_empty(), + "unarmed, the tally has nothing to say" + ); + s.run( + r#" + f = CreateFrame("Frame", "Named", nil); f:SetWidth(10); f:SetHeight(10) + f:SetPoint("TOPLEFT", nil, "TOPLEFT", 0, 0) + "#, + ) + .expect("setup"); + s.resolve(); + let rows = s.take_layout_derive_sites(); + assert!( + !rows.is_empty(), + "creating a frame gives up naming — if this is empty the tally is not being written, and \ + every reading taken from it is a false negative" + ); + for (site, n) in &rows { + assert!(*n > 0, "a row with no count should not exist: {site}"); + let (file, line) = site.rsplit_once(':').expect("site is file:line"); + assert!( + file.ends_with(".rs"), + "a site should be a source position, got {site}" + ); + assert!( + line.parse::().is_ok(), + "a site's line should be a number, got {site}" + ); + } + // Take-and-rearm: the rows just read must not be counted again. + assert!( + s.take_layout_derive_sites().is_empty(), + "a take leaves the tally empty, or every window reports the session's running total" + ); + + // And the assertion that catches the failure the doc above describes. A missing + // `#[track_caller]` anywhere in the chain does not empty the tally — it collapses every row + // onto `give_up_naming`'s own line, so the tally looks healthy and says nothing. Two triggers + // that give up naming from two different lines must therefore read as two rows: minting a + // frame id and minting a region id are different writes and the report has to tell them apart. + for step in [ + r#"g = CreateFrame("Frame", "Another", nil)"#, + r#"fs = Another:CreateFontString(nil, "ARTWORK")"#, + ] { + s.run(step).expect("trigger"); + s.resolve(); + s.resolve(); + } + let mixed = s.take_layout_derive_sites(); + let distinct: std::collections::BTreeSet<&str> = + mixed.iter().map(|(site, _)| site.as_str()).collect(); + assert!( + distinct.len() >= 2, + "two different writes should name two different sites, got {distinct:?} — every row on one line means a `#[track_caller]` is missing from the naming chain and the tally is reporting its own bookkeeper" + ); +}