Add MVP of virtual machine tracer

Author: nekevss

core/engine/src/vm/mod.rs

@@ -18,6 +18,9 @@ use boa_gc::{Finalize, Gc, Trace, custom_trace};
 use shadow_stack::ShadowStack;
 use std::{future::Future, ops::ControlFlow, pin::Pin, task};
 
+#[cfg(feature = "trace")]
+pub use trace::{EmptyTracer, StdoutTracer, VirtualMachineTracer};
+
 #[cfg(feature = "trace")]
 use crate::sys::time::Instant;
 
@@ -53,6 +56,8 @@ pub(crate) mod opcode;
 pub(crate) mod shadow_stack;
 pub(crate) mod source_info;
 
+mod trace;
+
 #[cfg(feature = "flowgraph")]
 pub mod flowgraph;
 
@@ -98,6 +103,10 @@ pub struct Vm {
 
     #[cfg(feature = "trace")]
     pub(crate) trace: bool,
+
+    /// A tracer registered to emit VM events
+    #[cfg(feature = "trace")]
+    pub(crate) tracer: Box<dyn VirtualMachineTracer>,
 }
 
 /// The stack holds the [`JsValue`]s for the calling convention and registers.
@@ -334,6 +343,7 @@ impl Vm {
             shadow_stack: ShadowStack::default(),
             #[cfg(feature = "trace")]
             trace: false,
+            tracer: Box::new(EmptyTracer),
         }
     }
 
@@ -581,40 +591,35 @@ impl Vm {
     }
 }
 
