[move-vm][aptos-vm] Basic execution counters (#15086)

Cargo.toml

@@ -233,6 +233,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",
@@ -866,6 +867,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

@@ -107,6 +107,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},
@@ -1908,6 +1909,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);
 
@@ -1938,6 +1941,8 @@ impl AptosVM {
                 code_storage,
             ));
 
+        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,
@@ -1956,6 +1961,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
@@ -1996,6 +2005,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

@@ -21,6 +21,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,
@@ -110,6 +111,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,46 @@
+// Copyright (c) The Move Contributors
+// SPDX-License-Identifier: Apache-2.0
+
+use once_cell::sync::Lazy;
+use prometheus::{register_histogram_vec, HistogramTimer, HistogramVec};
+
+/// Helper trait to encapsulate [HistogramVec] functionality. Users can use this trait to time
+/// different VM parts collecting metrics for different labels. Use wisely as timers do introduce
+/// an overhead, so using on a hot path is not recommended.
+pub trait Timer {
+    /// Returns a new timer for the specified label.
+    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()
+    }
+}
+
+/// Timer that can be used to instrument the VM to collect metrics for different parts of the code.
+/// To access and view the metrics, set up where to send them, e.g., `PUSH_METRICS_NAMESPACE` and
+/// `PUSH_METRICS_ENDPOINT`. Then, metrics can be seen on Grafana dashboard, for instance.
+///
+/// Note: the timer uses "exponential" buckets with a factor of 2.
+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,
+    )
+    .expect("Registering the histogram should always succeed")
+});

third_party/move/move-vm/runtime/Cargo.toml

@@ -29,6 +29,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/loader/mod.rs

@@ -65,6 +65,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 use script::Script;
 pub(crate) use script::ScriptCache;
@@ -525,6 +526,8 @@ impl LoaderV1 {
         data_store: &mut TransactionDataCache,
         module_store: &LegacyModuleStorageAdapter,
     ) -> 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:
@@ -621,6 +624,8 @@ impl Loader {
         module_store: &LegacyModuleStorageAdapter,
         module_storage: &impl ModuleStorage,
     ) -> 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,
@@ -842,6 +847,8 @@ impl LoaderV1 {
         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.
@@ -911,6 +918,8 @@ impl LoaderV1 {
             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,
@@ -952,6 +961,9 @@ impl LoaderV1 {
 
         // 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,

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,
 };
@@ -289,6 +290,8 @@ impl Module {
         module: Arc<CompiledModule>,
         struct_name_index_map: &StructNameIndexMap,
     ) -> PartialVMResult<Self> {
+        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

@@ -25,6 +25,7 @@ use move_core_types::{
     account_address::AccountAddress, 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,
@@ -423,6 +424,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,
@@ -434,6 +436,7 @@ impl VMRuntime {
             extensions,
             &self.loader,
         )?;
+        drop(timer);
 
         let serialized_return_values = self
             .serialize_return_values(module_store, module_storage, &return_tys, return_values)