VM Trace output fixes #1035 (#1048)

* no more need for dbg!()
* pass -t or --trace for tracing output
* documentation on output

.vscode/tasks.json

@@ -26,7 +26,7 @@
       "type": "process",
       "label": "Cargo Run (VM)",
       "command": "cargo",
-      "args": ["run", "--features", "vm", "../tests/js/test.js"],
+      "args": ["run", "--features", "vm", "--", "-t", "../tests/js/test.js"],
       "group": {
         "kind": "build",
         "isDefault": true

boa/src/context.rs

@@ -233,6 +233,9 @@ pub struct Context {
 
     /// Cached standard objects and their prototypes.
     standard_objects: StandardObjects,
+
+    /// Whether or not to show trace of instructions being ran
+    pub trace: bool,
 }
 
 impl Default for Context {
@@ -249,6 +252,7 @@ impl Default for Context {
             well_known_symbols,
             iterator_prototypes: IteratorPrototypes::default(),
             standard_objects: Default::default(),
+            trace: false,
         };
 
         // Add new builtIns to Context Realm
@@ -754,7 +758,6 @@ impl Context {
 
         let mut compiler = Compiler::default();
         statement_list.compile(&mut compiler);
-        dbg!(&compiler);
 
         let mut vm = VM::new(compiler, self);
         // Generate Bytecode and place it into instruction_stack
@@ -794,4 +797,9 @@ impl Context {
     pub fn standard_objects(&self) -> &StandardObjects {
         &self.standard_objects
     }
+
+    /// Set the value of trace on the context
+    pub fn set_trace(&mut self, trace: bool) {
+        self.trace = trace;
+    }
 }

boa/src/vm/compilation.rs

@@ -2,17 +2,21 @@ use super::*;
 use crate::{syntax::ast::Const, syntax::ast::Node, value::RcBigInt, value::RcString};
 
 #[derive(Debug, Default)]
+/// The compiler struct holds all the instructions.
 pub struct Compiler {
+    /// Vector of instructions
     pub(super) instructions: Vec<Instruction>,
+    /// The pool stores constant data that can be indexed with the opcodes and pushed on the stack
     pub(super) pool: Vec<Value>,
 }
 
 impl Compiler {
-    // Add a new instruction.
+    /// Add a new instruction.
     pub fn add_instruction(&mut self, instr: Instruction) {
         self.instructions.push(instr);
     }
 
+    /// This specilaized method puts the string value in the pool then adds an instructions which points to the correct index
     pub fn add_string_instruction<S>(&mut self, string: S)
     where
         S: Into<RcString>,
@@ -22,6 +26,7 @@ impl Compiler {
         self.pool.push(string.into().into());
     }
 
+    /// This specilaized method puts the BigInt value in the pool then adds an instructions which points to the correct index
     pub fn add_bigint_instruction<B>(&mut self, bigint: B)
     where
         B: Into<RcBigInt>,

boa/src/vm/mod.rs

@@ -1,29 +1,53 @@
+//! The Virtual Machine (VM) handles generating instructions, then executing them.
+//! This module will provide an instruction set for the AST to use, various traits, plus an interpreter to execute those instructions
+
 use crate::{environment::lexical_environment::VariableScope, BoaProfiler, Context, Result, Value};
 
 pub(crate) mod compilation;
 pub(crate) mod instructions;
 
 pub use compilation::Compiler;
 pub use instructions::Instruction;
+use std::time::{Duration, Instant};
 
-// Virtual Machine.
+/// Virtual Machine.
 #[derive(Debug)]
 pub struct VM<'a> {
     ctx: &'a mut Context,
+    idx: usize,
     instructions: Vec<Instruction>,
     pool: Vec<Value>,
     stack: Vec<Value>,
     stack_pointer: usize,
+    profile: Profiler,
+    is_trace: bool,
+}
+/// This profiler is used to output trace information when `--trace` is provided by the CLI or trace is set to `true` on the [`VM`] object
+#[derive(Debug)]
+struct Profiler {
+    instant: Instant,
+    prev_time: Duration,
+    trace_string: String,
+    start_flag: bool,
 }
 
 impl<'a> VM<'a> {
     pub fn new(compiler: Compiler, ctx: &'a mut Context) -> Self {
+        let trace = ctx.trace;
         Self {
             ctx,
+            idx: 0,
             instructions: compiler.instructions,
             pool: compiler.pool,
             stack: vec![],
             stack_pointer: 0,
+            is_trace: trace,
+            profile: Profiler {
+                instant: Instant::now(),
+                prev_time: Duration::from_secs(0),
+                trace_string: String::new(), // Won't allocate if we don't use trace
+                start_flag: false,
+            },
         }
     }
 
@@ -45,12 +69,16 @@ impl<'a> VM<'a> {
 
     pub fn run(&mut self) -> Result<Value> {
         let _timer = BoaProfiler::global().start_event("runVM", "vm");
-        let mut idx = 0;
+        self.idx = 0;
+
+        while self.idx < self.instructions.len() {
+            if self.is_trace {
+                self.trace_print(false);
+            };
 
-        while idx < self.instructions.len() {
             let _timer =
-                BoaProfiler::global().start_event(&self.instructions[idx].to_string(), "vm");
-            match self.instructions[idx] {
+                BoaProfiler::global().start_event(&self.instructions[self.idx].to_string(), "vm");
+            match self.instructions[self.idx] {
                 Instruction::Undefined => self.push(Value::undefined()),
                 Instruction::Null => self.push(Value::null()),
                 Instruction::True => self.push(Value::boolean(true)),
@@ -307,10 +335,68 @@ impl<'a> VM<'a> {
                 }
             }
 
-            idx += 1;
+            self.idx += 1;
         }
 
+        if self.is_trace {
+            self.trace_print(true);
+        };
         let res = self.pop();
         Ok(res)
     }
+
+    pub fn trace_print(&mut self, end: bool) {
+        if self.profile.start_flag {
+            let duration = self.profile.instant.elapsed() - self.profile.prev_time;
+
+            if self.is_trace {
+                println!(
+                    "{0: <10} {1}",
+                    format!("{}μs", duration.as_micros()),
+                    self.profile.trace_string
+                );
+            }
+        } else {
+            let duration = self.profile.instant.elapsed() - self.profile.prev_time;
+            println!("VM start up time: {}μs", duration.as_micros());
+            println!(
+                "{0: <10} {1: <20} {2: <10}",
+                "Time", "Instr", "Top Of Stack"
+            );
+            println!();
+        }
+
+        self.profile.start_flag = true;
+
+        if self.is_trace {
+            self.profile.trace_string = format!(
+                "{0:<20}  {1}",
+                format!(
+                    "{:<20}",
+                    self.instructions[if end { self.idx - 1 } else { self.idx }]
+                ),
+                match self.stack.last() {
+                    None => "<empty>".to_string(),
+                    Some(val) => format!("{}\t{:p}", val.display(), val),
+                }
+            );
+        }
+
+        if end {
+            println!();
+            println!("Pool");
+            for (i, val) in self.pool.iter().enumerate() {
+                println!("{:<10} {:<10} {:p}", i, val.display(), val);
+            }
+
+            println!();
+            println!("Stack");
+            for (i, val) in self.stack.iter().enumerate() {
+                println!("{:<10} {:<10} {:p}", i, val.display(), val);
+            }
+            println!();
+        }
+
+        self.profile.prev_time = self.profile.instant.elapsed();
+    }
 }

boa_cli/src/main.rs

@@ -66,6 +66,11 @@ struct Opt {
     )]
     dump_ast: Option<Option<DumpFormat>>,
 
+    /// Dump the AST to stdout with the given format.
+    #[cfg(feature = "vm")]
+    #[structopt(long = "trace", short = "t")]
+    trace: bool,
+
     /// Use vi mode in the REPL
     #[structopt(long = "vi")]
     vi_mode: bool,
@@ -143,6 +148,10 @@ pub fn main() -> Result<(), std::io::Error> {
 
     let mut context = Context::new();
 
+    // Trace Output
+    #[cfg(feature = "vm")]
+    context.set_trace(args.trace);
+
     for file in &args.files {
         let buffer = read(file)?;
 

docs/debugging.md

@@ -94,3 +94,7 @@ rust-lldb ./target/debug/boa [arguments]
 
 [remote_containers]: https://marketplace.visualstudio.com/items?itemName=ms-vscode-remote.remote-containers
 [blog_debugging]: https://jason-williams.co.uk/debugging-rust-in-vscode
+
+## VM
+
+For debugging the new VM see [here](./vm.md)