benilla-octo/crates/benilla-ui/src/script/verb_prof.rs

//! Per-verb attribution (`WOW_UI_VERBS=1`): which **binding** an addon's time goes into.
//!
//! [`super::handler_prof`] names the handler and [`super::tick_prof`] names the tick phase, and
//! between them they leave the question this answers. A reload of the player's interface spends
//! 4.47 s inside handler bodies, and single calls there cost hundreds of milliseconds —
//! `pfBag:OnHide` 394 ms in ONE call — which is not Lua arithmetic. A handler's self time includes
//! the engine work it provokes, so that time is ours: it is inside the verbs the handler called
//! (`CreateFrame`, `SetPoint`, `SetTexture`, `Show`), and nothing charged it to them.
//!
//! **How it attaches.** Armed, [`install`] walks `_G` and every widget method table at the end of
//! [`UiScript::new`](super::UiScript::new) — before any FrameXML or addon runs, so every function
//! it finds is one of ours or one of Lua's own, never an addon's — and replaces each with a closure
//! that times the call. Lua's own are in there too, which is why [`STACK_RELATIVE`] exists. A verb that
//! calls back into Lua (a handler fired from inside `Show`) has that nested time inside its own,
//! as the handler profiler's *total* column does; the two instruments read against each other.
//!
//! **Reading it live.** `WOW_UI_VERBS=<secs>` prints a window every `<secs>` from
//! [`report_window`], called at the end of [`UiScript::tick`](super::UiScript::tick) beside the
//! handler and raise reports, so a real session names its own verbs. That route is why the bare
//! `WOW_UI_VERBS=1` the harnesses pass now also means "one second": before it, the only caller of
//! [`log_report`] was the `addon_harness` example's `--together` load, and the profiler armed in
//! the client paid for every call and printed nothing at all.
//!
//! Off, nothing is wrapped and nothing is paid. On, each call costs two `Instant::now`s and an
//! uncontended lock, which is why this is an instrument and not a counter that ships armed.

use std::collections::HashMap;
use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::Mutex;
use std::time::Instant;

use mlua::{Lua, MultiValue, Table, Value};

/// `(calls, nanos)` per verb name, process-wide: the VM is single-threaded, so this lock is
/// uncontended, and a process-wide table lets a harness that builds several VMs read one total.
static ROWS: Mutex<Option<HashMap<String, (u64, u128)>>> = Mutex::new(None);
static ARMED: AtomicBool = AtomicBool::new(false);

/// Whether `WOW_UI_VERBS` armed the profiler, read once.
pub fn armed() -> bool {
    static ON: std::sync::OnceLock<bool> = std::sync::OnceLock::new();
    *ON.get_or_init(|| {
        let on = std::env::var_os("WOW_UI_VERBS").is_some_and(|v| !v.is_empty() && v != "0");
        ARMED.store(on, Ordering::Relaxed);
        on
    })
}

/// The report period from `WOW_UI_VERBS=<secs>`; `0.0` records without ever printing a window,
/// for a caller that prints [`log_report`] on its own schedule. Read once.
fn period() -> f32 {
    static SECS: std::sync::OnceLock<f32> = std::sync::OnceLock::new();
    *SECS.get_or_init(|| {
        std::env::var("WOW_UI_VERBS")
            .ok()
            .and_then(|v| v.trim().parse::<f32>().ok())
            .filter(|s| s.is_finite() && *s > 0.0)
            .unwrap_or(0.0)
    })
}

/// Rows a window prints before rolling the rest into a `… N more` line.
const REPORT_ROWS: usize = 16;

/// Wall seconds and frames since the last window, beside [`ROWS`]: process-wide for the same
/// reason the rows are, so a harness holding several VMs still reads one window.
static WINDOW: Mutex<(f32, u32)> = Mutex::new((0.0, 0));

