Refactor VM tracing into trait-based system with CLI flags

Replace ad-hoc #[cfg(feature = "vm-trace")] blocks with a composable
VmTracer trait behind a renamed `trace` feature flag. Add four tracer
implementations: PrintTracer, HistogramTracer, TimingTracer, and
SpanTracer (source heat map). Tracers are enabled via CLI flags
--trace-print, --trace-histogram, --trace-time, and --trace-span.

Co-Authored-By: Claude Opus 4.6 <[email protected]>

Author: timfennis

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

ndc_interpreter/src/lib.rs

@@ -7,6 +7,8 @@ use ndc_vm::value::CompiledFunction;
 use ndc_vm::{OutputSink, Vm};
 use std::rc::Rc;
 
+#[cfg(feature = "trace")]
+pub use ndc_vm::tracer;
 pub use ndc_vm::{NativeFunction, Value};
 
 pub struct Interpreter {
@@ -18,6 +20,8 @@ pub struct Interpreter {
     /// `None` until the first `eval` call; kept alive afterwards so that
     /// variables declared on one line are visible on subsequent lines.
     repl_state: Option<(Vm, Compiler)>,
+    #[cfg(feature = "trace")]
+    tracer: Option<Box<dyn tracer::VmTracer>>,
 }
 
 impl Interpreter {
@@ -41,6 +45,8 @@ impl Interpreter {
             analyser: Analyser::from_scope_tree(ScopeTree::from_global_scope(vec![])),
             source_db: SourceDb::new(),
             repl_state: None,
+            #[cfg(feature = "trace")]
+            tracer: None,
         }
     }
 
@@ -55,6 +61,11 @@ impl Interpreter {
         self.analyser = Analyser::from_scope_tree(ScopeTree::from_global_scope(functions));
     }
 
+    #[cfg(feature = "trace")]
+    pub fn set_tracer(&mut self, tracer: Box<dyn tracer::VmTracer>) {
+        self.tracer = Some(tracer);
+    }
+
     pub fn functions(&self) -> impl Iterator<Item = &Rc<NativeFunction>> {
         self.registry.iter()
     }
@@ -138,8 +149,8 @@ impl Interpreter {
 
     fn interpret_vm(
         &mut self,
-        #[cfg(feature = "vm-trace")] input: &str,
-        #[cfg(not(feature = "vm-trace"))] _input: &str,
+        #[cfg(feature = "trace")] input: &str,
+        #[cfg(not(feature = "trace"))] _input: &str,
         expressions: impl Iterator<Item = ExpressionLocation>,
     ) -> Result<Value, InterpreterError> {
         use ndc_vm::{Function as VmFunction, Object as VmObject, Value as VmValue};
@@ -163,9 +174,12 @@ impl Interpreter {
                 };
                 let (code, checkpoint) = Compiler::compile_resumable(expressions)?;
                 let mut vm = Vm::new(code, globals).with_output(output);
-                #[cfg(feature = "vm-trace")]
+                #[cfg(feature = "trace")]
                 {
                     vm = vm.with_source(input);
+                    if let Some(tracer) = self.tracer.take() {
+                        vm = vm.with_tracer(tracer);
+                    }
                 }
                 vm.run()?;
                 let result = vm.last_value(checkpoint.num_locals());
@@ -177,7 +191,7 @@ impl Interpreter {
                 let prev_num_locals = checkpoint.num_locals();
                 let (code, new_checkpoint) = checkpoint.resume(expressions)?;
                 vm.resume_from_halt(code, globals, resume_ip, prev_num_locals);
-                #[cfg(feature = "vm-trace")]
+                #[cfg(feature = "trace")]
                 {
                     vm.set_source(input);
                 }

ndc_vm/Cargo.toml

@@ -4,7 +4,7 @@ edition.workspace = true
 version.workspace = true
 
 [features]
-vm-trace = []
+trace = []
 
 [dependencies]
 thiserror.workspace = true

ndc_vm/src/lib.rs

@@ -3,6 +3,9 @@ pub mod compiler;
 pub mod disassemble;
 pub mod error;
 pub mod iterator;
+#[cfg(feature = "trace")]
+#[allow(clippy::print_stderr)]
+pub mod tracer;
 pub mod value;
 mod vm;