Skip to content

Add Vm trace functionality and add trace to boa_wasm #3227

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 11 commits into
base: main
Choose a base branch
from
Open

Add Vm trace functionality and add trace to boa_wasm #3227

Show file tree
Hide file tree
Changes from 10 commits
Commits
Show all changes
11 commits
Select commit Hold shift + click to select a range
0baa009
Squash wasm-debugger to one commit
nekevss Dec 7, 2023
a1900c8
Post-rebase fmt
nekevss Dec 7, 2023
2ae0204
Clean up logic for clarity
nekevss Dec 7, 2023
e0e64d2
Review feedback
nekevss Dec 8, 2023
a07ba2a
Add tracer name and fix/clean some logic
nekevss Dec 8, 2023
8099c04
Fix TraceAction import
nekevss Dec 8, 2023
39f973e
cargo fmt all
nekevss Dec 8, 2023
ed1cf6c
Redesign for Vec<Box<dyn Tracer>>
nekevss Jan 19, 2024
b20bb5b
cargo fmt and clippy
nekevss Jan 20, 2024
1b95f81
cargo fmt
nekevss Feb 4, 2024
94045e1
Remove comment and fix duplicate main trace
nekevss Apr 20, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions Cargo.lock
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

42 changes: 40 additions & 2 deletions cli/src/debug/function.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,10 @@ use boa_engine::{
builtins::function::OrdinaryFunction,
js_string,
object::ObjectInitializer,
vm::flowgraph::{Direction, Graph},
vm::{
flowgraph::{Direction, Graph},
trace::{TraceAction, Tracer},
},
Context, JsArgs, JsNativeError, JsObject, JsResult, JsValue, NativeFunction,
};

Expand Down Expand Up @@ -121,6 +124,39 @@ fn bytecode(_: &JsValue, args: &[JsValue], _: &mut Context) -> JsResult<JsValue>
Ok(js_string!(code.to_string()).into())
}

// ==== Trace functionality ====

#[derive(Debug)]
struct FunctionTracer;

impl Tracer for FunctionTracer {
fn should_trace(&self, frame: &boa_engine::vm::CallFrame) -> TraceAction {
if frame.code_block().traceable() {
if frame.code_block().was_traced() {
return TraceAction::Block;
}
return TraceAction::BlockWithBytecode;
}
TraceAction::None
}

fn emit_bytecode_trace(&self, msg: &str) {
println!("{msg}");
}

fn emit_call_frame_entrance_trace(&self, msg: &str) {
println!("{msg}");
}

fn emit_call_frame_exit_trace(&self, msg: &str) {
println!("{msg}");
}

fn emit_instruction_trace(&self, msg: &str) {
println!("{msg}");
}
}

