Add debug mode and VM tracing

Introduce a `debug_mode` flag to the `Environment` and a new `run_debug`
method. This method uses a `TracingObserver` to log the VM's execution
flow, including node evaluation and scope state changes. This allows for
detailed inspection of script execution.

The `BoundKind` enum now also includes a `display_name` method for
better log readability.
This commit is contained in:
Michael Schimmel
2026-02-18 00:56:29 +01:00
parent 25e3bc1d01
commit faada16723
5 changed files with 212 additions and 30 deletions
+20 -3
View File
@@ -70,7 +70,24 @@ pub enum BoundKind {
Map {
entries: Vec<(Node<BoundKind, StaticType>, Node<BoundKind, StaticType>)>,
},
// Extension points (need to be adapted for bound nodes if they use variables)
// For now, we assume extensions are self-contained or handled dynamically.
}
impl BoundKind {
pub fn display_name(&self) -> String {
match self {
BoundKind::Nop => "NOP".to_string(),
BoundKind::Constant(v) => format!("CONST({})", v),
BoundKind::Get(addr) => format!("GET({:?})", addr),
BoundKind::Set { addr, .. } => format!("SET({:?})", addr),
BoundKind::DefLocal { slot, .. } => format!("DEF_LOCAL(Slot:{})", slot),
BoundKind::If { .. } => "IF".to_string(),
BoundKind::DefGlobal { global_index, .. } => format!("DEF_GLOBAL(Idx:{})", global_index),
BoundKind::Lambda { upvalues, .. } => format!("LAMBDA(Captures:{})", upvalues.len()),
BoundKind::Call { .. } => "CALL".to_string(),
BoundKind::TailCall { .. } => "T-CALL".to_string(),
BoundKind::Block { .. } => "BLOCK".to_string(),
BoundKind::Tuple { elements } => format!("TUPLE({})", elements.len()),
BoundKind::Map { entries } => format!("MAP({})", entries.len()),
}
}
}
+43 -10
View File
@@ -4,7 +4,7 @@ use std::collections::HashMap;
use crate::ast::types::{Value, StaticType};
use crate::ast::parser::Parser;
use crate::ast::compiler::binder::Binder;
use crate::ast::vm::VM;
use crate::ast::vm::{VM, TracingObserver};
use crate::ast::compiler::tco::TCO;
@@ -13,6 +13,7 @@ use crate::ast::compiler::dumper::Dumper;
pub struct Environment {
pub global_names: Rc<RefCell<HashMap<String, (u32, StaticType)>>>,
pub global_values: Rc<RefCell<Vec<Value>>>,
pub debug_mode: bool,
}
impl Default for Environment {
@@ -26,11 +27,16 @@ impl Environment {
let env = Self {
global_names: Rc::new(RefCell::new(HashMap::new())),
global_values: Rc::new(RefCell::new(Vec::new())),
debug_mode: false,
};
env.register_stdlib();
env
}
pub fn set_debug_mode(&mut self, enabled: bool) {
self.debug_mode = enabled;
}
pub fn register_native(&self, name: &str, ty: StaticType, func: impl Fn(Vec<Value>) -> Value + 'static) {
let mut names = self.global_names.borrow_mut();
let mut values = self.global_values.borrow_mut();
@@ -118,23 +124,50 @@ impl Environment {
}
pub fn run_script(&self, source: &str) -> Result<Value, String> {
if self.debug_mode {
let (res, logs) = self.run_debug(source)?;
for line in logs {
println!("{}", line);
}
res
} else {
// 1. Parse
let mut parser = Parser::new(source)?;
let untyped_ast = parser.parse_expression()?;
// 2. Check for trailing tokens
if !parser.at_eof() {
return Err("Unexpected trailing expressions in script. Use (do ...) for sequences.".to_string());
}
// 3. Bind & Type Check
let bound_ast = Binder::bind_root(self.global_names.clone(), &untyped_ast)?;
// 4. Optimize
let bound_ast = TCO::optimize(bound_ast);
// 5. Execute
let mut vm = VM::new(self.global_values.clone());
vm.run(&bound_ast)
}
}
pub fn run_debug(&self, source: &str) -> Result<(Result<Value, String>, Vec<String>), String> {
// 1. Parse
let mut parser = Parser::new(source)?;
let untyped_ast = parser.parse_expression()?;
// 2. Check for trailing tokens
if !parser.at_eof() {
return Err("Unexpected trailing expressions in script. Use (do ...) for sequences.".to_string());
}
// 3. Bind & Type Check
// 2. Bind
let bound_ast = Binder::bind_root(self.global_names.clone(), &untyped_ast)?;
// 4. Optimize
// 3. Optimize (TCO)
let bound_ast = TCO::optimize(bound_ast);
// 5. Execute
// 4. Execute with TracingObserver
let mut vm = VM::new(self.global_values.clone());
vm.run(&bound_ast)
let mut observer = TracingObserver::new();
let result = vm.run_with_observer(&mut observer, &bound_ast);
Ok((result, observer.logs))
}
}
+32
View File
@@ -91,6 +91,38 @@ pub enum StaticType {
Object(&'static str),
}
impl fmt::Display for StaticType {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
StaticType::Any => write!(f, "any"),
StaticType::Void => write!(f, "void"),
StaticType::Bool => write!(f, "bool"),
StaticType::Int => write!(f, "int"),
StaticType::Float => write!(f, "float"),
StaticType::Text => write!(f, "text"),
StaticType::Keyword => write!(f, "keyword"),
StaticType::List(inner) => write!(f, "[{}]", inner),
StaticType::Record(fields) => {
write!(f, "{{")?;
for (i, (k, v)) in fields.iter().enumerate() {
if i > 0 { write!(f, ", ")?; }
write!(f, ":{} {}", k.name(), v)?;
}
write!(f, "}}")
},
StaticType::Function { params, ret } => {
write!(f, "fn(")?;
for (i, p) in params.iter().enumerate() {
if i > 0 { write!(f, " ")?; }
write!(f, "{}", p)?;
}
write!(f, ") -> {}", ret)
},
StaticType::Object(name) => write!(f, "{}", name),
}
}
}
impl Value {
pub fn is_truthy(&self) -> bool {
match self {
+90 -17
View File
@@ -27,6 +27,61 @@ struct CallFrame {
closure: Option<Rc<Closure>>,
}
/// Hook for observing VM execution (zero-cost when O::ACTIVE is false)
pub trait VMObserver {
const ACTIVE: bool = false;
fn before_eval(&mut self, _vm: &VM, _node: &Node<BoundKind, StaticType>, _indent: usize) {}
fn after_eval(&mut self, _vm: &VM, _node: &Node<BoundKind, StaticType>, _res: &Result<Value, String>, _indent: usize) {}
}
/// Default observer that does nothing and should be optimized away
pub struct NoOpObserver;
impl VMObserver for NoOpObserver {}
/// Observer that logs the execution tree and scope state
pub struct TracingObserver {
pub logs: Vec<String>,
}
impl TracingObserver {
pub fn new() -> Self {
Self { logs: Vec::new() }
}
fn pad(&self, indent: usize) -> String {
"| ".repeat(indent)
}
}
impl VMObserver for TracingObserver {
const ACTIVE: bool = true;
fn before_eval(&mut self, _vm: &VM, node: &Node<BoundKind, StaticType>, indent: usize) {
let pad = self.pad(indent);
self.logs.push(format!("{}{} [{}]: {{", pad, node.kind.display_name(), node.ty));
}
fn after_eval(&mut self, vm: &VM, node: &Node<BoundKind, StaticType>, res: &Result<Value, String>, indent: usize) {
let pad = self.pad(indent);
// Show scope state on certain nodes (like Delphi ShowScope)
match &node.kind {
BoundKind::DefLocal { .. } | BoundKind::Set { .. } | BoundKind::DefGlobal { .. } => {
let s_pad = self.pad(indent + 1);
self.logs.push(format!("{}--- Scope Status ---", s_pad));
self.logs.push(format!("{}Stack (top 5): {:?}", s_pad, vm.stack.iter().rev().take(5).collect::<Vec<_>>()));
},
_ => {}
}
let res_str = match res {
Ok(v) => format!("{}", v),
Err(e) => format!("ERROR: {}", e),
};
self.logs.push(format!("{}}} -> {}", pad, res_str));
}
}
pub struct VM {
stack: Vec<Value>,
globals: Rc<RefCell<Vec<Value>>>,
@@ -43,6 +98,10 @@ impl VM {
}
pub fn run(&mut self, root: &Node<BoundKind, StaticType>) -> Result<Value, String> {
self.run_with_observer(&mut NoOpObserver, root)
}
pub fn run_with_observer<O: VMObserver>(&mut self, observer: &mut O, root: &Node<BoundKind, StaticType>) -> Result<Value, String> {
self.stack.clear();
self.frames.clear();
@@ -52,19 +111,33 @@ impl VM {
closure: None,
});
let result = self.eval(root);
let result = self.eval(observer, 0, root);
self.frames.pop();
result
}
fn eval(&mut self, node: &Node<BoundKind, StaticType>) -> Result<Value, String> {
fn eval<O: VMObserver>(&mut self, observer: &mut O, indent: usize, node: &Node<BoundKind, StaticType>) -> Result<Value, String> {
if O::ACTIVE {
observer.before_eval(self, node, indent);
}
let result = self.eval_internal(observer, indent, node);
if O::ACTIVE {
observer.after_eval(self, node, &result, indent);
}
result
}
fn eval_internal<O: VMObserver>(&mut self, observer: &mut O, indent: usize, node: &Node<BoundKind, StaticType>) -> Result<Value, String> {
match &node.kind {
BoundKind::Nop => Ok(Value::Void),
BoundKind::Constant(v) => Ok(v.clone()),
BoundKind::DefGlobal { global_index, value } => {
let val = self.eval(value)?;
let val = self.eval(observer, indent + 1, value)?;
let idx = *global_index as usize;
let mut globals = self.globals.borrow_mut();
if idx >= globals.len() {
@@ -77,13 +150,13 @@ impl VM {
BoundKind::Get(addr) => self.get_value(*addr),
BoundKind::Set { addr, value } => {
let val = self.eval(value)?;
let val = self.eval(observer, indent + 1, value)?;
self.set_value(*addr, val.clone())?;
Ok(val)
},
BoundKind::DefLocal { slot, value, captured_by } => {
let val = self.eval(value)?;
let val = self.eval(observer, indent + 1, value)?;
let final_val = if !captured_by.is_empty() {
Value::Cell(Rc::new(RefCell::new(val)))
} else {
@@ -105,11 +178,11 @@ impl VM {
},
BoundKind::If { cond, then_br, else_br } => {
let c = self.eval(cond)?;
let c = self.eval(observer, indent + 1, cond)?;
if c.is_truthy() {
self.eval(then_br)
self.eval(observer, indent + 1, then_br)
} else if let Some(e) = else_br {
self.eval(e)
self.eval(observer, indent + 1, e)
} else {
Ok(Value::Void)
}
@@ -118,7 +191,7 @@ impl VM {
BoundKind::Block { exprs } => {
let mut last = Value::Void;
for e in exprs {
last = self.eval(e)?;
last = self.eval(observer, indent + 1, e)?;
}
Ok(last)
},
@@ -138,10 +211,10 @@ impl VM {
},
BoundKind::TailCall { callee, args } => {
let func_val = self.eval(callee)?;
let func_val = self.eval(observer, indent + 1, callee)?;
let mut arg_vals = Vec::with_capacity(args.len());
for arg in args {
arg_vals.push(self.eval(arg)?);
arg_vals.push(self.eval(observer, indent + 1, arg)?);
}
match func_val {
@@ -154,11 +227,11 @@ impl VM {
},
BoundKind::Call { callee, args } => {
let mut func_val = self.eval(callee)?;
let mut func_val = self.eval(observer, indent + 1, callee)?;
let mut arg_vals = Vec::with_capacity(args.len());
for arg in args {
arg_vals.push(self.eval(arg)?);
arg_vals.push(self.eval(observer, indent + 1, arg)?);
}
// Trampoline Loop
@@ -177,7 +250,7 @@ impl VM {
closure: Some(closure_rc.clone()),
});
let result = self.eval(&closure.function_node);
let result = self.eval(observer, indent + 1, &closure.function_node);
self.frames.pop();
self.stack.truncate(old_stack_top);
@@ -203,7 +276,7 @@ impl VM {
BoundKind::Tuple { elements } => {
let mut vals = Vec::with_capacity(elements.len());
for e in elements {
vals.push(self.eval(e)?);
vals.push(self.eval(observer, indent + 1, e)?);
}
Ok(Value::List(Rc::new(vals)))
},
@@ -211,8 +284,8 @@ impl VM {
BoundKind::Map { entries } => {
let mut map = HashMap::new();
for (k, v) in entries {
let key = self.eval(k)?;
let val = self.eval(v)?;
let key = self.eval(observer, indent + 1, k)?;
let val = self.eval(observer, indent + 1, v)?;
if let Value::Keyword(kw) = key {
map.insert(kw, val);
+27
View File
@@ -120,4 +120,31 @@ mod tests {
}
}
}
#[test]
fn test_debug_mode_logging() {
let env = Environment::new();
let source = "(+ 10 20)";
let result = env.run_debug(source).expect("Failed to run debug");
let (val, logs) = result;
// 1. Check value
match val {
Ok(Value::Int(30)) => (),
_ => panic!("Expected Int(30), got {:?}", val),
}
// 2. Check logs (should have entries for + and constants)
assert!(!logs.is_empty(), "Logs should not be empty");
// Look for typical trace patterns
let has_call = logs.iter().any(|l| l.contains("CALL"));
let has_const = logs.iter().any(|l| l.contains("CONST(10)"));
let has_result = logs.iter().any(|l| l.contains("} -> 30"));
assert!(has_call, "Logs should contain CALL");
assert!(has_const, "Logs should contain CONST(10)");
assert!(has_result, "Logs should contain result 30");
}
}