/// [`ROWS`] as the previous window left it, so a window can be a **delta**.
///
/// It would be shorter to [`reset`] after printing, and wrong: [`ROWS`] is the one table and
/// [`log_report`]'s callers read it whole, at a moment of their own choosing. The `addon_harness`
/// example's `--together` ticks ten times before printing its load bill, so a window that cleared
/// the table would hand it whatever happened after the last window instead of the load. A snapshot
/// costs one clone of a few hundred rows a second and leaves the cumulative table alone.
static PREV: Mutex<Option<Counts>> = Mutex::new(None);

/// Count a ticked frame and print the window when it is due, then start a fresh one.
pub(super) fn report_window(elapsed: f32) {
    if !armed() || period() <= 0.0 {
        return;
    }
    let (window, frames) = {
        let mut w = WINDOW.lock().unwrap_or_else(|p| p.into_inner());
        w.0 += elapsed;
        w.1 += 1;
        if w.0 < period() {
            return;
        }
        std::mem::replace(&mut *w, (0.0, 0))
    };
    // What this window did, not what the process has done: a cumulative table hides a verb whose
    // whole cost arrived in one burst three minutes ago.
    log_window(&window_delta(), window, frames);
}

/// Every verb's cost **since the last window**, costliest first, and bank the new baseline.
fn window_delta() -> Vec<VerbRow> {
    let now: Counts = ROWS
        .lock()
        .unwrap_or_else(|p| p.into_inner())
        .as_ref()
        .cloned()
        .unwrap_or_default();
    let mut prev = PREV.lock().unwrap_or_else(|p| p.into_inner());
    let rows = diff(&now, prev.as_ref());
    *prev = Some(now);
    rows
}

/// `(calls, nanos)` per verb name, the shape [`ROWS`] and [`PREV`] both hold.
type Counts = HashMap<String, (u64, u128)>;

/// `now - was` per verb, costliest first; a verb with no calls this window is left out.
///
/// Split out from [`window_delta`] because that one reads two process-wide statics and this is the
/// whole of the arithmetic.
fn diff(now: &Counts, was: Option<&Counts>) -> Vec<VerbRow> {
    let mut out: Vec<VerbRow> = now
        .iter()
        .filter_map(|(name, &(calls, nanos))| {
            let (p_calls, p_nanos) = was.and_then(|w| w.get(name)).copied().unwrap_or_default();
            // Saturating for its own sake: the totals only ever grow, so the subtraction cannot
            // underflow, and an `unwrap`-free arithmetic is one fewer thing to be wrong about.
            let calls = calls.saturating_sub(p_calls);
            (calls > 0).then(|| VerbRow {
                name: name.clone(),
                calls,
                micros: nanos.saturating_sub(p_nanos) as f64 / 1000.0,
            })
        })
        .collect();
    out.sort_by(|a, b| b.micros.total_cmp(&a.micros).then(a.name.cmp(&b.name)));
    out
}

/// The `[ui-verbs]` window block, per frame as the client's other cost reports are.
fn log_window(rows: &[VerbRow], window: f32, frames: u32) {
    let f = f64::from(frames.max(1));
    let total: f64 = rows.iter().map(|r| r.micros).sum();
    let calls: f64 = rows.iter().map(|r| r.calls as f64).sum();
    eprintln!(
        "[ui-verbs] {window:.2}s · {frames} frames · {} verbs · self {:.0} us/f over {calls_pf:.0} calls/f",
        rows.len(),
        total / f,
        calls_pf = calls / f,
    );
    eprintln!("[ui-verbs]   us/f  calls/f  us/call  verb");
    for r in rows.iter().take(REPORT_ROWS) {
        eprintln!(
            "[ui-verbs] {:6.1} {:8.1} {:8.2}  {}",
            r.micros / f,
            r.calls as f64 / f,
            r.micros / r.calls.max(1) as f64,
            r.name
        );
    }
    if let Some(rest) = rows.len().checked_sub(REPORT_ROWS).filter(|n| *n > 0) {
        let tail: f64 = rows.iter().skip(REPORT_ROWS).map(|r| r.micros).sum();
        eprintln!(
            "[ui-verbs] {:6.1}                    … {rest} more",
            tail / f
        );
    }
}

