//! `hover_log.rs` — the **hover-cost recorder** (`WOW_HOVER_LOG`). //! //! The director reports dropped frames while hovering bag items and spells. Reproducing that needs //! a live session and a *hand* on the mouse, which the headless capture harness cannot supply and //! reading `[ui-cost]` lines off a terminal cannot survive: the interesting frames are a handful of //! spikes inside thousands of quiet ones. So this records **every frame** to a file, tagged with //! what the tooltip was showing at the time, and prints a report at exit that ranks the cost //! *against the tooltip state* — hovering vs not, and which hover. //! //! Run: `WOW_HOVER_LOG=1 cargo run --release -p benilla` (writes `target/hover-log.csv`; a path //! value writes there instead). Hover whatever feels bad, for as long as you like, then quit — the //! report prints to the terminal and the raw rows stay in the file. //! //! Columns are one frame each: the wall frame time and the process-CPU delta (the meter vsync //! cannot rail — `perf.rs`), the UI pass's own phase split (tick/resolve/measure/extract/diff, //! μs — the same marks `WOW_UI_COST=1` prints), and the tooltip context (shown, line count, owner //! frame, first line). A spike with flat UI phases is NOT a UI-pass cost, and that negative is the //! most valuable thing this can say. use std::io::Write; use bevy::prelude::*; use bevy::time::Real; use benilla_ui::script::UiScript; /// One frame's UI-pass phase split, in μs — written by [`crate::ui_script::extract::drive_script`] /// under the same marks the `[ui-cost]` line prints, read here. #[derive(Resource, Default, Clone)] pub struct UiFrameCost { /// How many FontStrings the layout asked the font engine to shape this frame, and the first /// few by name — a steady hover that keeps asking is the churn this recorder exists to catch. pub measured: usize, pub measured_texts: Vec, pub tick: u128, pub resolve: u128, pub measure: u128, pub extract: u128, pub convert: u128, pub diff: u128, pub quads: usize, pub solves: u64, pub skipped: bool, } /// Where to write, from `$WOW_HOVER_LOG`: unset ⇒ off, `1` ⇒ the default path, anything else ⇒ /// that path. fn log_path() -> Option { match std::env::var("WOW_HOVER_LOG") { Err(_) => None, Ok(v) if v.is_empty() || v == "0" => None, Ok(v) if v == "1" => Some("target/hover-log.csv".to_string()), Ok(v) => Some(v), } } /// Is the recorder on? Read once — the phase marks in `drive_script` consult this every frame. pub fn enabled() -> bool { static ON: std::sync::OnceLock = std::sync::OnceLock::new(); *ON.get_or_init(|| log_path().is_some()) } /// One recorded frame, kept in memory for the exit report (the file gets it either way). #[derive(Clone)] struct Row { frame_ms: f32, cpu_ms: f32, cost: UiFrameCost, /// The tooltip context: `None` = no tooltip up. `(owner frame, line count, first line)`. tip: Option<(String, i64, String)>, } #[derive(Resource)] struct Recorder { out: std::io::BufWriter, path: String, rows: Vec, prev_cpu: Option, } pub struct HoverLogPlugin; impl Plugin for HoverLogPlugin { fn build(&self, app: &mut App) { if !enabled() { return; } let path = log_path().expect("enabled() checked"); if let Some(dir) = std::path::Path::new(&path).parent() { let _ = std::fs::create_dir_all(dir); } match std::fs::File::create(&path) { Ok(f) => { let mut out = std::io::BufWriter::new(f); let _ = writeln!( out, "frame_ms,cpu_ms,tick_us,resolve_us,measure_us,extract_us,convert_us,\ diff_us,quads,solves,skipped,measured,measured_texts,tip_owner,tip_lines,\ tip_first_line" ); info!("hover log: recording every frame to {path}"); app.insert_resource(Recorder { out, path, rows: Vec::with_capacity(64_000), prev_cpu: None, }) .add_systems(Last, (record, report_on_exit).chain()); } Err(e) => error!("hover log: cannot write {path}: {e}"), } } } /// The tooltip context, asked of the VM itself so it reads the same names the director sees. One /// tiny chunk per frame, only while recording. fn tooltip_context(script: &UiScript) -> Option<(String, i64, String)> { let chunk = r#" if not GameTooltip or not GameTooltip:IsShown() then return "" end local owner = GameTooltip:GetOwner() local name = "(no owner)" if owner and owner.GetName and owner:GetName() then name = owner:GetName() end local first = "" if GameTooltipTextLeft1 and GameTooltipTextLeft1:GetText() then first = GameTooltipTextLeft1:GetText() end return name .. "\t" .. GameTooltip:NumLines() .. "\t" .. first "#; let s: String = script.eval(chunk).ok()?; if s.is_empty() { return None; } let mut parts = s.split('\t'); let owner = parts.next()?.to_string(); let lines = parts.next()?.trim().parse::().ok()? as i64; let first = parts.next().unwrap_or("").to_string(); Some((owner, lines, first)) } /// A CSV cell: quote and escape, and keep it to one line (tooltip text carries `|c` markup). fn cell(s: &str) -> String { format!("\"{}\"", s.replace('"', "\"\"").replace(['\n', '\r'], " ")) } fn record( time: Res>, cost: Res, script: Option>, mut rec: ResMut, ) { let frame_ms = time.delta_secs() * 1000.0; let cpu_now = crate::perf::process_cpu_secs(); let cpu_ms = match (rec.prev_cpu, cpu_now) { (Some(prev), Some(now)) => ((now - prev) * 1000.0) as f32, _ => 0.0, }; rec.prev_cpu = cpu_now; // The very first frame's delta is the startup gap, not a frame. if rec.rows.is_empty() && frame_ms > 100.0 { return; } let tip = script.as_deref().and_then(tooltip_context); let c = cost.clone(); let (owner, lines, first) = tip .clone() .unwrap_or_else(|| (String::new(), 0, String::new())); let _ = writeln!( rec.out, "{frame_ms:.3},{cpu_ms:.3},{},{},{},{},{},{},{},{},{},{},{},{},{lines},{}", c.tick, c.resolve, c.measure, c.extract, c.convert, c.diff, c.quads, c.solves, u8::from(c.skipped), c.measured, cell(&c.measured_texts.join(" ⏎ ")), cell(&owner), cell(&first), ); rec.rows.push(Row { frame_ms, cpu_ms, cost: c, tip, }); } fn pct(sorted: &[f32], p: f32) -> f32 { if sorted.is_empty() { return 0.0; } #[allow(clippy::cast_precision_loss, clippy::cast_possible_truncation)] let i = ((sorted.len() - 1) as f32 * p).round() as usize; sorted[i] } /// One population's line in the report: how many frames, and what they cost. fn summarize(label: &str, rows: &[&Row]) -> String { if rows.is_empty() { return format!(" {label:<34} (no frames)"); } let mut wall: Vec = rows.iter().map(|r| r.frame_ms).collect(); let mut cpu: Vec = rows.iter().map(|r| r.cpu_ms).collect(); wall.sort_by(f32::total_cmp); cpu.sort_by(f32::total_cmp); #[allow(clippy::cast_precision_loss)] let n = rows.len() as f32; let ui_us = |f: fn(&UiFrameCost) -> u128| { rows.iter().map(|r| f(&r.cost) as f64).sum::() / f64::from(n) }; // The churn number: mean FontStrings re-shaped per frame. A settled UI sits at 0.00; anything // above it in a steady hover population is a string whose measure key moves every frame. let measured = rows.iter().map(|r| r.cost.measured as f64).sum::() / f64::from(n); // What the frame actually DID, as opposed to what it cost: how often the layout fixpoint ran // (a solve walks the whole anchor graph, not the tooltip's corner of it) and how often the // extract gate skipped the conversion+rasterize loop outright. #[allow(clippy::cast_precision_loss)] let solves = rows.iter().map(|r| r.cost.solves as f64).sum::() / f64::from(n); let skips = 100.0 * rows.iter().filter(|r| r.cost.skipped).count() as f32 / n; // Counted against the DROPPED threshold, not the raw budget: synced wall time rails at the // display's present grant and jitters around it, so counting frames over 16.7 ms mostly counts // jitter (`perf.rs`'s `DROPPED_FACTOR` — a missed interval is what a player feels). let dropped = rows .iter() .filter(|r| r.frame_ms > crate::perf::FRAME_BUDGET_MS * 1.5) .count(); format!( " {label:<34} n={:<6} wall p50={:>6.2} p99={:>6.2} max={:>7.2} cpu p50={:>6.2} \ p99={:>6.2} dropped={:>5.1}%\n ui μs: tick={:>6.0} resolve={:>6.0} \ measure={:>5.0} extract={:>6.0} convert={:>6.0} diff={:>5.0}\n solves/frame={:.2} \ reshaped/frame={:.2} extract-gate-skipped={:.0}%", rows.len(), pct(&wall, 0.50), pct(&wall, 0.99), wall.last().copied().unwrap_or(0.0), pct(&cpu, 0.50), pct(&cpu, 0.99), 100.0 * dropped as f32 / n, ui_us(|c| c.tick), ui_us(|c| c.resolve), ui_us(|c| c.measure), ui_us(|c| c.extract), ui_us(|c| c.convert), ui_us(|c| c.diff), solves, measured, skips, ) } /// At quit: the ranked read. Splits the run by tooltip state — that split IS the question, and a /// per-owner breakdown says whether one hover channel (bag slot vs spell button) is the expensive /// one. The worst frames print with their tooltip context so a spike is attributable to what was /// under the cursor at the time. fn report_on_exit(mut exits: MessageReader, mut rec: ResMut) { if exits.read().next().is_none() { return; } let _ = rec.out.flush(); let rows: Vec = rec.rows.clone(); if rows.is_empty() { info!("hover log: no frames recorded"); return; } println!("{}", report(&rows, &rec.path)); } /// Re-read a recorded CSV and print the report — `WOW_HOVER_LOG_REPORT=`, handled before the /// app starts (see `main`). The analysis moves faster than the sessions that feed it: a question /// this report cannot yet answer is one column away, and re-deriving it from rows already on disk /// costs nobody a second play session. pub fn report_recorded_file(path: &str) { let text = match std::fs::read_to_string(path) { Ok(t) => t, Err(e) => { eprintln!("hover log: cannot read {path}: {e}"); return; } }; let mut rows = Vec::new(); for line in text.lines().skip(1) { if let Some(r) = parse_row(line) { rows.push(r); } } if rows.is_empty() { eprintln!("hover log: no rows parsed from {path}"); return; } println!("{}", report(&rows, path)); } /// One CSV line back into a [`Row`]. Splits on commas OUTSIDE quotes (the text columns carry /// commas and doubled quotes — `cell`'s escaping, read back). fn parse_row(line: &str) -> Option { let mut fields: Vec = Vec::new(); let mut cur = String::new(); let mut quoted = false; let mut chars = line.chars().peekable(); while let Some(c) = chars.next() { match c { '"' if quoted && chars.peek() == Some(&'"') => { cur.push('"'); chars.next(); } '"' => quoted = !quoted, ',' if !quoted => fields.push(std::mem::take(&mut cur)), _ => cur.push(c), } } fields.push(cur); if fields.len() < 16 { return None; } let num = |i: usize| fields[i].parse::().ok(); let owner = fields[13].clone(); Some(Row { frame_ms: num(0)? as f32, cpu_ms: num(1)? as f32, cost: UiFrameCost { measured: num(11)? as usize, measured_texts: if fields[12].is_empty() { Vec::new() } else { fields[12].split(" ⏎ ").map(str::to_string).collect() }, tick: num(2)? as u128, resolve: num(3)? as u128, measure: num(4)? as u128, extract: num(5)? as u128, convert: num(6)? as u128, diff: num(7)? as u128, quads: num(8)? as usize, solves: num(9)? as u64, skipped: num(10)? != 0.0, }, tip: if owner.is_empty() { None } else { Some((owner, num(14)? as i64, fields[15].clone())) }, }) } /// The report body, shared by the live exit path and the offline reader. fn report(rows: &[Row], path: &str) -> String { let mut out = String::new(); out.push_str("\n==================== HOVER LOG ====================\n"); let all: Vec<&Row> = rows.iter().collect(); let idle: Vec<&Row> = rows.iter().filter(|r| r.tip.is_none()).collect(); let hover: Vec<&Row> = rows.iter().filter(|r| r.tip.is_some()).collect(); out.push_str(&summarize("ALL", &all)); out.push('\n'); out.push_str(&summarize("no tooltip", &idle)); out.push('\n'); out.push_str(&summarize("tooltip up", &hover)); out.push('\n'); // Per hover target, busiest first — one line per owner frame the tooltip was anchored to. let mut by_owner: std::collections::BTreeMap> = Default::default(); for r in &hover { if let Some((owner, _, _)) = &r.tip { by_owner.entry(owner.clone()).or_default().push(r); } } let mut owners: Vec<(String, Vec<&Row>)> = by_owner.into_iter().collect(); owners.sort_by_key(|(_, v)| std::cmp::Reverse(v.len())); for (owner, rs) in owners.iter().take(8) { out.push_str(&summarize(&format!(" ↳ {owner}"), rs)); out.push('\n'); } // The split that separates a STEADY tax from a per-CHANGE one: frames that ran the layout // fixpoint against frames that did not. A hover whose quiet frames are as expensive as its // solving ones has a per-frame problem; one where the cost lives entirely in the solving // frames is paying per content CHANGE — and moving the mouse across a bag grid changes content // constantly, which is the same felt hitch by a different mechanism and a different fix. let solved: Vec<&Row> = hover .iter() .copied() .filter(|r| r.cost.solves > 0) .collect(); let quiet: Vec<&Row> = hover .iter() .copied() .filter(|r| r.cost.solves == 0) .collect(); out.push_str(&summarize("tooltip up · frames that SOLVED", &solved)); out.push('\n'); out.push_str(&summarize("tooltip up · frames that did NOT", &quiet)); out.push('\n'); // The churn roll-up: which strings the font engine was asked to re-shape, and on how many // frames. A string appearing on hundreds of frames is a measure key that never settles — the // per-frame re-shape and the forced second resolve both hang off it, and it is the fix's // target. Counted per frame it appears on, not per request, so one loud string reads as one // row. let mut churn: std::collections::HashMap = Default::default(); for r in rows { for t in &r.cost.measured_texts { let e = churn.entry(t.clone()).or_default(); e.0 += 1; e.1 += usize::from(r.tip.is_some()); } } let mut churn: Vec<(String, (usize, usize))> = churn.into_iter().collect(); churn.sort_by_key(|(_, (all, _))| std::cmp::Reverse(*all)); if !churn.is_empty() { out.push_str(" re-shaped strings (frames seen / of those, with a tooltip up):\n"); for (text, (all, hovering)) in churn.iter().take(15) { out.push_str(&format!(" {all:>6} {hovering:>6} {text:?}\n")); } } // The worst frames, with what was under the cursor. // Ranked by CPU, not wall: under vsync every wall reading rails at the present interval and // says nothing (`perf.rs`) — CPU is the cost meter the rail cannot fool. let mut worst = rows.to_vec(); worst.sort_by(|a, b| b.cpu_ms.total_cmp(&a.cpu_ms)); out.push_str( " worst frames by CPU (cpu ms / wall ms / ui tick+resolve+convert μs / tooltip):\n", ); for r in worst.iter().take(12) { let tip = r.tip.as_ref().map_or_else( || "-".to_string(), |(o, n, f)| format!("{o} [{n} lines] {f}"), ); out.push_str(&format!( " {:>8.2} {:>7.2} {:>6}+{:>6}+{:>6} {tip}\n", r.cpu_ms, r.frame_ms, r.cost.tick, r.cost.resolve, r.cost.convert )); } out.push_str(&format!(" rows: {path}\n")); out.push_str("===================================================\n"); out }