xenia-rs/crates/xenia-gpu/src/prof.rs

//! Lightweight env-gated wall-time profiler (probe-patch, UNCOMMITTED).
//!
//! Attributes emulator wall time to coarse buckets so we can tell whether the
//! movie-playback slowdown is CPU-interpreter bound, texture-decode bound, or
//! GPU-present bound. Enabled only when `XENIA_PROFILE` is set; the hot-path
//! cost when disabled is a single relaxed atomic add of already-measured nanos
//! (callers still pay `Instant::now()` — acceptable at the coarse boundaries we
//! instrument: per basic-block, per texture upload, per present).
//!
//! Read the buckets with `xenia_gpu::prof::report(wall_ns)` at clean shutdown.

use std::sync::atomic::{AtomicU64, Ordering};
use std::sync::OnceLock;

static START: OnceLock<std::time::Instant> = OnceLock::new();

/// Lazily anchor the wall-time window (first call wins). Called from `add`.
#[inline]
fn mark_start() {
    START.get_or_init(std::time::Instant::now);
}

/// Nanos since the profiler's first accounted event.
pub fn wall_ns() -> u64 {
    START.get().map(|t| t.elapsed().as_nanos() as u64).unwrap_or(0)
}

pub static STEP_NS: AtomicU64 = AtomicU64::new(0); // guest interpreter (step_block)
pub static STEP_INSTR: AtomicU64 = AtomicU64::new(0); // guest instructions retired
pub static STEP_CALLS: AtomicU64 = AtomicU64::new(0);

pub static TEXDEC_NS: AtomicU64 = AtomicU64::new(0); // texture decode + host upload
pub static TEXDEC_CALLS: AtomicU64 = AtomicU64::new(0);
pub static TEXDEC_BYTES: AtomicU64 = AtomicU64::new(0);

pub static PRESENT_NS: AtomicU64 = AtomicU64::new(0); // frontbuffer present
pub static PRESENT_CALLS: AtomicU64 = AtomicU64::new(0);

pub static DRAW_NS: AtomicU64 = AtomicU64::new(0); // host draw submission
pub static DRAW_CALLS: AtomicU64 = AtomicU64::new(0);

pub static KERNEL_NS: AtomicU64 = AtomicU64::new(0); // kernel HLE export dispatch
pub static KERNEL_CALLS: AtomicU64 = AtomicU64::new(0);

pub static BUILD_NS: AtomicU64 = AtomicU64::new(0); // block decode / cache lookup
pub static BUILD_CALLS: AtomicU64 = AtomicU64::new(0);

// Top-level lockstep-loop attribution (sums to ~100% with idle/GPU-pacer):
pub static ROUND_NS: AtomicU64 = AtomicU64::new(0); // per-round tax (clock/timestamp/isr/schedule)
pub static ROUND_CALLS: AtomicU64 = AtomicU64::new(0);
pub static PROLOGUE_NS: AtomicU64 = AtomicU64::new(0); // worker_prologue (⊇ KERNEL)
pub static PROLOGUE_CALLS: AtomicU64 = AtomicU64::new(0);
pub static RUNSB_NS: AtomicU64 = AtomicU64::new(0); // run_superblock (⊇ STEP + chain BUILD + EPILOGUE)
pub static RUNSB_CALLS: AtomicU64 = AtomicU64::new(0);
pub static EPILOGUE_NS: AtomicU64 = AtomicU64::new(0); // worker_epilogue (subset of RUNSB)
pub static EPILOGUE_CALLS: AtomicU64 = AtomicU64::new(0);

/// Cached on/off state so the per-block hot path never touches the
/// environment. 0 = uninitialised, 1 = on, 2 = off.
static ENABLED: std::sync::atomic::AtomicU8 = std::sync::atomic::AtomicU8::new(0);

/// Cheap (one relaxed load + branch) enabled check for hot paths. Resolves
/// `XENIA_PROFILE` from the environment exactly once, then caches it.
#[inline]
pub fn is_on() -> bool {
    match ENABLED.load(Ordering::Relaxed) {
        1 => true,
        2 => false,
        _ => {
            let on = std::env::var_os("XENIA_PROFILE").is_some();
            ENABLED.store(if on { 1 } else { 2 }, Ordering::Relaxed);
            on
        }
    }
}

#[inline]
pub fn enabled() -> bool {
    is_on()
}

#[inline]
pub fn add(counter: &AtomicU64, v: u64) {
    mark_start();
    counter.fetch_add(v, Ordering::Relaxed);
}

/// RAII timer: adds elapsed nanos to `ns` and bumps `calls` on drop.
pub struct ScopeTimer {
    t0: std::time::Instant,
    ns: &'static AtomicU64,
    calls: &'static AtomicU64,
}

impl ScopeTimer {
    #[inline]
    pub fn new(ns: &'static AtomicU64, calls: &'static AtomicU64) -> Self {
        mark_start();
        Self { t0: std::time::Instant::now(), ns, calls }
    }
}

