From faada16723919e19d9155295d917d6ef11cbfea0 Mon Sep 17 00:00:00 2001 From: Michael Schimmel Date: Wed, 18 Feb 2026 00:56:29 +0100 Subject: [PATCH] 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. --- src/ast/compiler/bound_nodes.rs | 23 ++++++- src/ast/environment.rs | 53 +++++++++++++--- src/ast/types.rs | 32 ++++++++++ src/ast/vm.rs | 107 +++++++++++++++++++++++++++----- src/integration_test.rs | 27 ++++++++ 5 files changed, 212 insertions(+), 30 deletions(-) diff --git a/src/ast/compiler/bound_nodes.rs b/src/ast/compiler/bound_nodes.rs index 67d796a..fbcd69c 100644 --- a/src/ast/compiler/bound_nodes.rs +++ b/src/ast/compiler/bound_nodes.rs @@ -70,7 +70,24 @@ pub enum BoundKind { Map { entries: Vec<(Node, Node)>, }, - - // 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()), + } + } } diff --git a/src/ast/environment.rs b/src/ast/environment.rs index 239e208..9a94b45 100644 --- a/src/ast/environment.rs +++ b/src/ast/environment.rs @@ -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>>, pub global_values: Rc>>, + 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 + '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 { + 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, Vec), 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)) } } diff --git a/src/ast/types.rs b/src/ast/types.rs index a4c44ec..436e8c8 100644 --- a/src/ast/types.rs +++ b/src/ast/types.rs @@ -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 { diff --git a/src/ast/vm.rs b/src/ast/vm.rs index f8729b0..04bcf60 100644 --- a/src/ast/vm.rs +++ b/src/ast/vm.rs @@ -27,6 +27,61 @@ struct CallFrame { closure: Option>, } +/// 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, _indent: usize) {} + fn after_eval(&mut self, _vm: &VM, _node: &Node, _res: &Result, _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, +} + +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, 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, res: &Result, 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::>())); + }, + _ => {} + } + + 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, globals: Rc>>, @@ -43,6 +98,10 @@ impl VM { } pub fn run(&mut self, root: &Node) -> Result { + self.run_with_observer(&mut NoOpObserver, root) + } + + pub fn run_with_observer(&mut self, observer: &mut O, root: &Node) -> Result { 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) -> Result { + fn eval(&mut self, observer: &mut O, indent: usize, node: &Node) -> Result { + 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(&mut self, observer: &mut O, indent: usize, node: &Node) -> Result { 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); diff --git a/src/integration_test.rs b/src/integration_test.rs index 1891b3a..8cf0d11 100644 --- a/src/integration_test.rs +++ b/src/integration_test.rs @@ -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"); + } }