-#[allow(clippy::print_stdout)]
 #[cfg(feature = "trace")]
 impl Context {
-    const COLUMN_WIDTH: usize = 26;
-    const TIME_COLUMN_WIDTH: usize = Self::COLUMN_WIDTH / 2;
-    const OPCODE_COLUMN_WIDTH: usize = Self::COLUMN_WIDTH;
-    const OPERAND_COLUMN_WIDTH: usize = Self::COLUMN_WIDTH;
-    const NUMBER_OF_COLUMNS: usize = 4;
+    /// Sets the `Vm` tracer to the provided `VirtualMachineTracer` implementation
+    pub fn set_virtual_machine_tracer(&mut self, tracer: Box<dyn VirtualMachineTracer>) {
+        self.vm.tracer = tracer;
+    }
 
     pub(crate) fn trace_call_frame(&self) {
+        use crate::vm::trace::{
+            CallFrameMessage, CallFrameName, ExecutionStartMessage, VirtualMachineEvent,
+        };
         let frame = self.vm.frame();
-        let msg = if self.vm.frames.is_empty() {
-            " VM Start ".to_string()
-        } else {
-            format!(
-                " Call Frame -- {} ",
-                frame.code_block().name().to_std_string_escaped()
-            )
+        let call_frame_message = CallFrameMessage {
+            bytecode: frame.code_block.to_string(),
         };
+        self.vm
+            .tracer
+            .emit_event(VirtualMachineEvent::CallFrameTrace(call_frame_message));
 
-        println!("{}", frame.code_block);
-        println!(
-            "{msg:-^width$}",
-            width = Self::COLUMN_WIDTH * Self::NUMBER_OF_COLUMNS - 10
-        );
-        println!(
-            "{:<TIME_COLUMN_WIDTH$} {:<OPCODE_COLUMN_WIDTH$} {:<OPERAND_COLUMN_WIDTH$} Stack\n",
-            "Time",
-            "Opcode",
-            "Operands",
-            TIME_COLUMN_WIDTH = Self::TIME_COLUMN_WIDTH,
-            OPCODE_COLUMN_WIDTH = Self::OPCODE_COLUMN_WIDTH,
-            OPERAND_COLUMN_WIDTH = Self::OPERAND_COLUMN_WIDTH,
-        );
+        let call_frame_name = if self.vm.frames.is_empty() {
+            CallFrameName::Global
+        } else {
+            CallFrameName::Name(frame.code_block().name().to_std_string_escaped())
+        };
+        self.vm
+            .tracer
+            .emit_event(VirtualMachineEvent::ExecutionStart(ExecutionStartMessage {
+                call_frame_name,
+            }));
     }
 
     fn trace_execute_instruction<F>(
@@ -625,6 +630,8 @@ impl Context {
     where
         F: FnOnce(&mut Context, Opcode) -> ControlFlow<CompletionRecord>,
     {
+        use crate::vm::trace::{OpcodeExecutionMessage, VirtualMachineEvent};
+
         let frame = self.vm.frame();
         let (instruction, _) = frame
             .code_block
@@ -647,7 +654,9 @@ impl Context {
             | Opcode::SuperCall
             | Opcode::SuperCallSpread
             | Opcode::SuperCallDerived => {
-                println!();
+                self.vm
+                    .tracer
+                    .emit_event(VirtualMachineEvent::ExecutionCallEvent);
             }
             _ => {}
         }
@@ -661,14 +670,16 @@ impl Context {
             .stack
             .display_trace(self.vm.frame(), self.vm.frames.len() - 1);
 
-        println!(
-            "{:<TIME_COLUMN_WIDTH$} {:<OPCODE_COLUMN_WIDTH$} {operands:<OPERAND_COLUMN_WIDTH$} {stack}",
-            format!("{}μs", duration.as_micros()),
-            format!("{}", opcode.as_str()),
-            TIME_COLUMN_WIDTH = Self::TIME_COLUMN_WIDTH,
-            OPCODE_COLUMN_WIDTH = Self::OPCODE_COLUMN_WIDTH,
-            OPERAND_COLUMN_WIDTH = Self::OPERAND_COLUMN_WIDTH,
-        );
+        self.vm
+            .tracer
+            .emit_event(VirtualMachineEvent::ExecutionTrace(
+                OpcodeExecutionMessage {
+                    opcode: opcode.as_str(),
+                    duration,
+                    operands,
+                    stack,
+                },
+            ));
 
         result
     }

core/engine/src/vm/trace.rs

@@ -0,0 +1,126 @@
+use std::time::Duration;
+
+/// The call frame name
+///
+/// This will have the name of the call frame provided or `Global` it's
+/// the global call frame.
+#[derive(Debug, Clone)]
+pub enum CallFrameName {
+    Global,
+    Name(String),
+}
+
+/// A message that is emitted at the beginning of execution
+#[derive(Debug, Clone)]
+pub struct ExecutionStartMessage {
+    pub call_frame_name: CallFrameName,
+}
+
+/// A message that emits details about a call frame
+#[derive(Debug, Clone)]
+pub struct CallFrameMessage {
+    pub bytecode: String,
+}
+
+/// A message that emits instruction execution details about a call frame
+#[derive(Debug, Clone)]
+pub struct OpcodeExecutionMessage {
+    pub opcode: &'static str,
+    pub duration: Duration,
+    pub operands: String,
+    pub stack: String,
+}
+
+/// The various events that are emitted from Boa's virtual machine.
+#[derive(Debug, Clone)]
+pub enum VirtualMachineEvent {
+    /// This event is the first event triggered.
+    ///
+    /// It emits information about the call frame.
+    CallFrameTrace(CallFrameMessage),
+    /// This event is triggered when the execution of a call frame is starting.
+    ExecutionStart(ExecutionStartMessage),
+    /// This event is triggered when executing an operation.
+    ///
+    /// It provides information about the opcode execution
+    ExecutionTrace(OpcodeExecutionMessage),
+    /// This event is triggered when a opcode that calls is reached.
+    ///
+    /// It signals that we about about to switch call frames.
+    ExecutionCallEvent,
+}
+
+/// A trait to define a tracer that plugs into Boa's `Vm`
+pub trait VirtualMachineTracer: std::fmt::Debug {
+    /// Emits `VirtualMachineEvent`s from the virtual machine during execution
+    fn emit_event(&self, _event: VirtualMachineEvent) {}
+}
+
+/// A default empty virtual machine tracer that drops events submitted to it.
+#[derive(Debug, Clone, Copy)]
+pub struct EmptyTracer;
+
+impl VirtualMachineTracer for EmptyTracer {}
+
+/// `StdoutTracer` is a `VirtualMachineTracer` implementation that prints the events
+/// to stdout in a specific format.
+#[derive(Debug, Clone, Copy)]
+pub struct StdoutTracer;
+
+impl StdoutTracer {
+    const COLUMN_WIDTH: usize = 26;
+    const TIME_COLUMN_WIDTH: usize = Self::COLUMN_WIDTH / 2;
+    const OPCODE_COLUMN_WIDTH: usize = Self::COLUMN_WIDTH;
+    const OPERAND_COLUMN_WIDTH: usize = Self::COLUMN_WIDTH;
+    const NUMBER_OF_COLUMNS: usize = 4;
+}
+
+#[allow(clippy::print_stdout)]
+impl VirtualMachineTracer for StdoutTracer {
+    fn emit_event(&self, event: VirtualMachineEvent) {
+        match event {
+            VirtualMachineEvent::ExecutionStart(start_message) => {
+                let msg = match start_message.call_frame_name {
+                    CallFrameName::Global => " VM Start ".to_string(),
+                    CallFrameName::Name(name) => {
+                        format!(" Call Frame -- {name} ")
+                    }
+                };
+
+                println!(
+                    "{msg:-^width$}",
+                    width = Self::COLUMN_WIDTH * Self::NUMBER_OF_COLUMNS - 10
+                );
+                println!(
+                    "{:<TIME_COLUMN_WIDTH$} {:<OPCODE_COLUMN_WIDTH$} {:<OPERAND_COLUMN_WIDTH$} Stack\n",
+                    "Time",
+                    "Opcode",
+                    "Operands",
+                    TIME_COLUMN_WIDTH = Self::TIME_COLUMN_WIDTH,
+                    OPCODE_COLUMN_WIDTH = Self::OPCODE_COLUMN_WIDTH,
+                    OPERAND_COLUMN_WIDTH = Self::OPERAND_COLUMN_WIDTH,
+                );
+            }
+            VirtualMachineEvent::ExecutionCallEvent => println!(),
+            VirtualMachineEvent::CallFrameTrace(call_frame_message) => {
+                println!("{}", call_frame_message.bytecode);
+            }
+            VirtualMachineEvent::ExecutionTrace(execution_messsage) => {
+                let OpcodeExecutionMessage {
+                    opcode,
+                    duration,
+                    operands,
+                    stack,
+                } = execution_messsage;
+
+                println!(
+                    "{:<TIME_COLUMN_WIDTH$} {opcode:<OPCODE_COLUMN_WIDTH$} {operands:<OPERAND_COLUMN_WIDTH$} {stack}",
+                    format!("{}μs", duration.as_micros()),
+                    TIME_COLUMN_WIDTH = Self::TIME_COLUMN_WIDTH,
+                    OPCODE_COLUMN_WIDTH = Self::OPCODE_COLUMN_WIDTH,
+                    OPERAND_COLUMN_WIDTH = Self::OPERAND_COLUMN_WIDTH,
+                );
+            }
+        }
+    }
+}