sui_eval/

trace.rs

//! Infinite recursion debugging tools for the tree-walker evaluator.
//!
//! Five integrated tools:
//!
//! 1. **Force chain capture** — always-on, captures the chain of thunk
//!    forces leading to a blackhole cycle.
//! 2. **Trace mode** (`SUI_TRACE_EVAL=1` or `=verbose`) — logs every
//!    thunk force to stderr or a ring buffer.
//! 3. **Max force depth** (`--max-force-depth N`) — caps the force
//!    stack and reports early.
//! 4. **Thunk stats** — extends `perf.rs` counters with thunk-specific
//!    metrics (created, forced unique, max depth).
//! 5. **Static cycle detection** — lives in the compiler; see
//!    `sui-bytecode/src/compiler.rs`.

use std::cell::{Cell, RefCell};
use std::collections::VecDeque;
use std::path::{Path, PathBuf};
use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering};

// ── Tool 1: Force Chain Capture ──────────────────────────────────

/// A single entry on the force stack.
#[derive(Debug, Clone)]
pub struct ForceFrame {
    /// File where the thunk was defined (if known).
    pub defined_in: Option<PathBuf>,
    /// Human-readable description (truncated source text).
    pub description: String,
    /// Unique identity of the thunk (pointer address).
    pub thunk_id: usize,
}

/// The chain of forces that led to a cycle.
#[derive(Debug, Clone)]
pub struct ForceChain(pub Vec<ForceFrame>);

thread_local! {
    static FORCE_STACK: RefCell<Vec<ForceFrame>> = RefCell::new(Vec::new());
}

/// Push a frame onto the force stack. Called when a thunk begins forcing.
pub fn push_force(frame: ForceFrame) {
    FORCE_STACK.with(|s| {
        s.borrow_mut().push(frame);
        // Update thunk stats: track max depth.
        let depth = s.borrow().len();
        THUNK_MAX_FORCE_DEPTH.with(|m| {
            if depth > m.get() as usize {
                m.set(depth as u32);
            }
        });
        THUNK_CURRENT_FORCE_DEPTH.with(|c| c.set(depth as u32));
    });
}

/// Pop a frame from the force stack. Called when a thunk finishes forcing.
pub fn pop_force() {
    FORCE_STACK.with(|s| {
        s.borrow_mut().pop();
        let depth = s.borrow().len();
        THUNK_CURRENT_FORCE_DEPTH.with(|c| c.set(depth as u32));
    });
}

/// Diagnostic: is `thunk_id` present anywhere on the current force
/// stack?  A `true` means the SAME thunk pointer is being re-entered
/// (a genuine self-cycle); a `false` means the blackholed thunk is NOT
/// on the stack (a re-created / distinct thunk — a sharing gap).
pub fn force_stack_contains(thunk_id: usize) -> bool {
    FORCE_STACK.with(|s| s.borrow().iter().any(|f| f.thunk_id == thunk_id))
}

/// Diagnostic: dump the whole force stack's thunk ids + files + descriptions.
pub fn dump_force_stack_ids() {
    FORCE_STACK.with(|s| {
        let stack = s.borrow();
        eprintln!("[SUI_DEBUG_CYCLE] force stack depth={}", stack.len());
        for (i, f) in stack.iter().enumerate() {
            let loc = f
                .defined_in
                .as_ref()
                .map(|p| p.display().to_string())
                .unwrap_or_else(|| "<eval>".into());
            let d: String = f.description.chars().take(50).collect();
            let d = d.replace('\n', " ");
            eprintln!("[SUI_DEBUG_CYCLE]   [{i}] id={:#x} {loc}  ::  {d}", f.thunk_id);
        }
    });
}

/// Capture the cycle portion of the force stack starting from the
/// frame whose `thunk_id` matches the blackholed thunk.
pub fn capture_cycle(thunk_id: usize) -> ForceChain {
    FORCE_STACK.with(|s| {
        let stack = s.borrow();
        let start = stack.iter().position(|f| f.thunk_id == thunk_id);
        match start {
            Some(idx) => ForceChain(stack[idx..].to_vec()),
            None => ForceChain(stack.clone()),
        }
    })
}

