layout: name the write that asks for a whole-graph derivation
`[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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn
This commit is contained in:
@@ -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<PlateFeed> {
|
||||
.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<PlateFeed> {
|
||||
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
|
||||
|
||||
@@ -199,7 +199,12 @@ fn summarize(win: &Window) -> Summary {
|
||||
/// `Option<Res<_>>` 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<UiFrameCost>, mesh: Option<Res<UiMeshCost>>, mut win: ResMut<Window>) {
|
||||
fn report(
|
||||
cost: Res<UiFrameCost>,
|
||||
mesh: Option<Res<UiMeshCost>>,
|
||||
script: Option<NonSendMut<benilla_ui::script::UiScript>>,
|
||||
mut win: ResMut<Window>,
|
||||
) {
|
||||
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<UiFrameCost>, mesh: Option<Res<UiMeshCost>>, 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();
|
||||
}
|
||||
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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<std::collections::HashMap<(&'static str, u32), u64>>,
|
||||
/// 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=<secs>:<n>` 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;
|
||||
}
|
||||
|
||||
@@ -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::<u32>().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"
|
||||
);
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user