fn set_trace_flag_in_function_object(object: &JsObject, value: bool) -> JsResult<()> {
let Some(function) = object.downcast_ref::<OrdinaryFunction>() else {
return Err(JsNativeError::typ()
Expand All @@ -145,14 +181,15 @@ fn trace(_: &JsValue, args: &[JsValue], context: &mut Context) -> JsResult<JsVal

let arguments = args.get(2..).unwrap_or(&[]);

context.set_tracer_implementation(Box::new(FunctionTracer));
set_trace_flag_in_function_object(callable, true)?;
let result = callable.call(this, arguments, context);
set_trace_flag_in_function_object(callable, false)?;

result
}

fn traceable(_: &JsValue, args: &[JsValue], _: &mut Context) -> JsResult<JsValue> {
fn traceable(_: &JsValue, args: &[JsValue], context: &mut Context) -> JsResult<JsValue> {
let value = args.get_or_undefined(0);
let traceable = args.get_or_undefined(1).to_boolean();

Expand All @@ -162,6 +199,7 @@ fn traceable(_: &JsValue, args: &[JsValue], _: &mut Context) -> JsResult<JsValue
.into());
};

context.set_tracer_implementation(Box::new(FunctionTracer));
set_trace_flag_in_function_object(callable, traceable)?;

Ok(value.clone())
Expand Down
4 changes: 3 additions & 1 deletion cli/src/main.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -347,7 +347,9 @@ fn main() -> Result<(), io::Error> {
add_runtime(&mut context);

// Trace Output
context.set_trace(args.trace);
if args.trace {
context.init_trace();
}

if args.debug_object {
init_boa_debug_object(&mut context);
Expand Down
17 changes: 14 additions & 3 deletions core/engine/src/context/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,10 @@ pub use icu::IcuError;
use intrinsics::Intrinsics;

use crate::vm::RuntimeLimits;

#[cfg(feature = "trace")]
use crate::vm::trace;

use crate::{
builtins,
class::{Class, ClassBuilder},
Expand Down Expand Up @@ -445,11 +449,18 @@ impl Context {
&self.vm.realm
}

/// Set the value of trace on the context
#[cfg(feature = "trace")]
#[inline]
pub fn set_trace(&mut self, trace: bool) {
self.vm.trace = trace;
/// Initializes the default `Vm` trace from the context
pub fn init_trace(&mut self) {
self.vm.trace.activate_trace();
}

#[cfg(feature = "trace")]
/// Sets custom handling of trace messages.
pub fn set_tracer_implementation(&mut self, tracer: Box<dyn trace::Tracer>) {
// self.init_trace();
self.vm.trace.set_tracer(tracer);
}

/// Get optimizer options.
Expand Down
22 changes: 20 additions & 2 deletions core/engine/src/vm/code_block.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -69,7 +69,11 @@ bitflags! {

/// Trace instruction execution to `stdout`.
#[cfg(feature = "trace")]
const TRACEABLE = 0b1000_0000_0000_0000;
const TRACEABLE = 0b0100_0000_0000_0000;

/// Stores whether the `CodeBlock` been traced.
#[cfg(feature = "trace")]
const WAS_TRACED = 0b1000_0000_0000_0000;
}
}

Expand Down Expand Up @@ -194,7 +198,7 @@ impl CodeBlock {

/// Check if the function is traced.
#[cfg(feature = "trace")]
pub(crate) fn traceable(&self) -> bool {
pub fn traceable(&self) -> bool {
self.flags.get().contains(CodeBlockFlags::TRACEABLE)
}
/// Enable or disable instruction tracing to `stdout`.
Expand All @@ -206,6 +210,20 @@ impl CodeBlock {
self.flags.set(flags);
}

/// Returns whether the frame has been previously traced.
#[cfg(feature = "trace")]
pub fn was_traced(&self) -> bool {
self.flags.get().contains(CodeBlockFlags::WAS_TRACED)
}

/// Set the current frame as traced.
#[cfg(feature = "trace")]
pub fn set_frame_traced(&self, value: bool) {
let mut flags = self.flags.get();
flags.set(CodeBlockFlags::WAS_TRACED, value);
self.flags.set(flags);
}

/// Check if the function is a class constructor.
pub(crate) fn is_class_constructor(&self) -> bool {
self.flags
Expand Down
84 changes: 32 additions & 52 deletions core/engine/src/vm/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,17 +21,24 @@ mod code_block;
mod completion_record;
mod inline_cache;
mod opcode;
#[cfg(feature = "trace")]
pub mod trace;

mod runtime_limits;

#[cfg(feature = "flowgraph")]
pub mod flowgraph;

pub(crate) use inline_cache::InlineCache;

#[cfg(feature = "trace")]
use trace::VmTrace;

// TODO: see if this can be exposed on all features.
#[allow(unused_imports)]
pub(crate) use opcode::{Instruction, InstructionIterator, Opcode, VaryingOperandKind};
pub use runtime_limits::RuntimeLimits;

pub use {
call_frame::{CallFrame, GeneratorResumeKind},
code_block::CodeBlock,
Expand Down Expand Up @@ -76,7 +83,7 @@ pub struct Vm {
pub(crate) realm: Realm,

#[cfg(feature = "trace")]
pub(crate) trace: bool,
pub(crate) trace: VmTrace,
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A thought that I've had over the last day or so is whether it would be worthwhile redesigning so that the Trace is a trait on Vm.

struct Vm<T: ExecutionTrace=()> {
    ...
    trace: T
}

The only issue with this that I haven't totally thought through is that I'm not sure we'd be able to feature flag the fields (all though we could probably still feature flag the method calls)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the current design is fine. What would be the benefit of having it as a trait?

Copy link
Member Author

@nekevss nekevss Apr 19, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Mostly I'm not sure if I'm totally in love with the Vec<Box<dyn Tracer>> on VmTrace. It works and improves the current functionality, but I'm mostly just thinking whether there may be a bit of a better design 😕 That being said, I'm not sure a theoretically better design out weighs the functionality here.

Edit: Using a trait would allow the trace to be defined at compile time essentially.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Imo the Vec<Box<dyn Tracer>> is totally fine for this use case.

Using a trait would allow the trace to be defined at compile time essentially.

I'm not sure if that is a benefit. The upside would be reducing dynamic dispatch, but if you enable tracing, you probably do not care about that last bit of performance.
Being able to change the tracing at runtime also seems like a nice feature right?

Copy link
Member Author

@nekevss nekevss Apr 19, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is a nice feature! And you're right, if someone enables tracing then they are probably not concerned about performance. But if it's switched to a trait that doesn't mean that there couldn't be an implementation of the trait that can be updated at runtime. And if we were to update this to something without dynamic dispatching, then we even provide an impl of the trait that could be updated at runtime.

The primary difference would be that it would be a user deciding to use dynamic dispatching over Boa locking the user into using it.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would say the current implementation is good engough. If there are shortcomings we could change it. I would prefer that to adding a generic to the Vm struct. But if you think it is significantly better, go for it :)

Copy link
Member

@jedel1043 jedel1043 May 7, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I do think we could offer "combinators" for tracers. Instead of having Vec<Box<dyn Tracer>>, why not something like Box<dyn Tracer>, where we impl<T: Tracer, U: Tracer> Tracer for (T, U)?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

😕 Maybe.

There's probably a better option with how Tracer is defined too. I was playing around with a new design and have something like:

pub trait Tracer: std::fmt::Debug {
    fn trace_instruction(&self, ctx: &TraceDecisionCtx<'_>) -> InstructionTraceAction;
    fn trace_bytecode(&self, ctx: &TraceDecisionCtx<'_>) -> BytecodeTraceAction;
    fn emit(&self, event: &TraceEvent<'_>);
}

Where TraceEvent is something like:

pub enum TraceEvent<'a> {
    NewCallFrame(&'a NewFrameEvent<'a>),
    ExitCallFrame(&'a ExitFrameEvent<'a>),
    Instruction(&'a InstructionTrace),
    ByteCode(&'a BytecodeTraceEvent),
}

But that design still has VmTrace using a Vec.

}

/// Active runnable in the current vm context.
Expand Down Expand Up @@ -108,7 +115,7 @@ impl Vm {
native_active_function: None,
realm,
#[cfg(feature = "trace")]
trace: false,
trace: VmTrace::default(),
}
}

Expand Down Expand Up @@ -181,6 +188,9 @@ impl Vm {
}

self.frames.push(frame);

#[cfg(feature = "trace")]
self.trace.trace_call_frame(self);
}

pub(crate) fn push_frame_with_stack(
Expand All @@ -193,6 +203,9 @@ impl Vm {
self.push(function);

self.push_frame(frame);

#[cfg(feature = "trace")]
self.trace.trace_call_frame(self);
}

pub(crate) fn pop_frame(&mut self) -> Option<CallFrame> {
Expand Down Expand Up @@ -264,38 +277,6 @@ pub(crate) enum CompletionType {

#[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;

pub(crate) fn trace_call_frame(&self) {
let msg = if self.vm.frames.last().is_some() {
format!(
" Call Frame -- {} ",
self.vm.frame().code_block().name().to_std_string_escaped()
)
} else {
" VM Start ".to_string()
};

println!("{}", self.vm.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,
);
}

fn trace_execute_instruction<F>(&mut self, f: F) -> JsResult<CompletionType>
where
F: FnOnce(Opcode, &mut Context) -> JsResult<CompletionType>,
Expand Down Expand Up @@ -368,13 +349,12 @@ impl Context {
VaryingOperandKind::U32 => ".U32",
};

println!(
"{:<TIME_COLUMN_WIDTH$} {:<OPCODE_COLUMN_WIDTH$} {operands:<OPERAND_COLUMN_WIDTH$} {stack}",
format!("{}μs", duration.as_micros()),
format!("{}{varying_operand_kind}", 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.trace.trace_instruction(
duration.as_micros(),
varying_operand_kind,
opcode.as_str(),
&operands,
&stack,
);

result
Expand Down Expand Up @@ -417,7 +397,7 @@ impl Context {
}

#[cfg(feature = "trace")]
let result = if self.vm.trace || self.vm.frame().code_block.traceable() {
let result = if self.vm.trace.should_trace(self.vm.frame()) {
self.trace_execute_instruction(f)
} else {
self.execute_instruction(f)
Expand Down Expand Up @@ -445,6 +425,8 @@ impl Context {
}
self.vm.environments.truncate(env_fp);
self.vm.stack.truncate(fp);
#[cfg(feature = "trace")]
self.vm.trace.trace_frame_end(&self.vm, "Throw");
return ControlFlow::Break(CompletionRecord::Throw(err));
}

Expand All @@ -469,6 +451,9 @@ impl Context {
let fp = self.vm.frame().fp() as usize;
self.vm.stack.truncate(fp);

#[cfg(feature = "trace")]
self.vm.trace.trace_frame_end(&self.vm, "Return");

let result = self.vm.take_return_value();
if self.vm.frame().exit_early() {
return ControlFlow::Break(CompletionRecord::Normal(result));
Expand All @@ -480,6 +465,8 @@ impl Context {
CompletionType::Throw => {
let mut fp = self.vm.frame().fp();
let mut env_fp = self.vm.frame().env_fp;
#[cfg(feature = "trace")]
self.vm.trace.trace_frame_end(&self.vm, "Throw");
if self.vm.frame().exit_early() {
self.vm.environments.truncate(env_fp as usize);
self.vm.stack.truncate(fp as usize);
Expand Down Expand Up @@ -519,6 +506,9 @@ impl Context {
}
// Early return immediately.
CompletionType::Yield => {
#[cfg(feature = "trace")]
self.vm.trace.trace_frame_end(&self.vm, "Yield");

let result = self.vm.take_return_value();
if self.vm.frame().exit_early() {
return ControlFlow::Break(CompletionRecord::Return(result));
Expand All @@ -538,11 +528,6 @@ impl Context {
pub(crate) async fn run_async_with_budget(&mut self, budget: u32) -> CompletionRecord {
let _timer = Profiler::global().start_event("run_async_with_budget", "vm");

#[cfg(feature = "trace")]
if self.vm.trace {
self.trace_call_frame();
}

let mut runtime_budget: u32 = budget;

loop {
Expand All @@ -563,11 +548,6 @@ impl Context {
pub(crate) fn run(&mut self) -> CompletionRecord {
let _timer = Profiler::global().start_event("run", "vm");

#[cfg(feature = "trace")]
if self.vm.trace {
self.trace_call_frame();
}

loop {
match self.execute_one(Opcode::execute) {
ControlFlow::Continue(()) => {}
Expand Down
Loading