impl std::fmt::Display for ForceChain {
    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
        writeln!(f, "infinite recursion detected")?;
        writeln!(f, "force chain ({} frames):", self.0.len())?;
        // Dedup adjacent identical descriptions to keep the chain
        // readable when the same expression text repeats (mutual
        // recursion through a single call site).  Empty descriptions
        // bypass dedup — they're the "cheap" non-tracing form where
        // every frame is a distinct thunk so collapsing them would
        // misrepresent the cycle.  Set `SUI_TRACE_EVAL=verbose` for
        // the rich per-frame descriptions.
        let mut prev_desc: Option<&str> = None;
        let mut repeat = 0u32;
        for (i, frame) in self.0.iter().enumerate() {
            let has_desc = !frame.description.is_empty();
            if has_desc && prev_desc == Some(&frame.description) {
                repeat += 1;
                continue;
            }
            if repeat > 0 {
                writeln!(f, "    ... repeated {repeat} more times")?;
                repeat = 0;
            }
            let loc = frame
                .defined_in
                .as_ref()
                .map(|p| p.display().to_string())
                .unwrap_or_else(|| "<eval>".into());
            let arrow = if i == 0 { "\u{2192}" } else { "\u{2192}" };
            let desc = if has_desc {
                frame.description.as_str()
            } else {
                "<thunk>"
            };
            writeln!(f, "  {arrow} {desc} ({loc})")?;
            prev_desc = if has_desc { Some(&frame.description) } else { None };
        }
        if repeat > 0 {
            writeln!(f, "    ... repeated {repeat} more times")?;
        }
        if self.0.iter().any(|fr| fr.description.is_empty()) {
            writeln!(
                f,
                "  hint: set SUI_TRACE_EVAL=verbose for per-frame source text"
            )?;
        }
        Ok(())
    }
}

// ── Tool 2: Trace Mode ──────────────────────────────────────────

static TRACE_ENABLED: AtomicBool = AtomicBool::new(false);

/// Whether trace mode is set to "verbose" (prints each force immediately)
/// vs. ring-buffer mode (only dumps on error).
static TRACE_VERBOSE: AtomicBool = AtomicBool::new(false);

/// Initialize tracing from the `SUI_TRACE_EVAL` environment variable.
///
/// - Empty / unset: tracing disabled
/// - `"1"` or `"verbose"`: verbose mode (each force printed to stderr)
/// - Any other non-empty value: ring-buffer mode (dumped on error)
pub fn init_trace() {
    let mode = std::env::var("SUI_TRACE_EVAL").unwrap_or_default();
    if mode.is_empty() {
        TRACE_ENABLED.store(false, Ordering::Relaxed);
        TRACE_VERBOSE.store(false, Ordering::Relaxed);
    } else {
        TRACE_ENABLED.store(true, Ordering::Relaxed);
        TRACE_VERBOSE.store(mode == "1" || mode == "verbose", Ordering::Relaxed);
    }
}

/// Whether any trace mode is active.
#[inline(always)]
pub fn trace_enabled() -> bool {
    TRACE_ENABLED.load(Ordering::Relaxed)
}

thread_local! {
    static TRACE_DEPTH: Cell<u32> = const { Cell::new(0) };
    /// Ring buffer for non-verbose mode — only dump on error.
    static RING_BUFFER: RefCell<VecDeque<String>> =
        RefCell::new(VecDeque::with_capacity(256));
}

/// Log a force-enter event. In verbose mode, prints immediately.
/// In ring-buffer mode, stores for later dump.
pub fn trace_force_enter(file: Option<&Path>, desc: &str) {
    if !trace_enabled() {
        return;
    }
    let depth = TRACE_DEPTH.with(|d| {
        let v = d.get();
        d.set(v + 1);
        v
    });
    let indent = "  ".repeat(depth as usize);
    let loc = file
        .map(|f| f.display().to_string())
        .unwrap_or_default();
    let msg = format!("[trace] {indent}force {loc} ({desc})");
    if TRACE_VERBOSE.load(Ordering::Relaxed) {
        eprintln!("{msg}");
    }
    RING_BUFFER.with(|rb| {
        let mut rb = rb.borrow_mut();
        if rb.len() >= 256 {
            rb.pop_front();
        }
        rb.push_back(msg);
    });
}

/// Log a force-exit event (decrements trace depth).
pub fn trace_force_exit() {
    if !trace_enabled() {
        return;
    }
    TRACE_DEPTH.with(|d| d.set(d.get().saturating_sub(1)));
}

/// Dump the last `n` ring-buffer entries to stderr (for inline diagnostics).
pub fn dump_ring_tail(n: usize) {
    RING_BUFFER.with(|rb| {
        let rb = rb.borrow();
        let start = rb.len().saturating_sub(n);
        for line in rb.iter().skip(start) {
            eprintln!("{line}");
        }
    });
}

/// Dump the trace ring buffer to stderr. Called on error paths.
pub fn dump_trace_on_error() {
    if !trace_enabled() {
        return;
    }
    RING_BUFFER.with(|rb| {
        let rb = rb.borrow();
        if rb.is_empty() {
            return;
        }
        eprintln!("[trace] last {} force operations:", rb.len());
        for line in rb.iter() {
            eprintln!("{line}");
        }
    });
}

