✨ Refactor VM tracing into trait-based system

manual/src/SUMMARY.md

@@ -32,6 +32,7 @@
 - [Method call syntax](./features/method-call-syntax.md)
 - [Slices](./features/slices.md)
 - [Memoization](./features/memoization.md)
+- [Tracing](./features/tracing.md)
 
 # Troubleshooting
 - [Overload dispatch with collections](./troubleshooting/overload-dispatch-collections.md)

manual/src/features/tracing.md

@@ -0,0 +1,80 @@
+# Tracing
+
+Andy C++ has built-in tracing support for inspecting how the bytecode VM executes your program. Tracing is available when the binary is compiled with the `trace` feature flag and is controlled via command-line flags on the `run` subcommand.
+
+```sh
+cargo run --features trace -- run --trace-print program.ndc
+```
+
+Multiple trace flags can be combined in a single invocation.
+
+## Trace modes
+
+### `--trace-print`
+
+Prints every VM instruction to stderr as it is dispatched, along with the corresponding source excerpt:
+
+```
+[VM] 0000 GetGlobal(2)                    assert_eq
+[VM] 0001 GetGlobal(87)                   +
+[VM] 0002 Constant(0)                     15
+[VM] 0003 Constant(1)                     3
+[VM] 0004 Call(2)                         +
+```
+
+This is useful for understanding the exact sequence of bytecode operations your program produces.
+
+### `--trace-histogram`
+
+Prints a summary table of how many times each instruction type was dispatched:
+
+```
+--------------------------------------------------
+Instruction histogram (179 total)
+--------------------------------------------------
+  Call                         43  ( 24.0%)
+  Constant                     44  ( 24.6%)
+  GetLocal                     32  ( 17.9%)
+  ...
+```
+
+### `--trace-time`
+
+Measures cumulative wall-clock time spent per instruction type and prints a summary:
+
+```
+------------------------------------------------------------
+Instruction timing (total: 184µs)
+------------------------------------------------------------
+  Call                        69µs  ( 37.4%)
+  Constant                    33µs  ( 18.1%)
+  ...
+```
+
+The time for an instruction is measured from when it starts executing until the next instruction begins.
+
+### `--trace-span`
+
+Renders the source code as a heat map, coloring regions from green (cold) to red (hot) based on how much execution time was spent on the bytecode instructions associated with each source span.
+
+```sh
+cargo run --features trace -- run --trace-span program.ndc
+```
+
+This gives a visual overview of where your program spends its time. The heat is additive: if a character is covered by multiple overlapping spans (e.g. an expression inside a loop body), all their durations contribute, so hot inner code within a hot loop shows as hotter than the surrounding syntax.
+
+> **Note:** The span-based heat map is a rough profiling aid, not a precise profiler. In particular, recursive function calls can produce misleading results because the function body spans overlap with themselves across call depths, and the timing of `Call` instructions only measures call-setup overhead rather than the total time spent in the callee.
+
+## Building with tracing
+
+Tracing is behind a Cargo feature flag so it has zero cost when not compiled in:
+
+```sh
+# Without tracing (default) — no overhead
+cargo build
+
+# With tracing support
+cargo build --features trace
+```
+
+The trace flags only appear in `--help` when compiled with the feature enabled.

ndc_bin/Cargo.toml

@@ -25,3 +25,6 @@ yansi.workspace = true
 rustyline.workspace = true
 termimad = "0.34.1"
 tokio.workspace = true
+
+[features]
+trace = ["ndc_interpreter/trace"]

ndc_bin/src/main.rs

@@ -14,6 +14,8 @@ mod repl;
 
 mod docs;
 mod highlighter;
+#[cfg(feature = "trace")]
+mod span_tracer;
 
 #[derive(Parser)]
 #[command(name = "Andy C++")]
