Skip to content
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

VM 2 Tracing #20848

Open
wants to merge 2 commits into
base: tzakian/vm-rebase1
Choose a base branch
from
Open

VM 2 Tracing #20848

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
2b3ed25
Tracing added to new VM
cgswords Jan 8, 2025
c8c8d03
Add missing files
cgswords Jan 17, 2025
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
6 changes: 3 additions & 3 deletions external-crates/move/crates/move-cli/src/sandbox/commands/run.rs
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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>>,
Copy link
Contributor

@tzakian tzakian Feb 5, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

See comment lower down, but I kinda like the way this turned out at the entry points so I'd be in favor of keeping it as-is here.

}

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()
Copy link
Contributor

@tzakian tzakian Feb 5, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

I think this is a bug in the current tracer as well, but I think above you'll need to do something like

let err = gas_meter.charge_drop_frame(...).map_err(|e| ..);
profile_close_frame!( ...);
trace(..., err.as_ref().err());
err?;

Otherwise if the charge for the drop frame causes an OOG you wont see it in the trace.

);

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
Open in desktop
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;
Copy link
Contributor

Choose a reason for hiding this comment

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

Seems a weird place for this use (and the above one too). Move to top of the file?

Loading
Loading