[move] Basic execution counters

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",

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 }

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()

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<Vec<Vec<u8>>, 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(

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 }

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<HistogramVec> = 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()
+});

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]

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,
                 _ =>

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<Arc<CompiledScript>> {
+        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<LoadedFunction> {
+        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<Item = (&'a AccountAddress, &'a IdentStr)>,
         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<TypeTag> {
+        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)
     }

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<Self, (PartialVMError, Arc<CompiledModule>)> {
+        let _timer = VM_TIMER.timer_with_label("Module::new");
+
         let id = module.self_id();
 
         let mut structs = vec![];

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::<PartialVMResult<Vec<_>>>()
             .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)