diff --git a/Cargo.lock b/Cargo.lock index c0e4c40a291f4..4e369f24da787 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4477,6 +4477,7 @@ dependencies = [ "move-binary-format", "move-core-types", "move-unit-test", + "move-vm-metrics", "move-vm-runtime", "move-vm-types", "num_cpus", @@ -11670,6 +11671,14 @@ dependencies = [ "tempfile", ] +[[package]] +name = "move-vm-metrics" +version = "0.1.0" +dependencies = [ + "once_cell", + "prometheus", +] + [[package]] name = "move-vm-paranoid-tests" version = "0.1.0" @@ -11696,6 +11705,7 @@ dependencies = [ "move-compiler", "move-core-types", "move-ir-compiler", + "move-vm-metrics", "move-vm-types", "once_cell", "parking_lot 0.12.1", diff --git a/Cargo.toml b/Cargo.toml index ef24ceb98c54c..35a6f8a91989b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -232,6 +232,7 @@ members = [ "third_party/move/move-prover/test-utils", "third_party/move/move-symbol-pool", "third_party/move/move-vm/integration-tests", + "third_party/move/move-vm/metrics", "third_party/move/move-vm/paranoid-tests", "third_party/move/move-vm/runtime", "third_party/move/move-vm/test-utils", @@ -848,6 +849,7 @@ move-transactional-test-runner = { path = "third_party/move/testing-infra/transa move-unit-test = { path = "third_party/move/tools/move-unit-test", features = [ "table-extension", ] } +move-vm-metrics = { path = "third_party/move/move-vm/metrics" } move-vm-runtime = { path = "third_party/move/move-vm/runtime" } move-vm-test-utils = { path = "third_party/move/move-vm/test-utils", features = [ "table-extension", diff --git a/aptos-move/aptos-vm/Cargo.toml b/aptos-move/aptos-vm/Cargo.toml index c2755c5530282..607f58a530ed0 100644 --- a/aptos-move/aptos-vm/Cargo.toml +++ b/aptos-move/aptos-vm/Cargo.toml @@ -49,6 +49,7 @@ hex = { workspace = true } move-binary-format = { workspace = true } move-core-types = { workspace = true } move-unit-test = { workspace = true, optional = true } +move-vm-metrics = { workspace = true } move-vm-runtime = { workspace = true } move-vm-types = { workspace = true } num_cpus = { workspace = true } diff --git a/aptos-move/aptos-vm/src/aptos_vm.rs b/aptos-move/aptos-vm/src/aptos_vm.rs index 0fd1831d88d6b..1f0942effb241 100644 --- a/aptos-move/aptos-vm/src/aptos_vm.rs +++ b/aptos-move/aptos-vm/src/aptos_vm.rs @@ -103,6 +103,7 @@ use move_core_types::{ value::{serialize_values, MoveTypeLayout, MoveValue}, vm_status::StatusType, }; +use move_vm_metrics::{Timer, VM_TIMER}; use move_vm_runtime::{ logging::expect_no_verification_errors, module_traversal::{TraversalContext, TraversalStorage}, @@ -1761,6 +1762,8 @@ impl AptosVM { gas_meter: &mut impl AptosGasMeter, log_context: &AdapterLogSchema, ) -> (VMStatus, VMOutput) { + let _timer = VM_TIMER.timer_with_label("AptosVM::execute_user_transaction_impl"); + let traversal_storage = TraversalStorage::new(); let mut traversal_context = TraversalContext::new(&traversal_storage); @@ -1792,6 +1795,8 @@ impl AptosVM { change_set_configs, )); + let account_init_for_sponsored_transaction_timer = + VM_TIMER.timer_with_label("AptosVM::account_init_for_sponsored_transaction"); let is_account_init_for_sponsored_transaction = unwrap_or_discard!( is_account_init_for_sponsored_transaction(&txn_data, self.features(), resolver) ); @@ -1805,6 +1810,10 @@ impl AptosVM { )) ); } + drop(account_init_for_sponsored_transaction_timer); + + let payload_timer = + VM_TIMER.timer_with_label("AptosVM::execute_user_transaction_impl [payload]"); // We keep track of whether any newly published modules are loaded into the Vm's loader // cache as part of executing transactions. This would allow us to decide whether the cache @@ -1843,6 +1852,7 @@ impl AptosVM { unwrap_or_discard!(Err(deprecated_module_bundle!())) }, }; + drop(payload_timer); let gas_usage = txn_data .max_gas_amount() diff --git a/aptos-move/aptos-vm/src/verifier/transaction_arg_validation.rs b/aptos-move/aptos-vm/src/verifier/transaction_arg_validation.rs index 2ee495c5b10a6..9fc0fe1ea69da 100644 --- a/aptos-move/aptos-vm/src/verifier/transaction_arg_validation.rs +++ b/aptos-move/aptos-vm/src/verifier/transaction_arg_validation.rs @@ -20,6 +20,7 @@ use move_core_types::{ value::MoveValue, vm_status::StatusCode, }; +use move_vm_metrics::{Timer, VM_TIMER}; use move_vm_runtime::{ module_traversal::{TraversalContext, TraversalStorage}, LoadedFunction, @@ -108,6 +109,8 @@ pub fn validate_combine_signer_and_txn_args( func: &LoadedFunction, are_struct_constructors_enabled: bool, ) -> Result>, VMStatus> { + let _timer = VM_TIMER.timer_with_label("AptosVM::validate_combine_signer_and_txn_args"); + // Entry function should not return. if !func.return_tys().is_empty() { return Err(VMStatus::error( diff --git a/third_party/move/move-vm/metrics/Cargo.toml b/third_party/move/move-vm/metrics/Cargo.toml new file mode 100644 index 0000000000000..fe0d169907333 --- /dev/null +++ b/third_party/move/move-vm/metrics/Cargo.toml @@ -0,0 +1,17 @@ +[package] +name = "move-vm-metrics" +description = "MoveVM metrics" +version = "0.1.0" + +# Workspace inherited keys +authors = { workspace = true } +edition = { workspace = true } +homepage = { workspace = true } +license = { workspace = true } +publish = { workspace = true } +repository = { workspace = true } +rust-version = { workspace = true } + +[dependencies] +once_cell = { workspace = true } +prometheus = { workspace = true } diff --git a/third_party/move/move-vm/metrics/src/lib.rs b/third_party/move/move-vm/metrics/src/lib.rs new file mode 100644 index 0000000000000..0ecb4ea4e2b33 --- /dev/null +++ b/third_party/move/move-vm/metrics/src/lib.rs @@ -0,0 +1,37 @@ +// Copyright (c) The Move Contributors +// SPDX-License-Identifier: Apache-2.0 + +use once_cell::sync::Lazy; +use prometheus::{register_histogram_vec, HistogramTimer, HistogramVec}; + +pub trait Timer { + fn timer_with_label(&self, label: &str) -> HistogramTimer; +} + +impl Timer for HistogramVec { + fn timer_with_label(&self, label: &str) -> HistogramTimer { + self.with_label_values(&[label]).start_timer() + } +} + +pub static VM_TIMER: Lazy = Lazy::new(|| { + let factor = 2.0; + let num_buckets = 32; + + let mut next = 1e-9; + let mut buckets = Vec::with_capacity(num_buckets); + for _ in 0..num_buckets { + buckets.push(next); + next *= factor; + } + + register_histogram_vec!( + // Metric name: + "vm_timer_seconds", + // Metric description: + "VM timers", + &["name"], + buckets, + ) + .unwrap() +}); diff --git a/third_party/move/move-vm/runtime/Cargo.toml b/third_party/move/move-vm/runtime/Cargo.toml index ca8cbecfee164..3bf828d4fb071 100644 --- a/third_party/move/move-vm/runtime/Cargo.toml +++ b/third_party/move/move-vm/runtime/Cargo.toml @@ -27,6 +27,7 @@ typed-arena = { workspace = true } move-bytecode-verifier = { path = "../../move-bytecode-verifier" } move-core-types = { path = "../../move-core/types" } +move-vm-metrics = { workspace = true } move-vm-types = { path = "../types" } [dev-dependencies] diff --git a/third_party/move/move-vm/runtime/src/data_cache.rs b/third_party/move/move-vm/runtime/src/data_cache.rs index c562de0594e80..537451058dd6d 100644 --- a/third_party/move/move-vm/runtime/src/data_cache.rs +++ b/third_party/move/move-vm/runtime/src/data_cache.rs @@ -22,6 +22,7 @@ use move_core_types::{ value::MoveTypeLayout, vm_status::StatusCode, }; +use move_vm_metrics::{Timer, VM_TIMER}; use move_vm_types::{ loaded_data::runtime_types::Type, resolver::MoveResolver, @@ -210,6 +211,9 @@ impl<'r> TransactionDataCache<'r> { let mut load_res = None; if !account_cache.data_map.contains_key(ty) { + let _timer = + VM_TIMER.timer_with_label("TransactionDataCache::load_resource [cache miss]"); + let ty_tag = match loader.type_to_type_tag(ty)? { TypeTag::Struct(s_tag) => s_tag, _ => diff --git a/third_party/move/move-vm/runtime/src/loader/mod.rs b/third_party/move/move-vm/runtime/src/loader/mod.rs index f785ec41b0c96..2c93e7a9e3850 100644 --- a/third_party/move/move-vm/runtime/src/loader/mod.rs +++ b/third_party/move/move-vm/runtime/src/loader/mod.rs @@ -58,6 +58,7 @@ use move_binary_format::file_format::{ StructVariantHandleIndex, StructVariantInstantiationIndex, VariantFieldHandleIndex, VariantFieldInstantiationIndex, VariantIndex, }; +use move_vm_metrics::{Timer, VM_TIMER}; use move_vm_types::loaded_data::runtime_types::{StructLayout, TypeBuilder}; pub(crate) use script::{Script, ScriptCache}; use type_loader::intern_type; @@ -357,6 +358,8 @@ impl Loader { data_store: &mut TransactionDataCache, module_store: &ModuleStorageAdapter, ) -> VMResult> { + let _timer = VM_TIMER.timer_with_label("Loader::deserialize_and_verify_script"); + let script = data_store.load_compiled_script_to_cache(script, hash_value)?; // Verification: @@ -546,6 +549,8 @@ impl Loader { data_store: &mut TransactionDataCache, module_store: &ModuleStorageAdapter, ) -> VMResult { + let _timer = VM_TIMER.timer_with_label("Loader::load_function"); + let (module, function) = self.load_function_without_type_args( module_id, function_name, @@ -781,6 +786,8 @@ impl Loader { I: IntoIterator, I::IntoIter: DoubleEndedIterator, { + let _timer = VM_TIMER.timer_with_label("Loader::check_dependencies_and_charge_gas"); + // Initialize the work list (stack) and the map of visited modules. // // TODO: Determine the reserved capacity based on the max number of dependencies allowed. @@ -850,6 +857,8 @@ impl Loader { return Ok(cached); } + let _timer = VM_TIMER.timer_with_label("Loader::load_module [cache miss]"); + // otherwise, load the transitive closure of the target module let module_ref = self.load_and_verify_module_and_dependencies_and_friends( id, @@ -893,6 +902,9 @@ impl Loader { // Verify the module if it hasn't been verified before. if VERIFIED_MODULES.lock().get(&hash_value).is_none() { + let _timer = VM_TIMER + .timer_with_label("Loader::load_and_verify_module [verification cache miss]"); + move_bytecode_verifier::verify_module_with_config( &self.vm_config.verifier_config, &module, @@ -2157,6 +2169,7 @@ impl Loader { } pub(crate) fn type_to_type_tag(&self, ty: &Type) -> PartialVMResult { + let _timer = VM_TIMER.timer_with_label("Loader::type_to_type_tag"); let mut gas_context = PseudoGasContext { cost: 0, max_cost: self.vm_config.type_max_cost, @@ -2171,6 +2184,8 @@ impl Loader { ty: &Type, module_store: &ModuleStorageAdapter, ) -> PartialVMResult<(MoveTypeLayout, bool)> { + let _timer = + VM_TIMER.timer_with_label("Loader::type_to_type_layout_with_identifier_mappings"); let mut count = 0; self.type_to_type_layout_impl(ty, module_store, &mut count, 1) } diff --git a/third_party/move/move-vm/runtime/src/loader/modules.rs b/third_party/move/move-vm/runtime/src/loader/modules.rs index 456d954935b4a..61f430859a194 100644 --- a/third_party/move/move-vm/runtime/src/loader/modules.rs +++ b/third_party/move/move-vm/runtime/src/loader/modules.rs @@ -28,6 +28,7 @@ use move_core_types::{ language_storage::ModuleId, vm_status::StatusCode, }; +use move_vm_metrics::{Timer, VM_TIMER}; use move_vm_types::loaded_data::runtime_types::{ StructIdentifier, StructLayout, StructNameIndex, StructType, Type, }; @@ -284,6 +285,8 @@ impl Module { cache: &ModuleStorageAdapter, name_cache: &StructNameCache, ) -> Result)> { + let _timer = VM_TIMER.timer_with_label("Module::new"); + let id = module.self_id(); let mut structs = vec![]; diff --git a/third_party/move/move-vm/runtime/src/runtime.rs b/third_party/move/move-vm/runtime/src/runtime.rs index b049568d8bfb6..20317edbaa650 100644 --- a/third_party/move/move-vm/runtime/src/runtime.rs +++ b/third_party/move/move-vm/runtime/src/runtime.rs @@ -23,6 +23,7 @@ use move_core_types::{ account_address::AccountAddress, identifier::Identifier, language_storage::TypeTag, value::MoveTypeLayout, vm_status::StatusCode, }; +use move_vm_metrics::{Timer, VM_TIMER}; use move_vm_types::{ gas::GasMeter, loaded_data::runtime_types::Type, @@ -400,6 +401,7 @@ impl VMRuntime { .collect::>>() .map_err(|err| err.finish(Location::Undefined))?; + let timer = VM_TIMER.timer_with_label("Interpreter::entrypoint"); let return_values = Interpreter::entrypoint( function, deserialized_args, @@ -410,6 +412,7 @@ impl VMRuntime { extensions, &self.loader, )?; + drop(timer); let serialized_return_values = self .serialize_return_values(module_store, &return_tys, return_values)