// ── Tool 3: Max Force Depth ─────────────────────────────────────

static MAX_FORCE_DEPTH: AtomicUsize = AtomicUsize::new(0);

/// Set the maximum allowed force depth. 0 means no limit.
pub fn set_max_force_depth(limit: usize) {
    MAX_FORCE_DEPTH.store(limit, Ordering::Relaxed);
}

/// Check whether the current force depth exceeds the configured limit.
/// Returns `Ok(())` if within bounds or no limit is set.
pub fn check_force_depth() -> Result<(), String> {
    let limit = MAX_FORCE_DEPTH.load(Ordering::Relaxed);
    if limit == 0 {
        return Ok(());
    }
    let depth = FORCE_STACK.with(|s| s.borrow().len());
    if depth > limit {
        Err(format!("force depth exceeded ({depth}/{limit})"))
    } else {
        Ok(())
    }
}

// ── Tool 5: Thunk Stats (extends perf.rs) ───────────────────────

thread_local! {
    static THUNKS_CREATED: Cell<u64> = const { Cell::new(0) };
    static THUNKS_FORCED_UNIQUE: Cell<u64> = const { Cell::new(0) };
    static THUNK_MAX_FORCE_DEPTH: Cell<u32> = const { Cell::new(0) };
    static THUNK_CURRENT_FORCE_DEPTH: Cell<u32> = const { Cell::new(0) };
    /// Cumulative nanoseconds spent inside the overlay flatten-build closure
    /// (`NixAttrs::as_flat` cache-miss path). Diagnostic only; gated on
    /// `perf::enabled()`.
    static OVERLAY_FLATTEN_NANOS: Cell<u128> = const { Cell::new(0) };
    /// Cumulative nanoseconds spent inside `NixAttrs::sorted_entries`
    /// (resolve + sort for attrNames/keys/iter/values). Diagnostic only.
    static SORTED_ENTRIES_NANOS: Cell<u128> = const { Cell::new(0) };
    /// Cumulative nanoseconds spent inside `referenced_idents` (Storm A —
    /// the self/mutual-recursion detection subtree walk). Diagnostic only;
    /// gated on `perf::enabled()`.
    static SELF_REC_WALK_NANOS: Cell<u128> = const { Cell::new(0) };
}

/// Add `nanos` to the cumulative overlay-flatten-build timer.
#[inline(always)]
pub fn add_overlay_flatten_nanos(nanos: u128) {
    if crate::perf::enabled() {
        OVERLAY_FLATTEN_NANOS.with(|c| c.set(c.get() + nanos));
    }
}

/// Read the cumulative overlay-flatten-build nanoseconds.
pub fn get_overlay_flatten_nanos() -> u128 {
    OVERLAY_FLATTEN_NANOS.with(Cell::get)
}

/// Add `nanos` to the cumulative sorted_entries timer.
#[inline(always)]
pub fn add_sorted_entries_nanos(nanos: u128) {
    if crate::perf::enabled() {
        SORTED_ENTRIES_NANOS.with(|c| c.set(c.get() + nanos));
    }
}

/// Read the cumulative sorted_entries nanoseconds.
pub fn get_sorted_entries_nanos() -> u128 {
    SORTED_ENTRIES_NANOS.with(Cell::get)
}

/// Add `nanos` to the cumulative Storm-A (`referenced_idents`) timer.
#[inline(always)]
pub fn add_self_rec_walk_nanos(nanos: u128) {
    if crate::perf::enabled() {
        SELF_REC_WALK_NANOS.with(|c| c.set(c.get() + nanos));
    }
}

/// Read the cumulative Storm-A (`referenced_idents`) nanoseconds.
pub fn get_self_rec_walk_nanos() -> u128 {
    SELF_REC_WALK_NANOS.with(Cell::get)
}

// ── M2 scratch: maybe_thunk `_`-arm expr-kind histogram ──────────
// Byte-neutral (gated on perf::enabled): counts which rnix expr kind
// each maybe_thunk fall-through thunk wraps, so the 369K `_`-arm
// thunks can be traced to a kind and the byte-safe-elidable subset
// (constant Str, Paren, already-value List) separated from the
// laziness-critical subset (Select, Apply, If, With).
thread_local! {
    static MAYBE_OTHER_KINDS: RefCell<std::collections::BTreeMap<&'static str, u64>> =
        RefCell::new(std::collections::BTreeMap::new());
}

