benilla-octo/crates/benilla-app/src/ui_script/flash_trace.rs

//! `WOW_FLASH_CHURN=1`: name what is flashing.
//!
//! A window that "stutters" or "flashes" is being shown and hidden faster than the eye resolves,
//! and nothing in the log says which one — a `Show()`/`Hide()` pair is an ordinary thing to do, so
//! neither is worth a line on its own. What is *not* ordinary is doing it many times a second, and
//! that is a shape only a per-frame sweep can see.
//!
//! This walks every named frame **and region** each frame, counts the visibility edges, and once a
//! second prints the ones that toggled more than [`LOUD`] times. The name is the answer: a run
//! that prints `QuestFrame 47` says the quest window is being driven, not that the renderer is
//! slow.
//!
//! Regions matter as much as frames and were missed at first: a texture shown and hidden every
//! frame flashes exactly as visibly as a window, and Tmog's "Loading" overlay is one. Reading
//! frames alone reported "nothing is toggling" through a session that was visibly flashing, which
//! is the worst answer an instrument can give.
//!
//! Off unless the variable is set; with it set the sweep is one pass over the frame arena and a
//! hash lookup per named widget, keyed on handles ([`VisKey`]). **It is still O(named widgets)
//! per frame** — 2.7 ms on this interface — so it is for a session spent hunting a flashing
//! window, not for one measuring anything else.
//!
//! **The keys are handles, not names, and that is not a detail.** The first cut kept a
//! `HashMap<String, bool>` and cloned a name per named widget per frame. On this interface —
//! 17 064 frames and 40 012 regions — that is ~57 000 allocations and ~114 000 string hashes
//! every frame, which measured **6 ms a frame, 420 ms of every second**, enough to rank second
//! among all systems in a `WOW_SYSTEM_TIMING` report. An instrument armed in every diagnostic run
//! was therefore producing a large share of the stutter it was pointed at, and corrupting every
//! measurement taken beside it. Handles are `Copy` and hash without allocating; names are
//! resolved by [`UiScript::vis_key_name`] for the dozen rows that actually print.

use std::collections::HashMap;

use bevy::prelude::*;

use benilla_ui::script::{UiScript, VisKey};

/// Edges in a one-second window past which a frame is worth naming. A window opening and closing
/// legitimately does so once or twice; ten is a frame being driven by something.
const LOUD: u32 = 10;

/// Per-frame visibility and the edge tally since the last report.
#[derive(Default)]
pub(crate) struct FlashTrace {
    last: HashMap<VisKey, bool>,
    edges: HashMap<VisKey, u32>,
    scratch: Vec<(VisKey, bool)>,
    window_start: Option<f64>,
    armed: Option<bool>,
}

impl FlashTrace {
    /// Whether the tracer is on, read once.
    fn on(&mut self) -> bool {
        *self.armed.get_or_insert_with(|| {
            // Its own switch, not `WOW_FLASH_TRACE`. That variable also arms the frame-cost line
            // ([`crate::perf`]), which is the meter every session wants and costs nothing — while
            // this sweep is O(named widgets) and measured **2.7 ms a frame, 447 ms of every
            // second** on a 17 000-frame interface even after its allocations were removed. Two
            // instruments on one switch meant every run paid for the expensive one to read the
            // cheap one, and several of this project's measurements were taken that way.
            let on = std::env::var_os("WOW_FLASH_CHURN").is_some();
            // Say so once. Silence from a tracer is only evidence if you know it ran: two
            // sessions were read as "nothing is toggling" when the honest reading was "no idea".
            if on {
                info!(
                    "flash: churn tracer armed (WOW_FLASH_CHURN) — frames and regions toggling \
                     >{LOUD}x a second will be named; costs ~2.7 ms a frame on a loaded interface"
                );
            }
            on
        })
    }
}

/// Count every named frame's visibility edges; report the loud ones once a second.
pub(crate) fn trace_visibility_churn(
    script: Option<NonSendMut<UiScript>>,
    time: Res<Time>,
    mut memo: Local<crate::ui_script::VmMemo<FlashTrace>>,
) {
    let Some(script) = script else {
        return;
    };
    // Keyed on the session: a `/reload` builds a fresh VM with fresh frames, and last VM's
    // visibility map would read as a storm of edges on the first frame of the new one.
    let trace = memo.get(&script);
    if !trace.on() {
        return;
    }
    let mut scratch = std::mem::take(&mut trace.scratch);
    script.named_visibility(&mut scratch);
    for &(key, visible) in &scratch {
        // One lookup, not a lookup and an insert: the common case is a widget already in the map
        // whose state has not moved, and that case now touches no allocator at all.
        match trace.last.get_mut(&key) {
            Some(was) => {
                if *was != visible {
                    *trace.edges.entry(key).or_default() += 1;
                    *was = visible;
                }
            }
            None => {
                trace.last.insert(key, visible);
            }
        }
    }
    trace.scratch = scratch;

    let now = f64::from(time.elapsed_secs());
    let start = *trace.window_start.get_or_insert(now);
    if now - start < 1.0 {
        return;
    }
    trace.window_start = Some(now);
    let mut loud: Vec<(VisKey, u32)> = trace.edges.drain().filter(|&(_, n)| n >= LOUD).collect();
    if loud.is_empty() {
        return;
    }
    // Worst first: the driver is usually the top one, and its children follow it.
    // Worst first. The tie-break is the resolved name, so the line is stable run to run; it
    // resolves only after the truncation, which is the whole point of carrying handles.
    loud.sort_by_key(|row| std::cmp::Reverse(row.1));
    loud.truncate(12);
    let mut named: Vec<(String, u32)> = loud
        .into_iter()
        .map(|(key, count)| {
            let name = script
                .vis_key_name(key)
                .unwrap_or_else(|| format!("{key:?}"));
            (name, count)
        })
        .collect();
    named.sort_by(|a, b| b.1.cmp(&a.1).then_with(|| a.0.cmp(&b.0)));
    let list = named
        .iter()
        .map(|(n, c)| format!("{n} {c}"))
        .collect::<Vec<_>>()
        .join(", ");
    warn!("flash: frames toggling >{LOUD}x in the last second — {list}");
}