impl Drop for ScopeTimer {
    #[inline]
    fn drop(&mut self) {
        self.ns.fetch_add(self.t0.elapsed().as_nanos() as u64, Ordering::Relaxed);
        self.calls.fetch_add(1, Ordering::Relaxed);
    }
}

static NEXT_REPORT_INSTR: AtomicU64 = AtomicU64::new(500_000_000);

/// Fire a snapshot every ~500M retired guest instructions (headless runs have
/// no present() to piggyback on and may never reach the clean-exit report).
#[inline]
pub fn maybe_report_by_instr() {
    if !enabled() {
        return;
    }
    let instr = STEP_INSTR.load(Ordering::Relaxed);
    let thresh = NEXT_REPORT_INSTR.load(Ordering::Relaxed);
    if instr >= thresh
        && NEXT_REPORT_INSTR
            .compare_exchange(thresh, thresh + 500_000_000, Ordering::Relaxed, Ordering::Relaxed)
            .is_ok()
    {
        report(0);
    }
}

/// Print the accumulated buckets against the profiler's own wall window.
/// The argument is accepted for call-site convenience but ignored in favour
/// of the internally-anchored window (`wall_ns()`).
pub fn report(_ignored: u64) {
    let wall_ns = wall_ns();
    let g = |c: &AtomicU64| c.load(Ordering::Relaxed);
    let ms = |ns: u64| ns as f64 / 1e6;
    let pct = |ns: u64| {
        if wall_ns == 0 {
            0.0
        } else {
            100.0 * ns as f64 / wall_ns as f64
        }
    };
    let step_ns = g(&STEP_NS);
    let step_instr = g(&STEP_INSTR);
    let tex_ns = g(&TEXDEC_NS);
    let pres_ns = g(&PRESENT_NS);
    let draw_ns = g(&DRAW_NS);
    let mips = if step_ns == 0 {
        0.0
    } else {
        step_instr as f64 / (step_ns as f64 / 1e3) // instr / us = MIPS
    };
    let kern_ns = g(&KERNEL_NS);
    let build_ns = g(&BUILD_NS);
    let round_ns = g(&ROUND_NS);
    let prologue_ns = g(&PROLOGUE_NS);
    let runsb_ns = g(&RUNSB_NS);
    let epilogue_ns = g(&EPILOGUE_NS);
    // Derived leftovers (honest lumping — see comments):
    //   runsb_other = chain-loop body (arithmetic/stop-checks) + in-chain block lookups
    //   prologue_other = block lookup (first block) + scheduler bookkeeping
    let runsb_other = runsb_ns.saturating_sub(step_ns).saturating_sub(epilogue_ns);
    let prologue_other = prologue_ns.saturating_sub(kern_ns);
    let line = |label: &str, ns: u64, extra: &str| {
        eprintln!("  {:<20}{:>10.1} ms  {:>5.1}%  {}", label, ms(ns), pct(ns), extra);
    };
    eprintln!("=== XENIA_PROFILE (wall {:.1} ms) ===", ms(wall_ns));
    eprintln!("  -- TOP LEVEL (single-thread lockstep loop; sums ~100%) --");
    line("per-round tax", round_ns, &format!("({} rounds)", g(&ROUND_CALLS)));
    line("worker_prologue", prologue_ns, &format!("({} visits)", g(&PROLOGUE_CALLS)));
    line("run_superblock", runsb_ns, &format!("({} visits)", g(&RUNSB_CALLS)));
    let top = round_ns + prologue_ns + runsb_ns;
    eprintln!(
        "  ---- top accounted {:.1}% ; idle/GPU-pacer/misc {:.1}%",
        pct(top),
        pct(wall_ns.saturating_sub(top))
    );
    eprintln!("  -- SUB-ATTRIBUTION --");
    line(
        "interp step_block",
        step_ns,
        &format!("[in run_superblock] ({} calls, {} instr, {:.1} MIPS)", g(&STEP_CALLS), step_instr, mips),
    );
    line("worker_epilogue", epilogue_ns, "[in run_superblock]");
    line("run_superblock other", runsb_other, "[chain-loop body + in-chain lookups]");
    line("kernel HLE export", kern_ns, &format!("[in worker_prologue] ({} calls)", g(&KERNEL_CALLS)));
    line("worker_prologue other", prologue_other, "[first-block lookup + sched bookkeeping]");
    line("block decode/cache", build_ns, &format!("[split across prologue+runsb] ({} calls)", g(&BUILD_CALLS)));
    line("texture decode+up", tex_ns, &format!("({} calls, {} MiB)", g(&TEXDEC_CALLS), g(&TEXDEC_BYTES) / (1024 * 1024)));
    line("host draw submit", draw_ns, &format!("({} calls)", g(&DRAW_CALLS)));
    line("frontbuffer present", pres_ns, &format!("({} calls)", g(&PRESENT_CALLS)));
}