#[inline(always)]
pub fn inc_maybe_other_kind(kind: &'static str) {
    if crate::perf::enabled() {
        MAYBE_OTHER_KINDS.with(|m| *m.borrow_mut().entry(kind).or_insert(0) += 1);
    }
}

pub fn report_maybe_other_kinds() {
    if !crate::perf::enabled() {
        return;
    }
    MAYBE_OTHER_KINDS.with(|m| {
        let m = m.borrow();
        if m.is_empty() {
            return;
        }
        let mut rows: Vec<(&&'static str, &u64)> = m.iter().collect();
        rows.sort_by(|a, b| b.1.cmp(a.1));
        eprintln!("--- maybe_thunk `_`-arm by expr kind ---");
        for (k, v) in rows {
            eprintln!("  {k:<20} {v}");
        }
    });
}

/// Increment the thunks-created counter.
#[inline(always)]
pub fn inc_thunks_created() {
    if crate::perf::enabled() {
        THUNKS_CREATED.with(|c| c.set(c.get() + 1));
    }
}

/// Increment the thunks-forced-unique counter.
#[inline(always)]
pub fn inc_thunks_forced_unique() {
    if crate::perf::enabled() {
        THUNKS_FORCED_UNIQUE.with(|c| c.set(c.get() + 1));
    }
}

/// Get current force depth (debug).
pub fn current_force_depth() -> u32 {
    THUNK_CURRENT_FORCE_DEPTH.with(Cell::get)
}

/// Get thunks created count (for progress snapshots).
pub fn get_thunks_created() -> u64 {
    THUNKS_CREATED.with(Cell::get)
}

/// Get thunks forced count (for progress snapshots).
pub fn get_thunks_forced() -> u64 {
    THUNKS_FORCED_UNIQUE.with(Cell::get)
}

/// Zero the thunk-creation/force counters. Used by `perf::reset` /
/// `perf::with_scope` to establish a clean measurement window.
pub fn reset_thunk_stats() {
    THUNKS_CREATED.with(|c| c.set(0));
    THUNKS_FORCED_UNIQUE.with(|c| c.set(0));
    THUNK_MAX_FORCE_DEPTH.with(|c| c.set(0));
    OVERLAY_FLATTEN_NANOS.with(|c| c.set(0));
    SORTED_ENTRIES_NANOS.with(|c| c.set(0));
    SELF_REC_WALK_NANOS.with(|c| c.set(0));
}

/// Report thunk stats to stderr (called from `perf::report`).
pub fn report_thunk_stats() {
    if !crate::perf::enabled() {
        return;
    }
    let created = THUNKS_CREATED.with(Cell::get);
    let forced = THUNKS_FORCED_UNIQUE.with(Cell::get);
    let max_depth = THUNK_MAX_FORCE_DEPTH.with(Cell::get);
    eprintln!("thunks_created: {created}");
    eprintln!("thunks_forced:  {forced}");
    eprintln!("max_force_depth: {max_depth}");
}

#[cfg(test)]
mod tests {
    use super::*;

    // ── Force chain capture ─────────────────────────────────

    #[test]
    fn force_chain_display_empty() {
        let chain = ForceChain(vec![]);
        let s = chain.to_string();
        assert!(s.contains("0 frames"));
    }

    #[test]
    fn force_chain_display_single() {
        let chain = ForceChain(vec![ForceFrame {
            defined_in: Some(PathBuf::from("/test.nix")),
            description: "x".into(),
            thunk_id: 1,
        }]);
        let s = chain.to_string();
        assert!(s.contains("1 frames"));
        assert!(s.contains("/test.nix"));
        assert!(s.contains("x"));
    }

    #[test]
    fn force_chain_display_empty_descriptions_show_one_per_frame() {
        // Empty descriptions (cheap non-tracing path) bypass dedup so
        // the cycle length isn't visually collapsed to "repeated".
        let frames: Vec<ForceFrame> = (0..3)
            .map(|i| ForceFrame {
                defined_in: Some(PathBuf::from(format!("/m{i}.nix"))),
                description: String::new(),
                thunk_id: i,
            })
            .collect();
        let s = ForceChain(frames).to_string();
        assert!(s.contains("3 frames"));
        assert_eq!(s.matches("<thunk>").count(), 3);
        assert!(s.contains("SUI_TRACE_EVAL=verbose"));
    }

    #[test]
    fn force_chain_display_repeated_frames() {
        let chain = ForceChain(vec![
            ForceFrame {
                defined_in: None,
                description: "x".into(),
                thunk_id: 1,
            },
            ForceFrame {
                defined_in: None,
                description: "x".into(),
                thunk_id: 2,
            },
            ForceFrame {
                defined_in: None,
                description: "x".into(),
                thunk_id: 3,
            },
            ForceFrame {
                defined_in: None,
                description: "y".into(),
                thunk_id: 4,
            },
        ]);
        let s = chain.to_string();
        assert!(s.contains("repeated 2 more times"));
        assert!(s.contains("y"));
    }

    #[test]
    fn force_chain_display_eval_location() {
        let chain = ForceChain(vec![ForceFrame {
            defined_in: None,
            description: "z".into(),
            thunk_id: 1,
        }]);
        let s = chain.to_string();
        assert!(s.contains("<eval>"));
    }

    #[test]
    fn push_pop_force_stack() {
        // Clear the thread-local stack first.
        FORCE_STACK.with(|s| s.borrow_mut().clear());
        push_force(ForceFrame {
            defined_in: None,
            description: "a".into(),
            thunk_id: 100,
        });
        push_force(ForceFrame {
            defined_in: None,
            description: "b".into(),
            thunk_id: 200,
        });
        let chain = capture_cycle(100);
        assert_eq!(chain.0.len(), 2);
        assert_eq!(chain.0[0].thunk_id, 100);
        pop_force();
        pop_force();
    }

    #[test]
    fn capture_cycle_with_unknown_id() {
        FORCE_STACK.with(|s| s.borrow_mut().clear());
        push_force(ForceFrame {
            defined_in: None,
            description: "a".into(),
            thunk_id: 10,
        });
        // Capture with an ID not on the stack returns the whole stack.
        let chain = capture_cycle(999);
        assert_eq!(chain.0.len(), 1);
        pop_force();
    }

    // ── Trace mode ──────────────────────────────────────────

    #[test]
    fn trace_disabled_by_default() {
        // After init with no env var, trace should be off.
        // (Cannot reliably test env var setting in parallel tests,
        // so just verify the function is callable.)
        let _ = trace_enabled();
    }

    #[test]
    fn trace_force_enter_exit_no_panic() {
        // Ensure enter/exit don't panic even when trace is off.
        trace_force_enter(None, "test");
        trace_force_exit();
    }

    // ── Max force depth ─────────────────────────────────────

    #[test]
    fn check_force_depth_logic() {
        // Test all depth-limit scenarios in a single test to avoid
        // AtomicUsize races between parallel tests.
        FORCE_STACK.with(|s| s.borrow_mut().clear());

        // No limit — always OK.
        set_max_force_depth(0);
        assert!(check_force_depth().is_ok());

        // Within limit — OK.
        set_max_force_depth(10);
        push_force(ForceFrame {
            defined_in: None,
            description: "a".into(),
            thunk_id: 1,
        });
        assert!(check_force_depth().is_ok());

        // Exceeded — 2 items with limit 1.
        set_max_force_depth(1);
        push_force(ForceFrame {
            defined_in: None,
            description: "b".into(),
            thunk_id: 2,
        });
        let result = check_force_depth();
        assert!(result.is_err());
        assert!(result.unwrap_err().contains("force depth exceeded"));

        // Cleanup.
        pop_force();
        pop_force();
        set_max_force_depth(0);
    }

    // ── Thunk stats ─────────────────────────────────────────

    #[test]
    fn thunk_stats_increment() {
        // Just verify the functions don't panic.
        inc_thunks_created();
        inc_thunks_forced_unique();
    }

    // ── Integration: force chain with eval ───────────────────

    #[test]
    fn force_chain_captures_self_reference() {
        let result = crate::eval::eval("let x = x; in x");
        assert!(result.is_err());
        let msg = result.unwrap_err().to_string();
        assert!(
            msg.contains("infinite recursion")
                || msg.contains("force chain")
                || msg.contains("blackhole"),
            "expected infinite recursion error, got: {msg}"
        );
    }

    #[test]
    fn force_chain_captures_mutual_recursion() {
        let result = crate::eval::eval("let a = b; b = a; in a");
        assert!(result.is_err());
        let msg = result.unwrap_err().to_string();
        assert!(
            msg.contains("infinite recursion")
                || msg.contains("force chain")
                || msg.contains("blackhole"),
            "expected infinite recursion error, got: {msg}"
        );
    }

    #[test]
    fn force_chain_captures_rec_self_reference() {
        let result = crate::eval::eval("rec { x = x; }.x");
        assert!(result.is_err());
        let msg = result.unwrap_err().to_string();
        assert!(
            msg.contains("infinite recursion")
                || msg.contains("force chain")
                || msg.contains("blackhole"),
            "expected infinite recursion error, got: {msg}"
        );
    }
}