vj-codegen 0.1.0

//! Compile-phase wall timers (`SV_SIM_TIMING=1`), a profiling aid.
//!
//! With the variable set, each compile phase prints one `[timing] ...` line to
//! stderr (phase wall time, plus counts where the phase has them); with it
//! unset, every call is a single cached-bool check, so designs not profiling
//! pay nothing. The state is a process-wide read-only flag, not per-run state.

use inkwell::module::Module;
use inkwell::values::FunctionValue;
use std::sync::{Mutex, OnceLock};
use std::time::Instant;

/// `(function name, lowering seconds, instructions)` per body lowered.
static LOWERED: Mutex<Vec<(String, f64, usize)>> = Mutex::new(Vec::new());

/// Instruction count of `f`'s body.
fn instr_count(f: FunctionValue<'_>) -> usize {
    f.get_basic_blocks()
        .iter()
        .map(|b| b.get_instructions().count())
        .sum()
}

/// Records the lowering (IR generation) time of one function body.
pub fn record(t: Option<Instant>, name: &str, f: FunctionValue<'_>) {
    if let Some(t) = t {
        let secs = t.elapsed().as_secs_f64();
        if let Ok(mut v) = LOWERED.lock() {
            v.push((name.to_string(), secs, instr_count(f)));
        }
    }
}

/// Prints function/instruction totals of the finished module, the top
/// functions by IR size, and the top recorded bodies by lowering time.
pub fn report_module(module: &Module<'_>) {
    if !enabled() {
        return;
    }
    let mut sizes: Vec<(String, usize, usize)> = module
        .get_functions()
        .filter(|f| f.count_basic_blocks() > 0)
        .map(|f| {
            (
                f.get_name().to_string_lossy().into_owned(),
                instr_count(f),
                f.count_basic_blocks() as usize,
            )
        })
        .collect();
    let total: usize = sizes.iter().map(|s| s.1).sum();
    eprintln!(
        "[timing] module: {} defined functions, {} IR instructions",
        sizes.len(),
        total
    );
    sizes.sort_by_key(|s| std::cmp::Reverse(s.1));
    for (n, i, b) in sizes.iter().take(25) {
        eprintln!("[timing]   ir-size {i:>9} instrs {b:>8} blocks  {n}");
    }
    // Functions grouped by their last two `__` name components (a fork
    // child is named for its whole fork path, so a leaf cloned once per
    // path shows up as one big group) and by fork depth.
    let mut by_leaf: std::collections::HashMap<String, (usize, usize)> =
        std::collections::HashMap::new();
    let mut by_depth: std::collections::BTreeMap<usize, (usize, usize)> =
        std::collections::BTreeMap::new();
    for (n, i, _) in &sizes {
        let parts: Vec<&str> = n.split("__").collect();
        let leaf = parts[parts.len().saturating_sub(2)..].join("__");
        let e = by_leaf.entry(leaf).or_default();
        e.0 += 1;
        e.1 += i;
        let d = by_depth
            .entry(parts.iter().filter(|p| p.starts_with("fork")).count())
            .or_default();
        d.0 += 1;
        d.1 += i;
    }
    for (d, (c, i)) in &by_depth {
        eprintln!("[timing]   fork-depth {d:>2}: {c:>7} fns {i:>10} instrs");
    }
    let mut leaves: Vec<_> = by_leaf.into_iter().collect();
    leaves.sort_by_key(|l| std::cmp::Reverse(l.1.1));
    for (n, (c, i)) in leaves.iter().take(15) {
        eprintln!("[timing]   leaf-group {c:>6} fns {i:>10} instrs  {n}");
    }
    if let Ok(mut v) = LOWERED.lock() {
        let sum: f64 = v.iter().map(|x| x.1).sum();
        eprintln!("[timing] lowering: {} recorded bodies, {sum:.1} s", v.len());
        v.sort_by(|a, b| b.1.total_cmp(&a.1));
        for (n, s, i) in v.iter().take(25) {
            eprintln!("[timing]   lower {s:>8.2} s {i:>9} instrs  {n}");
        }
        v.clear();
    }
}

/// The environment knob that enables the `[timing]` lines.
pub const TIMING_ENV: &str = "SV_SIM_TIMING";

/// Whether `SV_SIM_TIMING` is set (cached on first use).
pub fn enabled() -> bool {
    static ON: OnceLock<bool> = OnceLock::new();
    *ON.get_or_init(|| std::env::var_os(TIMING_ENV).is_some())
}

/// Seconds since the first call to this function in the process (the first
/// call is made at the start of lowering, so it approximates "since
/// elaboration finished").
fn epoch() -> Instant {
    static T0: OnceLock<Instant> = OnceLock::new();
    *T0.get_or_init(|| {
        let unix = std::time::SystemTime::now()
            .duration_since(std::time::UNIX_EPOCH)
            .map_or(0.0, |d| d.as_secs_f64());
        eprintln!("[timing] epoch (unix) {unix:.2}");
        Instant::now()
    })
}

/// Like [`end`], but silent when the phase took under `min_secs`.
pub fn end_if_over(t: Option<Instant>, min_secs: f64, label: &str, detail: &str) {
    if let Some(start) = t
        && start.elapsed().as_secs_f64() >= min_secs
    {
        end(t, label, detail);
    }
}

/// Starts a phase timer; `None` (free) when timing is off.
pub fn start() -> Option<Instant> {
    if enabled() {
        epoch();
        Some(Instant::now())
    } else {
        None
    }
}

/// Prints `[timing] <label>: <wall> s (t=<since epoch> s) <detail>`.
pub fn end(t: Option<Instant>, label: &str, detail: &str) {
    if let Some(t) = t {
        eprintln!(
            "[timing] {label}: {:.2} s (t={:.1}) {detail} [rss {} MB, peak {} MB]",
            t.elapsed().as_secs_f64(),
            epoch().elapsed().as_secs_f64(),
            proc_status_mb("VmRSS:"),
            proc_status_mb("VmHWM:"),
        );
    }
}

/// A `/proc/self/status` size field in MB (0 when unreadable), so a phase's
/// timing line also shows where the process's memory sits.
fn proc_status_mb(key: &str) -> u64 {
    std::fs::read_to_string("/proc/self/status")
        .ok()
        .and_then(|t| {
            t.lines()
                .find_map(|l| l.strip_prefix(key))
                .and_then(|r| r.split_whitespace().next())
                .and_then(|n| n.parse::<u64>().ok())
        })
        .map_or(0, |kb| kb / 1024)
}