fn record(name: &str, nanos: u128) {
    let mut rows = ROWS.lock().unwrap_or_else(|p| p.into_inner());
    let rows = rows.get_or_insert_with(HashMap::new);
    let slot = rows.entry(name.to_string()).or_insert((0, 0));
    slot.0 += 1;
    slot.1 += nanos;
}

/// One verb's cost over the process's life.
pub struct VerbRow {
    pub name: String,
    pub calls: u64,
    pub micros: f64,
}

/// Every verb called so far, costliest first.
pub fn report() -> Vec<VerbRow> {
    let rows = ROWS.lock().unwrap_or_else(|p| p.into_inner());
    let mut out: Vec<VerbRow> = rows
        .as_ref()
        .map(|m| {
            m.iter()
                .map(|(name, (calls, nanos))| VerbRow {
                    name: name.clone(),
                    calls: *calls,
                    micros: *nanos as f64 / 1000.0,
                })
                .collect()
        })
        .unwrap_or_default();
    out.sort_by(|a, b| b.micros.total_cmp(&a.micros).then(a.name.cmp(&b.name)));
    out
}

/// Print the table, as the other profilers print theirs: the header, then `rows` lines.
pub fn log_report(label: &str, rows: usize) {
    if !armed() {
        return;
    }
    let all = report();
    let total: f64 = all.iter().map(|r| r.micros).sum();
    let calls: u64 = all.iter().map(|r| r.calls).sum();
    eprintln!(
        "[ui-verbs] {label}: {} verbs, {calls} calls, {:.0} ms in all",
        all.len(),
        total / 1000.0
    );
    eprintln!("[ui-verbs]     ms    calls    us/call  verb");
    for r in all.iter().take(rows) {
        eprintln!(
            "[ui-verbs] {:6.0} {:8} {:10.1}  {}",
            r.micros / 1000.0,
            r.calls,
            r.micros / r.calls.max(1) as f64,
            r.name
        );
    }
    if let Some(rest) = all.len().checked_sub(rows).filter(|n| *n > 0) {
        let tail: f64 = all.iter().skip(rows).map(|r| r.micros).sum();
        eprintln!(
            "[ui-verbs] {:6.0}                     … {rest} more",
            tail / 1000.0
        );
    }
}

/// Forget everything measured, so a harness can bound a phase.
pub fn reset() {
    *ROWS.lock().unwrap_or_else(|p| p.into_inner()) = None;
}

/// Functions [`wrap_table`] must leave alone: each reads the **call stack by level**, and a
/// wrapper puts its own frame between the caller and the callee, so the level means something
/// else.
///
/// `setfenv` is the one that bit, in grom's 2026-10-19 session. pfUI's `api/api.lua:4` is
/// `setfenv(1, pfUI:GetEnvironment())`; level 1 from inside a wrapper is the wrapper, which is a C
/// function, so Lua raises ``setfenv' cannot change environment of given object`. That one armed
/// run logged **91** of those and took pfUI, AI_VoiceOver, WhatsTraining_Turtle, MasterTradeSkills
/// and others down with it — the instrument unloaded a third of the interface it was there to
/// measure, and the session's numbers were of a client without them.
///
/// `error(msg, level)` positions the message by level, and `debugstack([start])` is the reference's
/// traceback by level — `FuBarPlugin-2.0.lua:752` asks for `debugstack(6, 1, 0)` and
/// `AceDB-2.0.lua:742` reads a specific line of it. `pcall`/`xpcall` stay wrapped: they take no
/// level, and one armed session shows them working and worth seeing (pfUI's feature probes).
const STACK_RELATIVE: &[&str] = &["setfenv", "getfenv", "error", "debugstack"];

