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,3 +1,6 @@
+//! 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;
@@ -5,25 +8,46 @@ 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");
+                BoaProfiler::global().start_event(&self.instructions[self.idx].to_string(), "vm");
-            match self.instructions[idx] {
+            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)

docs/vm.md

@@ -0,0 +1,83 @@
+# VM (Beta)
+
+## State Of Play
+
+By default Boa does not use the VM branch; execution is done via walking the AST. This allows us to work on the VM branch whilst not interrupting any progress made on AST execution.
+
+You can interpret bytecode by passing the "vm" flag (see below). The diagram below should illustrate how things work today (Jan 2021).
+
+![image](img/boa_architecture.svg)
+
+## Enabling ByteCode interpretation
+
+You need to enable this via a feature flag. If using VSCode you can run `Cargo Run (VM)`. If using the command line you can pass `cargo run --features vm ../tests/js/test.js` from within the boa_cli folder.
+
+## Understanding the output
+
+Once set up you should you can try some very simple javascript in your test file. For example:
+
+```js
+let a = 1;
+let b = 2;
+```
+
+Should output:
+
+```
+VM start up time: 0μs
+Time       Instr                Top Of Stack
+
+27μs       DefLet(0)             <empty>
+3μs        One                   <empty>
+35μs       InitLexical(0)        1      0x7f727f41d0c0
+18μs       DefLet(1)             1      0x7f727f41d0c0
+4μs        Int32(2)              1      0x7f727f41d0c0
+19μs       InitLexical(1)        2      0x7f727f41d0d8
+
+Pool
+0          "a" 0x7f727f41d120
+1          "b" 0x7f727f41d138
+
+Stack
+0          1 0x7f727f41d0c0
+1          2 0x7f727f41d0d8
+
+2
+```
+
+The above will output 3 sections: Instructions, pool and Stack. We can go through each one in detail:
+
+### Instruction
+
+This shows each instruction being executed and how long it took. This is useful for us to see if a particular instruction is taking too long.
+Then you have the instruction itself and its operand. Last you have what is on the top of the stack **before** the instruction is executed, followed by the memory address of that same value. We show the memory address to identify if 2 values are the same or different.
+
+### Pool
+
+JSValues can live on the pool, which acts as our heap. Instructions often have an index of where on the pool it refers to a value.
+You can use these values to match up with the instructions above. For e.g (using the above output) `DefLet(0)` means take the value off the pool at index `0`, which is `a` and define it in the current scope.
+
+### Stack
+
+The stack view shows what the stack looks like for the JS executed.
+Using the above output as an exmaple, after `One` has been executed the next instruction (`InitLexical(0)`) has a `1` on the top of the stack. This is because `One` puts `1` on the stack.
+
+### Comparing ByteCode output
+
+If you wanted another engine's bytecode output for the same JS, SpiderMonkey's bytecode output is the best to use. You can follow the setup [here](https://developer.mozilla.org/en-US/docs/Mozilla/Projects/SpiderMonkey/Introduction_to_the_JavaScript_shell). You will need to build from source because the pre-built binarys don't include the debugging utilities which we need.
+
+I named the binary `js_shell` as `js` conflicts with NodeJS. Once up and running you should be able to use `js_shell -f tests/js/test.js`. You will get no output to begin with, this is because you need to run `dis()` or `dis([func])` in the code. Once you've done that you should get some output like so:
+
+```
+loc     op
+-----   --
+00000:  GlobalOrEvalDeclInstantiation 0 #
+main:
+00005:  One                             # 1
+00006:  InitGLexical "a"                # 1
+00011:  Pop                             #
+00012:  Int8 2                          # 2
+00014:  InitGLexical "b"                # 2
+00019:  Pop                             #
+00020:  GetGName "dis"                  # dis
+```