Skip to content

Commit

Permalink
Tracing added to new VM
Browse files Browse the repository at this point in the history
  • Loading branch information
@cgswords
cgswords committed Jan 8, 2025
1 parent 5cba4a5 commit 2b3ed25
Show file tree
Hide file tree
Showing 12 changed files with 487 additions and 84 deletions.
6 changes: 3 additions & 3 deletions external-crates/move/crates/move-cli/src/sandbox/commands/run.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -66,12 +66,12 @@ pub fn run(
.map_err(|e| anyhow!("Error deserializing module: {:?}", e))?;
move_vm_profiler::tracing_feature_enabled! {
use move_vm_profiler::GasProfiler;
use move_vm_types::gas::GasMeter;
use move_vm_runtime::shared::gas::GasMeter;

let gas_rem: u64 = gas_status.remaining_gas().into();
gas_status.set_profiler(GasProfiler::init(
&session.vm_config().profiler_config,
function_name.to_owned(),
&runtime.vm_config().profiler_config,
function.to_owned(),
gas_rem,
));
}
Expand Down
11 changes: 7 additions & 4 deletions external-crates/move/crates/move-trace-format/src/format.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@
use crate::interface::{NopTracer, Tracer, Writer};
use move_binary_format::{
file_format::{Bytecode, FunctionDefinitionIndex as BinaryFunctionDefinitionIndex},
file_format_common::instruction_opcode,
file_format_common::{instruction_opcode, Opcodes},
};
use move_core_types::{
annotated_value::MoveValue,
Expand Down Expand Up @@ -282,20 +282,23 @@ impl MoveTraceBuilder {
}

/// Record an `Instruction` event in the trace along with the effects of the instruction.
pub fn instruction(
pub fn instruction<T: Into<Opcodes>>(
&mut self,
instruction: &Bytecode,
instruction: T,
type_parameters: Vec<TypeTag>,
effects: Vec<Effect>,
gas_left: u64,
pc: u16,
) {
let opcode: Opcodes = instruction.into();

self.push_event(TraceEvent::Instruction {
type_parameters,
pc,
gas_left,
instruction: Box::new(format!("{:?}", instruction_opcode(instruction))),
instruction: Box::new(format!("{:?}", opcode)),
});

for effect in effects {
self.push_event(TraceEvent::Effect(Box::new(effect)));
}
Expand Down
20 changes: 11 additions & 9 deletions external-crates/move/crates/move-unit-test/src/test_runner.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -288,7 +288,7 @@ impl SharedTestingConfig {
test_config: &SharedTestingConfig,
gas_meter: &mut impl GasMeter,
// TODO: Plumb tracing in
_tracer: Option<&mut MoveTraceBuilder>,
tracer: Option<&mut MoveTraceBuilder>,
module_id: ModuleId,
function_name: &str,
arguments: Vec<MoveValue>,
Expand All @@ -304,13 +304,15 @@ impl SharedTestingConfig {

let function_name = IdentStr::new(function_name).unwrap();

let serialized_return_values_result = vm_instance.execute_function_bypass_visibility(
&module_id,
function_name,
vec![], /* no ty args for now */
serialize_values(arguments.iter()),
gas_meter,
);
let serialized_return_values_result = vm_instance
.execute_function_bypass_visibility_with_tracer_if_enabled(
&module_id,
function_name,
vec![], /* no ty args for now */
serialize_values(arguments.iter()),
tracer,
gas_meter,
);
serialized_return_values_result.map(|res| {
(
res.return_values
Expand All @@ -332,7 +334,7 @@ impl SharedTestingConfig {
let mut gas_meter = GasStatus::new(&self.cost_table, Gas::new(self.execution_bound));
move_vm_profiler::tracing_feature_enabled! {
use move_vm_profiler::GasProfiler;
use move_vm_types::gas::GasMeter;
use move_vm_runtime::shared::gas::GasMeter;
gas_meter.set_profiler(GasProfiler::init_default_cfg(
function_name.to_owned(),
self.execution_bound,
Expand Down
96 changes: 88 additions & 8 deletions external-crates/move/crates/move-vm-runtime/src/execution/interpreter/eval.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ use crate::{
set_err_info,
state::{CallStack, MachineState, ResolvableType},
},
tracing::{trace, tracer::VMTracer},
values::{
IntegerValue, Reference, Struct, StructRef, VMValueCast, Value, Variant, VariantRef,
Vector, VectorRef,
Expand Down Expand Up @@ -43,13 +44,15 @@ enum StepStatus {
Done,
}

struct RunContext<'vm_cache, 'native, 'native_lifetimes> {
struct RunContext<'vm_cache, 'native, 'native_lifetimes, 'tracer, 'trace_builder> {
vtables: &'vm_cache VMDispatchTables,
vm_config: Arc<VMConfig>,
extensions: &'native mut NativeContextExtensions<'native_lifetimes>,
// TODO: consider making this `Option<&mut VMTracer<'_>>` and passing it like that everywhere?
tracer: &'tracer mut Option<VMTracer<'trace_builder>>,
}

impl RunContext<'_, '_, '_> {
impl RunContext<'_, '_, '_, '_, '_> {
// TODO: The Run Context should hold this, not go get it from the Loader.
fn vm_config(&self) -> &VMConfig {
&self.vm_config
Expand All @@ -66,12 +69,14 @@ pub(super) fn run(
vtables: &VMDispatchTables,
vm_config: Arc<VMConfig>,
extensions: &mut NativeContextExtensions,
tracer: &mut Option<VMTracer<'_>>,
gas_meter: &mut impl GasMeter,
) -> VMResult<Vec<Value>> {
let mut run_context = RunContext {
extensions,
vtables,
vm_config,
tracer,
};

let mut state = start_state;
Expand Down Expand Up @@ -137,6 +142,13 @@ fn step(
});

profile_open_instr!(gas_meter, format!("{:?}", instruction));
trace(run_context.tracer, |tracer| {
tracer.start_instruction(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
)
});
dbg_println!(flag: eval_step, "Instruction: {instruction:?}");
// These are split out because `PartialVMError` and `VMError` are different types. It's unclear
// why as they hold identical data, but if we could combine them, we could entirely inline
Expand All @@ -145,6 +157,14 @@ fn step(
Bytecode::Ret => {
let charge_result = gas_meter.charge_simple_instr(SimpleInstruction::Ret);
profile_close_instr!(gas_meter, format!("{:?}", instruction));
trace(run_context.tracer, |tracer| {
tracer.end_instruction(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
None,
)
});

partial_error_to_error(state, run_context, charge_result)?;
let non_ref_vals = state
Expand All @@ -161,9 +181,17 @@ fn step(

profile_close_frame!(
gas_meter,
arena::to_ref(current_frame.function).pretty_string()
state.call_stack.current_frame.function().pretty_string()
);

trace(run_context.tracer, |tracer| {
tracer.exit_frame(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
state.call_stack.current_frame.function(),
None,
)
});
if state.can_pop_call_frame() {
state.pop_call_frame()?;
// Note: the caller will find the callee's return values at the top of the shared operand stack
Expand All @@ -176,6 +204,14 @@ fn step(
}
Bytecode::CallGeneric(idx) => {
profile_close_instr!(gas_meter, format!("{:?}", instruction));
trace(run_context.tracer, |tracer| {
tracer.end_instruction(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
None,
)
});
let ty_args = state
.call_stack
.current_frame
Expand All @@ -194,6 +230,14 @@ fn step(
}
Bytecode::VirtualCall(vtable_key) => {
profile_close_instr!(gas_meter, format!("{:?}", instruction));
trace(run_context.tracer, |tracer| {
tracer.end_instruction(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
None,
)
});
let function = run_context
.vtables
.resolve_function(vtable_key)
Expand All @@ -203,11 +247,27 @@ fn step(
}
Bytecode::DirectCall(function) => {
profile_close_instr!(gas_meter, format!("{:?}", instruction));
trace(run_context.tracer, |tracer| {
tracer.end_instruction(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
None,
)
});
call_function(state, run_context, gas_meter, *function, vec![])?;
Ok(StepStatus::Running)
}
_ => {
let step_result = op_step_impl(state, run_context, gas_meter, instruction);
trace(run_context.tracer, |tracer| {
tracer.end_instruction(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
step_result.as_ref().err(),
)
});
partial_error_to_error(state, run_context, step_result)?;
Ok(StepStatus::Running)
}
Expand Down Expand Up @@ -883,7 +943,16 @@ fn call_function(
ty_args: Vec<Type>,
) -> VMResult<()> {
let fun_ref = function.to_ref();
profile_open_frame!(gas_meter, func_name.clone());
trace(run_context.tracer, |tracer| {
tracer.enter_frame(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
fun_ref,
&ty_args,
)
});
profile_open_frame!(gas_meter, fun_ref.name().to_string());

// Charge gas
let module_id = fun_ref.module_id();
Expand Down Expand Up @@ -918,11 +987,22 @@ fn call_function(
}

if fun_ref.is_native() {
call_native(state, run_context, gas_meter, fun_ref, ty_args)?;
let native_result = call_native(state, run_context, gas_meter, fun_ref, ty_args);

state.call_stack.current_frame.pc += 1; // advance past the Call instruction in the caller
// NB: Pass any error into the tracer before raising it.
trace(run_context.tracer, |tracer| {
tracer.exit_frame(
run_context.vtables,
state,
&gas_meter.remaining_gas().into(),
function.to_ref(),
native_result.as_ref().err(),
)
});

profile_close_frame!(gas_meter, func_name.clone());
native_result?;
state.call_stack.current_frame.pc += 1; // advance past the Call instruction in the caller
profile_close_frame!(gas_meter, fun_ref.name().to_string());
} else {
// Note: the caller will find the callee's return values at the top of the shared
// operand stack when the new frame returns.
Expand Down
32 changes: 23 additions & 9 deletions external-crates/move/crates/move-vm-runtime/src/execution/interpreter/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ use crate::{
execution::{
dispatch_tables::VMDispatchTables,
interpreter::state::{CallStack, MachineState, ModuleDefinitionResolver},
tracing::trace,
values::Value,
},
jit::execution::ast::{Function, Type},
Expand All @@ -23,19 +24,29 @@ pub(crate) mod state;
/// Entrypoint into the interpreter. All external calls need to be routed through this
/// function.
pub(crate) fn run(
function: VMPointer<Function>,
ty_args: Vec<Type>,
args: Vec<Value>,
vtables: &VMDispatchTables,
vm_config: Arc<VMConfig>,
extensions: &mut NativeContextExtensions,
tracer: &mut Option<VMTracer<'_>>,
gas_meter: &mut impl GasMeter,
function: VMPointer<Function>,
ty_args: Vec<Type>,
args: Vec<Value>,
) -> VMResult<Vec<Value>> {
let fun_ref = function.to_ref();
trace(tracer, |tracer| {
tracer.enter_initial_frame(
vtables,
&gas_meter.remaining_gas().into(),
function.ptr_clone().to_ref(),
&ty_args,
&args,
)
});
profile_open_frame!(gas_meter, fun_ref.pretty_string());

if fun_ref.is_native() {
let return_values = eval::call_native_with_args(
let return_result = eval::call_native_with_args(
None,
vtables,
gas_meter,
Expand All @@ -48,11 +59,12 @@ pub(crate) fn run(
.map_err(|e| {
e.at_code_offset(fun_ref.index(), 0)
.finish(Location::Module(fun_ref.module_id().clone()))
})?;

});
trace(tracer, |tracer| {
tracer.exit_initial_native_frame(&return_result, &gas_meter.remaining_gas().into())
});
profile_close_frame!(gas_meter, fun_ref.pretty_string());

Ok(return_values.into_iter().collect())
return_result.map(|values| values.into_iter().collect())
} else {
let module_id = function.to_ref().module_id();
let resolver = ModuleDefinitionResolver::new(vtables, module_id)
Expand All @@ -62,7 +74,7 @@ pub(crate) fn run(
.finish(Location::Module(fun_ref.module_id().clone()))
})?;
let state = MachineState::new(call_stack);
eval::run(state, vtables, vm_config, extensions, gas_meter)
eval::run(state, vtables, vm_config, extensions, tracer, gas_meter)
}
}

Expand All @@ -75,3 +87,5 @@ macro_rules! set_err_info {
}

pub(crate) use set_err_info;

use super::tracing::tracer::VMTracer;
Loading

0 comments on commit 2b3ed25

Please sign in to comment.