@@ -28,7 +30,25 @@ struct Cli {
 #[derive(Subcommand)]
 enum Command {
     /// Execute an .ndc file or start the repl (this default action may be omitted)
-    Run { file: Option<PathBuf> },
+    Run {
+        file: Option<PathBuf>,
+        /// Print each instruction as it is dispatched
+        #[cfg(feature = "trace")]
+        #[arg(long)]
+        trace_print: bool,
+        /// Print a histogram of instruction dispatch counts
+        #[cfg(feature = "trace")]
+        #[arg(long)]
+        trace_histogram: bool,
+        /// Print cumulative time spent per instruction type
+        #[cfg(feature = "trace")]
+        #[arg(long)]
+        trace_time: bool,
+        /// Render source as a heat map colored by time spent per span
+        #[cfg(feature = "trace")]
+        #[arg(long)]
+        trace_span: bool,
+    },
     /// Output an .ndc file using the built-in syntax highlighting engine
     Highlight { file: PathBuf },
 
@@ -56,14 +76,32 @@ enum Command {
 
 impl Default for Command {
     fn default() -> Self {
-        Self::Run { file: None }
+        Self::Run {
+            file: None,
+            #[cfg(feature = "trace")]
+            trace_print: false,
+            #[cfg(feature = "trace")]
+            trace_histogram: false,
+            #[cfg(feature = "trace")]
+            trace_time: false,
+            #[cfg(feature = "trace")]
+            trace_span: false,
+        }
     }
 }
 
 enum Action {
     RunLsp,
     RunFile {
         path: PathBuf,
+        #[cfg(feature = "trace")]
+        trace_print: bool,
+        #[cfg(feature = "trace")]
+        trace_histogram: bool,
+        #[cfg(feature = "trace")]
+        trace_time: bool,
+        #[cfg(feature = "trace")]
+        trace_span: bool,
     },
     DisassembleFile(PathBuf),
     HighlightFile(PathBuf),
@@ -79,8 +117,28 @@ impl TryFrom<Command> for Action {
 
     fn try_from(value: Command) -> Result<Self, Self::Error> {
         let action = match value {
-            Command::Run { file: Some(file) } => Self::RunFile { path: file },
-            Command::Run { file: None } => Self::StartRepl,
+            Command::Run {
+                file: Some(file),
+                #[cfg(feature = "trace")]
+                trace_print,
+                #[cfg(feature = "trace")]
+                trace_histogram,
+                #[cfg(feature = "trace")]
+                trace_time,
+                #[cfg(feature = "trace")]
+                trace_span,
+            } => Self::RunFile {
+                path: file,
+                #[cfg(feature = "trace")]
+                trace_print,
+                #[cfg(feature = "trace")]
+                trace_histogram,
+                #[cfg(feature = "trace")]
+                trace_time,
+                #[cfg(feature = "trace")]
+                trace_span,
+            },
+            Command::Run { file: None, .. } => Self::StartRepl,
             Command::Lsp { stdio: _ } => Self::RunLsp,
             Command::Disassemble { file } => Self::DisassembleFile(file),
             Command::Highlight { file } => Self::HighlightFile(file),
@@ -93,6 +151,14 @@ impl TryFrom<Command> for Action {
                     }
                     1 => Self::RunFile {
                         path: args[0].parse::<PathBuf>().context("invalid path")?,
+                        #[cfg(feature = "trace")]
+                        trace_print: false,
+                        #[cfg(feature = "trace")]
+                        trace_histogram: false,
+                        #[cfg(feature = "trace")]
+                        trace_time: false,
+                        #[cfg(feature = "trace")]
+                        trace_span: false,
                     },
                     n => return Err(anyhow!("invalid number of arguments: {n}")),
                 }
@@ -108,7 +174,17 @@ fn main() -> anyhow::Result<()> {
     let action: Action = cli.command.unwrap_or_default().try_into()?;
 
     match action {
-        Action::RunFile { path } => {
+        Action::RunFile {
+            path,
+            #[cfg(feature = "trace")]
+            trace_print,
+            #[cfg(feature = "trace")]
+            trace_histogram,
+            #[cfg(feature = "trace")]
+            trace_time,
+            #[cfg(feature = "trace")]
+            trace_span,
+        } => {
             let filename = path
                 .file_name()
                 .and_then(|name| name.to_str())
@@ -118,6 +194,28 @@ fn main() -> anyhow::Result<()> {
 
             let mut interpreter = Interpreter::new();
             interpreter.configure(ndc_stdlib::register);
+
+            #[cfg(feature = "trace")]
+            {
+                use ndc_interpreter::tracer;
+                let mut tracers: Vec<Box<dyn tracer::VmTracer>> = Vec::new();
+                if trace_print {
+                    tracers.push(Box::new(tracer::PrintTracer));
+                }
+                if trace_histogram {
+                    tracers.push(Box::new(tracer::HistogramTracer::new()));
+                }
+                if trace_time {
+                    tracers.push(Box::new(tracer::TimingTracer::new()));
+                }
+                if trace_span {
+                    tracers.push(Box::new(span_tracer::SpanTracer::new()));
+                }
+                if !tracers.is_empty() {
+                    interpreter.set_tracer(Box::new(tracer::CompositeTracer::new(tracers)));
+                }
+            }
+
             let name = filename.as_deref().unwrap_or("<input>");
             if let Err(err) = interpreter.eval_named(name, &string) {
                 diagnostic::emit_error(interpreter.source_db(), err);

ndc_bin/src/span_tracer.rs

@@ -0,0 +1,118 @@
+use ndc_interpreter::tracer::{InstructionContext, VmTracer};
+use std::collections::HashMap;
+use std::io::Write;
+use std::time::{Duration, Instant};
+use yansi::Paint;
+
+/// Accumulates time per source span, then renders the source code as a heat map
+/// where cold regions are green and hot regions are red.
+pub struct SpanTracer {
+    /// Accumulated time per (offset, length) span.
+    times: HashMap<(usize, usize), Duration>,
+    last: Option<((usize, usize), Instant)>,
+    source: Option<String>,
+}
+
+impl SpanTracer {
+    pub fn new() -> Self {
+        Self {
+            times: HashMap::new(),
+            last: None,
+            source: None,
+        }
+    }
+}
+
+impl VmTracer for SpanTracer {
+    fn on_instruction(&mut self, ctx: &InstructionContext<'_>) {
+        if self.source.is_none()
+            && let Some(src) = ctx.source
+        {
+            self.source = Some(src.to_owned());
+        }
+
+        let now = Instant::now();
+        let key = (ctx.span.offset(), ctx.span.end() - ctx.span.offset());
+        if let Some((prev_key, start)) = self.last.take() {
+            *self.times.entry(prev_key).or_default() += now - start;
+        }
+        self.last = Some((key, now));
+    }
+
+    fn on_complete(&mut self) {
+        // Finalize the last instruction's timing.
+        if let Some((key, start)) = self.last.take() {
+            *self.times.entry(key).or_default() += start.elapsed();
+        }
+
+        let Some(source) = &self.source else {
+            return;
+        };
+
+        if self.times.is_empty() {
+            return;
+        }
+
+        // Additive heat: each span's duration is added to every byte it covers.
+        // This means bytes inside both a hot outer span and an inner span accumulate
+        // both contributions, correctly showing them as hotter.
+        let spans: Vec<_> = self.times.drain().collect();
+        let mut heat = vec![Duration::ZERO; source.len()];
+        for ((offset, length), dur) in &spans {
+            let end = (offset + length).min(source.len());
+            for h in &mut heat[*offset..end] {
+                *h += *dur;
+            }
+        }
+
+        // Find max duration for normalization.
+        let max_dur = heat.iter().max().copied().unwrap_or(Duration::ZERO);
+
+        if max_dur.is_zero() {
+            print!("{source}");
+            let _ = std::io::stdout().flush();
+            return;
+        }
+
+        let max_nanos = max_dur.as_nanos() as f64;
+
+        // Render: walk the source, coloring each non-whitespace character by heat.
+        let mut byte_pos = 0;
+        for ch in source.chars() {
+            let len = ch.len_utf8();
+            let s = &source[byte_pos..byte_pos + len];
+
+            let color = if ch.is_ascii_whitespace() || byte_pos >= heat.len() {
+                None
+            } else {
+                let d = heat[byte_pos];
+                if d.is_zero() {
+                    None
+                } else {
+                    let t = d.as_nanos() as f64 / max_nanos;
+                    Some(heat_color(t))
+                }
+            };
+
+            match color {
+                Some((r, g, b)) => print!("{}", s.rgb(r, g, b)),
+                None => print!("{s}"),
+            }
+
+            byte_pos += len;
+        }
+
+        let _ = std::io::stdout().flush();
+    }
+}
+
+/// Interpolate from soft green (cold, t=0) through warm peach (t=0.5) to soft red (hot, t=1).
+fn heat_color(t: f64) -> (u8, u8, u8) {
+    let t = t.clamp(0.0, 1.0);
+    // Mix towards white to create pastel tones: lerp between the pure hue and (255,255,255).
+    let pastel = 0.4; // 0.0 = fully saturated, 1.0 = white
+    let r = ((t.min(0.5) * 2.0).mul_add(1.0 - pastel, pastel) * 255.0) as u8;
+    let g = ((t - 0.5).max(0.0).mul_add(-2.0, 1.0)).mul_add(1.0 - pastel, pastel) * 255.0;
+    let b = (pastel * 255.0) as u8;
+    (r, g as u8, b)
+}

ndc_interpreter/Cargo.toml

@@ -5,7 +5,7 @@ edition.workspace = true
 version.workspace = true
 
 [features]
-vm-trace = ["ndc_vm/vm-trace"]
+trace = ["ndc_vm/trace"]
 
 [dependencies]
 ndc_analyser.workspace = true