/// Wrap one table's function values in place, naming each `<prefix><key>`.
fn wrap_table(lua: &Lua, table: &Table, prefix: &str) -> mlua::Result<usize> {
    let mut wrapped = 0;
    let keys: Vec<String> = table
        .clone()
        .pairs::<Value, Value>()
        .filter_map(|p| p.ok())
        .filter_map(|(k, v)| match (k, v) {
            (Value::String(k), Value::Function(_)) => k.to_str().ok().map(|s| s.to_string()),
            _ => None,
        })
        .collect();
    for key in keys {
        if STACK_RELATIVE.contains(&key.as_str()) {
            continue;
        }
        let Ok(Value::Function(orig)) = table.raw_get::<Value>(key.as_str()) else {
            continue;
        };
        let name = format!("{prefix}{key}");
        let timed = lua.create_function(move |_, args: MultiValue| {
            let started = Instant::now();
            let out = orig.call::<MultiValue>(args);
            record(&name, started.elapsed().as_nanos());
            out
        })?;
        table.raw_set(key, timed)?;
        wrapped += 1;
    }
    Ok(wrapped)
}

/// Arm the profiler on a freshly built VM: every global and every widget method, timed. Called at
/// the end of [`UiScript::new`](super::UiScript::new), where `_G` holds our bindings and nothing
/// else — a later call would wrap FrameXML's own functions too and call them verbs.
pub(super) fn install(lua: &Lua) -> mlua::Result<()> {
    if !armed() {
        return Ok(());
    }
    let mut n = wrap_table(lua, &lua.globals(), "")?;
    for reg in super::surface::METHOD_TABLES {
        if let Ok(table) = lua.named_registry_value::<Table>(reg) {
            // `__benilla_frame_methods` → `frame:`, so a row reads as the addon wrote the call.
            let short = reg
                .strip_prefix("__benilla_")
                .and_then(|r| r.strip_suffix("_methods"))
                .unwrap_or(reg);
            n += wrap_table(lua, &table, &format!("{short}:"))?;
        }
    }
    eprintln!("[ui-verbs] armed — {n} verbs timed (WOW_UI_VERBS)");
    Ok(())
}

#[cfg(test)]
mod tests {
    use super::{diff, Counts};

    fn counts(rows: &[(&str, u64, u128)]) -> Counts {
        rows.iter()
            .map(|&(n, c, ns)| (n.to_string(), (c, ns)))
            .collect()
    }

    #[test]
    fn a_window_reports_its_own_calls_and_not_the_process_total() {
        let first = counts(&[("CreateFrame", 10, 10_000), ("frame:Show", 4, 2_000)]);
        let rows = diff(&first, None);
        assert_eq!(rows.len(), 2, "no baseline: everything is this window's");
        assert_eq!(rows[0].name, "CreateFrame", "costliest first");
        assert_eq!((rows[0].calls, rows[0].micros), (10, 10.0));

        // CreateFrame was not called again; frame:Show was, three times for 1 us.
        let second = counts(&[("CreateFrame", 10, 10_000), ("frame:Show", 7, 3_000)]);
        let rows = diff(&second, Some(&first));
        assert_eq!(
            rows.len(),
            1,
            "a verb with no calls this window is left out"
        );
        assert_eq!((rows[0].name.as_str(), rows[0].calls), ("frame:Show", 3));
        assert!(
            (rows[0].micros - 1.0).abs() < 1e-9,
            "1000 ns of new cost, not the 3000 it has ever cost: {}",
            rows[0].micros
        );
    }

    /// The 2026-10-19 regression, as a falsifier. Wrapping `_G` wholesale took `setfenv` with it,
    /// and `setfenv(1, env)` from a chunk then raised ``setfenv' cannot change environment of
    /// given object` — level 1 was the wrapper, a C function. pfUI's `api/api.lua:4` is exactly
    /// this line, which is why one armed session cost 91 load errors.
    #[test]
    fn wrapping_the_globals_spares_the_stack_relative_ones() {
        let lua = mlua::Lua::new();
        super::wrap_table(&lua, &lua.globals(), "").expect("wrap _G");
        // The globals are bound to locals first: after `setfenv` the chunk's own lookups go
        // through the new environment, where they are not.
        let answered: bool = lua
            .load(
                r#"
                    local setfenv, getfenv = setfenv, getfenv
                    local env = { ok = true }
                    setfenv(1, env)
                    return ok and getfenv(1) == env
                "#,
            )
            .eval()
            .expect("setfenv(1, …) must still reach the calling chunk");
        assert!(answered, "the chunk got someone else's environment");
    }
}