diff --git a/manual/src/SUMMARY.md b/manual/src/SUMMARY.md index eaffa0e7..60712370 100644 --- a/manual/src/SUMMARY.md +++ b/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) diff --git a/manual/src/features/tracing.md b/manual/src/features/tracing.md new file mode 100644 index 00000000..098485d9 --- /dev/null +++ b/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. diff --git a/ndc_bin/Cargo.toml b/ndc_bin/Cargo.toml index 836dac29..dfbf2217 100644 --- a/ndc_bin/Cargo.toml +++ b/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"] diff --git a/ndc_bin/src/main.rs b/ndc_bin/src/main.rs index 23048549..bc89e30a 100644 --- a/ndc_bin/src/main.rs +++ b/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 }, + Run { + file: Option, + /// 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,7 +76,17 @@ 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, + } } } @@ -64,6 +94,14 @@ 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 for Action { fn try_from(value: Command) -> Result { 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 for Action { } 1 => Self::RunFile { path: args[0].parse::().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> = 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(""); if let Err(err) = interpreter.eval_named(name, &string) { diagnostic::emit_error(interpreter.source_db(), err); diff --git a/ndc_bin/src/span_tracer.rs b/ndc_bin/src/span_tracer.rs new file mode 100644 index 00000000..a68d1fe4 --- /dev/null +++ b/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, +} + +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) +} diff --git a/ndc_interpreter/Cargo.toml b/ndc_interpreter/Cargo.toml index b23d6247..e023d5d5 100644 --- a/ndc_interpreter/Cargo.toml +++ 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 diff --git a/ndc_interpreter/src/lib.rs b/ndc_interpreter/src/lib.rs index 3fc87c2c..162c4679 100644 --- a/ndc_interpreter/src/lib.rs +++ b/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>, } 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) { + self.tracer = Some(tracer); + } + pub fn functions(&self) -> impl Iterator> { 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, ) -> Result { 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); } diff --git a/ndc_vm/Cargo.toml b/ndc_vm/Cargo.toml index da351e2a..99807be8 100644 --- a/ndc_vm/Cargo.toml +++ b/ndc_vm/Cargo.toml @@ -4,7 +4,7 @@ edition.workspace = true version.workspace = true [features] -vm-trace = [] +trace = [] [dependencies] thiserror.workspace = true diff --git a/ndc_vm/src/lib.rs b/ndc_vm/src/lib.rs index 4ae2bd61..bb8df3da 100644 --- a/ndc_vm/src/lib.rs +++ b/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; diff --git a/ndc_vm/src/tracer.rs b/ndc_vm/src/tracer.rs new file mode 100644 index 00000000..c8cefa03 --- /dev/null +++ b/ndc_vm/src/tracer.rs @@ -0,0 +1,224 @@ +use crate::chunk::OpCode; +use ndc_lexer::Span; +use std::collections::HashMap; +use std::fmt; +use std::time::{Duration, Instant}; + +fn format_duration(d: &Duration) -> String { + let nanos = d.as_nanos(); + if nanos < 1_000 { + format!("{nanos}ns") + } else if nanos < 1_000_000 { + let micros = nanos as f64 / 1_000.0; + fmt::format(format_args!("{micros:.0}µs")) + } else if nanos < 1_000_000_000 { + let millis = nanos as f64 / 1_000_000.0; + fmt::format(format_args!("{millis:.1}ms")) + } else { + let secs = d.as_secs_f64(); + fmt::format(format_args!("{secs:.2}s")) + } +} + +/// Context passed to a tracer on every dispatched instruction. +pub struct InstructionContext<'a> { + pub ip: usize, + pub opcode: &'a OpCode, + pub span: Span, + pub source: Option<&'a str>, +} + +/// Trait for observing VM instruction dispatch. +pub trait VmTracer { + /// Called before each instruction is dispatched. + fn on_instruction(&mut self, ctx: &InstructionContext<'_>); + + /// Called when the VM finishes execution. + /// Tracers that accumulate data should print their summaries here. + fn on_complete(&mut self); +} + +/// Maps an `OpCode` variant to its name as a static string. +fn opcode_name(op: &OpCode) -> &'static str { + match op { + OpCode::Call(_) => "Call", + OpCode::Pop => "Pop", + OpCode::Jump(_) => "Jump", + OpCode::JumpIfTrue(_) => "JumpIfTrue", + OpCode::JumpIfFalse(_) => "JumpIfFalse", + OpCode::Constant(_) => "Constant", + OpCode::GetLocal(_) => "GetLocal", + OpCode::GetUpvalue(_) => "GetUpvalue", + OpCode::SetLocal(_) => "SetLocal", + OpCode::SetUpvalue(_) => "SetUpvalue", + OpCode::GetGlobal(_) => "GetGlobal", + OpCode::MakeList(_) => "MakeList", + OpCode::MakeTuple(_) => "MakeTuple", + OpCode::MakeMap { .. } => "MakeMap", + OpCode::Closure { .. } => "Closure", + OpCode::GetIterator => "GetIterator", + OpCode::IterNext(_) => "IterNext", + OpCode::ListPush(_) => "ListPush", + OpCode::MapInsert(_) => "MapInsert", + OpCode::MakeRange { .. } => "MakeRange", + OpCode::Unpack(_) => "Unpack", + OpCode::Halt => "Halt", + OpCode::Return => "Return", + OpCode::CloseUpvalue(_) => "CloseUpvalue", + OpCode::Memoize => "Memoize", + } +} + +// --------------------------------------------------------------------------- +// PrintTracer +// --------------------------------------------------------------------------- + +/// Prints each instruction to stderr as it is dispatched. +pub struct PrintTracer; + +impl VmTracer for PrintTracer { + fn on_instruction(&mut self, ctx: &InstructionContext<'_>) { + let excerpt = ctx.source.and_then(|src| { + src.get(ctx.span.range()) + .map(|s| s.trim().replace('\n', "↵")) + }); + let op_str = format!("{:?}", ctx.opcode); + match excerpt { + Some(s) => eprintln!("[VM] {:04} {:<30} {}", ctx.ip, op_str, s), + None => eprintln!("[VM] {:04} {}", ctx.ip, op_str), + } + } + + fn on_complete(&mut self) {} +} + +// --------------------------------------------------------------------------- +// HistogramTracer +// --------------------------------------------------------------------------- + +/// Counts how many times each instruction is dispatched and prints a summary. +pub struct HistogramTracer { + counts: HashMap<&'static str, u64>, +} + +impl HistogramTracer { + #[must_use] + pub fn new() -> Self { + Self { + counts: HashMap::new(), + } + } +} + +impl Default for HistogramTracer { + fn default() -> Self { + Self::new() + } +} + +impl VmTracer for HistogramTracer { + fn on_instruction(&mut self, ctx: &InstructionContext<'_>) { + *self.counts.entry(opcode_name(ctx.opcode)).or_insert(0) += 1; + } + + fn on_complete(&mut self) { + let mut entries: Vec<_> = self.counts.drain().collect(); + entries.sort_by(|a, b| b.1.cmp(&a.1)); + + let total: u64 = entries.iter().map(|(_, c)| c).sum(); + eprintln!("\n{:-<50}", ""); + eprintln!("Instruction histogram ({total} total)"); + eprintln!("{:-<50}", ""); + for (name, count) in &entries { + let pct = *count as f64 / total as f64 * 100.0; + eprintln!(" {name:<20} {count:>10} ({pct:5.1}%)"); + } + } +} + +// --------------------------------------------------------------------------- +// TimingTracer +// --------------------------------------------------------------------------- + +/// Measures cumulative time spent on each instruction type. +/// +/// Timing for instruction N starts when `on_instruction` is called for N, +/// and ends when `on_instruction` is called for N+1 (or `on_complete`). +pub struct TimingTracer { + times: HashMap<&'static str, Duration>, + last: Option<(&'static str, Instant)>, +} + +impl TimingTracer { + #[must_use] + pub fn new() -> Self { + Self { + times: HashMap::new(), + last: None, + } + } +} + +impl Default for TimingTracer { + fn default() -> Self { + Self::new() + } +} + +impl VmTracer for TimingTracer { + fn on_instruction(&mut self, ctx: &InstructionContext<'_>) { + let now = Instant::now(); + if let Some((prev_name, start)) = self.last.take() { + *self.times.entry(prev_name).or_default() += now - start; + } + self.last = Some((opcode_name(ctx.opcode), now)); + } + + fn on_complete(&mut self) { + if let Some((name, start)) = self.last.take() { + *self.times.entry(name).or_default() += start.elapsed(); + } + + let mut entries: Vec<_> = self.times.drain().collect(); + entries.sort_by(|a, b| b.1.cmp(&a.1)); + + let total: Duration = entries.iter().map(|(_, d)| d).sum(); + eprintln!("\n{:-<60}", ""); + eprintln!("Instruction timing (total: {})", format_duration(&total)); + eprintln!("{:-<60}", ""); + for (name, dur) in &entries { + let pct = dur.as_secs_f64() / total.as_secs_f64() * 100.0; + eprintln!(" {name:<20} {:>10} ({pct:5.1}%)", format_duration(dur)); + } + } +} + +// --------------------------------------------------------------------------- +// CompositeTracer +// --------------------------------------------------------------------------- + +/// Dispatches to multiple tracers. +pub struct CompositeTracer { + tracers: Vec>, +} + +impl CompositeTracer { + #[must_use] + pub fn new(tracers: Vec>) -> Self { + Self { tracers } + } +} + +impl VmTracer for CompositeTracer { + fn on_instruction(&mut self, ctx: &InstructionContext<'_>) { + for tracer in &mut self.tracers { + tracer.on_instruction(ctx); + } + } + + fn on_complete(&mut self) { + for tracer in &mut self.tracers { + tracer.on_complete(); + } + } +} diff --git a/ndc_vm/src/vm.rs b/ndc_vm/src/vm.rs index 8beda689..6ae2959d 100644 --- a/ndc_vm/src/vm.rs +++ b/ndc_vm/src/vm.rs @@ -49,8 +49,10 @@ pub struct Vm { open_upvalues: Vec>>, /// Output sink for `print`, `dbg`, and similar I/O built-ins. output: OutputSink, - #[cfg(feature = "vm-trace")] + #[cfg(feature = "trace")] source: Option, + #[cfg(feature = "trace")] + tracer: Option>, } type MemoCache = (Rc>>, u64); @@ -83,8 +85,10 @@ impl Vm { }], open_upvalues: Vec::new(), output: OutputSink::Stdout, - #[cfg(feature = "vm-trace")] + #[cfg(feature = "trace")] source: None, + #[cfg(feature = "trace")] + tracer: None, }; for _ in 0..num_locals { vm.stack.push(Value::unit()); @@ -114,17 +118,23 @@ impl Vm { .map_err(|e| VmError::native(e.to_string())) } - #[cfg(feature = "vm-trace")] + #[cfg(feature = "trace")] pub fn with_source(mut self, source: impl Into) -> Self { self.source = Some(source.into()); self } - #[cfg(feature = "vm-trace")] + #[cfg(feature = "trace")] pub fn set_source(&mut self, source: impl Into) { self.source = Some(source.into()); } + #[cfg(feature = "trace")] + pub fn with_tracer(mut self, tracer: Box) -> Self { + self.tracer = Some(tracer); + self + } + pub fn run(&mut self) -> Result<(), VmError> { self.run_to_depth(0) } @@ -137,29 +147,26 @@ impl Vm { panic!("no call frames") } - loop { + let result = loop { let frame = self.frames.last_mut().expect("must not be empty"); let ip = frame.ip; let span = frame.closure.prototype.body.span(ip); let op = frame.closure.prototype.body.opcode(ip); frame.ip += 1; - #[cfg(feature = "vm-trace")] - { - let excerpt = self - .source - .as_deref() - .and_then(|src| src.get(span.range()).map(|s| s.trim().replace('\n', "↵"))); - let op_str = format!("{op:?}"); - match excerpt { - Some(s) => eprintln!("[VM] {ip:04} {op_str:<30} {s}"), - None => eprintln!("[VM] {ip:04} {op_str}"), - } + #[cfg(feature = "trace")] + if let Some(tracer) = &mut self.tracer { + tracer.on_instruction(&crate::tracer::InstructionContext { + ip, + opcode: op, + span, + source: self.source.as_deref(), + }); } match op { OpCode::Halt => { - return Ok(()); + break Ok(()); } OpCode::Return => { let ret = self.stack.pop().expect("stack underflow"); @@ -180,7 +187,7 @@ impl Vm { self.frames.pop().expect("no frame to pop"); self.stack.push(ret); if self.frames.len() == target_depth { - return Ok(()); + break Ok(()); } } OpCode::Constant(idx) => { @@ -508,12 +515,16 @@ impl Vm { })); } } + }; - #[cfg(feature = "vm-trace")] - { - dbg!(&self.stack); - } + #[cfg(feature = "trace")] + if target_depth == 0 + && let Some(tracer) = &mut self.tracer + { + tracer.on_complete(); } + + result } /// Returns a shared upvalue cell for the given absolute stack slot, creating @@ -649,8 +660,10 @@ impl Vm { frames: Vec::new(), open_upvalues: Vec::new(), output: OutputSink::Stdout, - #[cfg(feature = "vm-trace")] + #[cfg(feature = "trace")] source: None, + #[cfg(feature = "trace")] + tracer: None, }; vm.call_callback(func, args) }