From 6acc3d5942d74fbf630354c1df5ff00db41a2743 Mon Sep 17 00:00:00 2001 From: igor-aptos <110557261+igor-aptos@users.noreply.github.com> Date: Tue, 19 Nov 2024 14:11:00 -0800 Subject: [PATCH] [short][move e2e bench] Add gas metrics and more existing transaction types (#15302) ## Description This allows for easier understanding of gas calibration. Looking at gas/s metrics (and execution and io breakdown) makes it easy to calibrate new constants. ## How Has This Been Tested? used to calibrate vector::move_range native --- .../aptos-gas-calibration/src/measurements.rs | 20 ++-- .../src/measurements_helpers.rs | 20 ++-- aptos-move/aptos-vm-benchmarks/src/helper.rs | 20 ++-- aptos-move/e2e-benchmark/src/main.rs | 96 +++++++++++-------- aptos-move/e2e-tests/src/executor.rs | 72 +++++++++++--- execution/executor-benchmark/src/lib.rs | 19 ++-- execution/executor-benchmark/src/main.rs | 6 +- 7 files changed, 164 insertions(+), 89 deletions(-) diff --git a/aptos-move/aptos-gas-calibration/src/measurements.rs b/aptos-move/aptos-gas-calibration/src/measurements.rs index fa0257ce29a0c..df62baca470cf 100644 --- a/aptos-move/aptos-gas-calibration/src/measurements.rs +++ b/aptos-move/aptos-gas-calibration/src/measurements.rs @@ -162,15 +162,17 @@ fn compile_and_run_samples_ir( .equation_names .push(format!("{}::{}", &identifier, func_identifier.0)); - let elapsed = executor.exec_func_record_running_time( - &module_id, - &func_identifier.0, - vec![], - func_identifier.1.clone(), - iterations, - ExecFuncTimerDynamicArgs::NoArgs, - GasMeterType::UnmeteredGasMeter, - ); + let elapsed = executor + .exec_func_record_running_time( + &module_id, + &func_identifier.0, + vec![], + func_identifier.1.clone(), + iterations, + ExecFuncTimerDynamicArgs::NoArgs, + GasMeterType::UnmeteredGasMeter, + ) + .elapsed_micros(); gas_measurement.regular_meter.push(elapsed); // record with abstract gas meter diff --git a/aptos-move/aptos-gas-calibration/src/measurements_helpers.rs b/aptos-move/aptos-gas-calibration/src/measurements_helpers.rs index 3f242b4457d4e..987cf91799d4a 100644 --- a/aptos-move/aptos-gas-calibration/src/measurements_helpers.rs +++ b/aptos-move/aptos-gas-calibration/src/measurements_helpers.rs @@ -94,15 +94,17 @@ pub fn execute_user_txn( iterations: u64, args: Vec>, ) -> u128 { - let elapsed = executor.exec_func_record_running_time( - module_name, - function_name, - vec![], - args, - iterations, - ExecFuncTimerDynamicArgs::NoArgs, - GasMeterType::UnmeteredGasMeter, - ); + let elapsed = executor + .exec_func_record_running_time( + module_name, + function_name, + vec![], + args, + iterations, + ExecFuncTimerDynamicArgs::NoArgs, + GasMeterType::UnmeteredGasMeter, + ) + .elapsed_micros(); println!("running time (microseconds): {}", elapsed); elapsed } diff --git a/aptos-move/aptos-vm-benchmarks/src/helper.rs b/aptos-move/aptos-vm-benchmarks/src/helper.rs index aea964f3e20e2..de4f8d8c06f6d 100644 --- a/aptos-move/aptos-vm-benchmarks/src/helper.rs +++ b/aptos-move/aptos-vm-benchmarks/src/helper.rs @@ -64,15 +64,17 @@ pub fn execute_module_txn( // sign user transaction and only records the body of the transaction pub fn execute_user_txn(executor: &mut FakeExecutor, module_name: &ModuleId, function_name: &str) { - let elapsed = executor.exec_func_record_running_time( - module_name, - function_name, - vec![], - vec![], - 10, - ExecFuncTimerDynamicArgs::NoArgs, - GasMeterType::UnmeteredGasMeter, - ); + let elapsed = executor + .exec_func_record_running_time( + module_name, + function_name, + vec![], + vec![], + 10, + ExecFuncTimerDynamicArgs::NoArgs, + GasMeterType::UnmeteredGasMeter, + ) + .elapsed_micros(); println!("running time (microseconds): {}", elapsed); } diff --git a/aptos-move/e2e-benchmark/src/main.rs b/aptos-move/e2e-benchmark/src/main.rs index 76e98fc61d63f..51b2d00e293fb 100644 --- a/aptos-move/e2e-benchmark/src/main.rs +++ b/aptos-move/e2e-benchmark/src/main.rs @@ -3,7 +3,7 @@ use aptos_language_e2e_tests::{ account::Account, - executor::{ExecFuncTimerDynamicArgs, FakeExecutor, GasMeterType}, + executor::{ExecFuncTimerDynamicArgs, FakeExecutor, GasMeterType, Measurement}, }; use aptos_transaction_generator_lib::{ publishing::{ @@ -46,7 +46,7 @@ fn execute_and_time_entry_point( publisher_address: &AccountAddress, executor: &mut FakeExecutor, iterations: u64, -) -> u128 { +) -> Measurement { let mut rng = StdRng::seed_from_u64(14); let entry_fun = entry_point .create_payload( @@ -77,9 +77,9 @@ fn execute_and_time_entry_point( ) } -const ALLOWED_REGRESSION: f32 = 0.15; -const ALLOWED_IMPROVEMENT: f32 = 0.15; -const ABSOLUTE_BUFFER_US: f32 = 2.0; +const ALLOWED_REGRESSION: f64 = 0.15; +const ALLOWED_IMPROVEMENT: f64 = 0.15; +const ABSOLUTE_BUFFER_US: f64 = 2.0; const CALIBRATION_VALUES: &str = " Loop { loop_count: Some(100000), loop_type: NoOp } 6 0.988 1.039 41212.4 @@ -88,9 +88,9 @@ CreateObjects { num_objects: 10, object_payload_size: 0 } 6 0.940 1.026 152.1 CreateObjects { num_objects: 10, object_payload_size: 10240 } 6 0.934 1.051 9731.3 CreateObjects { num_objects: 100, object_payload_size: 0 } 6 0.966 1.051 1458.3 CreateObjects { num_objects: 100, object_payload_size: 10240 } 6 0.969 1.077 11196.4 -InitializeVectorPicture { length: 40 } 6 0.973 1.066 75.0 -VectorPicture { length: 40 } 6 0.955 1.092 22.0 -VectorPictureRead { length: 40 } 6 0.952 1.047 21.0 +InitializeVectorPicture { length: 128 } 6 0.973 1.066 170.3 +VectorPicture { length: 128 } 6 0.955 1.092 46.2 +VectorPictureRead { length: 128 } 6 0.952 1.047 45.1 InitializeVectorPicture { length: 30720 } 6 0.969 1.071 27295.8 VectorPicture { length: 30720 } 6 0.957 1.066 6560.2 VectorPictureRead { length: 30720 } 6 0.948 1.053 6642.8 @@ -103,11 +103,16 @@ TokenV1MintAndTransferNFTSequential 6 0.991 1.067 543.7 TokenV2AmbassadorMint { numbered: true } 6 0.987 1.052 474.4 LiquidityPoolSwap { is_stable: true } 6 0.970 1.042 555.4 LiquidityPoolSwap { is_stable: false } 6 0.925 1.001 535.3 +CoinInitAndMint 6 0.925 1.001 197.1 +FungibleAssetMint 6 0.925 1.001 231.6 +IncGlobalMilestoneAggV2 { milestone_every: 1 } 6 0.925 1.001 33.3 +IncGlobalMilestoneAggV2 { milestone_every: 2 } 6 0.925 1.001 19.1 +EmitEvents { count: 1000 } 6 0.925 1.001 8493.7 "; struct CalibrationInfo { // count: usize, - expected_time: f32, + expected_time_micros: f64, } fn get_parsed_calibration_values() -> HashMap { @@ -118,7 +123,7 @@ fn get_parsed_calibration_values() -> HashMap { let parts = line.split('\t').collect::>(); (parts[0].to_string(), CalibrationInfo { // count: parts[1].parse().unwrap(), - expected_time: parts[parts.len() - 1].parse().unwrap(), + expected_time_micros: parts[parts.len() - 1].parse().unwrap(), }) }) .collect() @@ -146,7 +151,7 @@ fn main() { loop_type: LoopType::Arithmetic, }, // This is a cheap bcs (serializing vec), so not representative of what BCS native call should cost. - // (, EntryPoints::Loop { loop_count: Some(1000), loop_type: LoopType::BCS { len: 1024 }}), + // (, EntryPoints::Loop { loop_count: Some(1000), loop_type: LoopType::BcsToBytes { len: 1024 }}), EntryPoints::CreateObjects { num_objects: 10, object_payload_size: 0, @@ -163,9 +168,9 @@ fn main() { num_objects: 100, object_payload_size: 10 * 1024, }, - EntryPoints::InitializeVectorPicture { length: 40 }, - EntryPoints::VectorPicture { length: 40 }, - EntryPoints::VectorPictureRead { length: 40 }, + EntryPoints::InitializeVectorPicture { length: 128 }, + EntryPoints::VectorPicture { length: 128 }, + EntryPoints::VectorPictureRead { length: 128 }, EntryPoints::InitializeVectorPicture { length: 30 * 1024 }, EntryPoints::VectorPicture { length: 30 * 1024 }, EntryPoints::VectorPictureRead { length: 30 * 1024 }, @@ -188,22 +193,27 @@ fn main() { EntryPoints::TokenV2AmbassadorMint { numbered: true }, EntryPoints::LiquidityPoolSwap { is_stable: true }, EntryPoints::LiquidityPoolSwap { is_stable: false }, + EntryPoints::CoinInitAndMint, + EntryPoints::FungibleAssetMint, + EntryPoints::IncGlobalMilestoneAggV2 { milestone_every: 1 }, + EntryPoints::IncGlobalMilestoneAggV2 { milestone_every: 2 }, + EntryPoints::EmitEvents { count: 1000 }, ]; let mut failures = Vec::new(); let mut json_lines = Vec::new(); println!( - "{:>15} {:>15} {:>15} entry point", - "wall time (us)", "expected (us)", "diff(- is impr)" + "{:>13} {:>13} {:>13}{:>13} {:>13} {:>13} entry point", + "walltime(us)", "expected(us)", "dif(- is impr)", "gas/s", "exe gas", "io gas", ); for (index, entry_point) in entry_points.into_iter().enumerate() { let entry_point_name = format!("{:?}", entry_point); - let expected_time = calibration_values + let expected_time_micros = calibration_values .get(&entry_point_name) - .unwrap() - .expected_time; + .expect(&entry_point_name) + .expected_time_micros; let publisher = executor.new_account_at(AccountAddress::random()); let mut package_handler = PackageHandler::new(entry_point.package_name()); @@ -215,7 +225,6 @@ fn main() { 0, package.publish_transaction_payload(), ); - println!("Published package: {:?}", entry_point.package_name()); if let Some(init_entry_point) = entry_point.initialize_entry_point() { execute_txn( &mut executor, @@ -228,52 +237,59 @@ fn main() { Some(publisher.address()), ), ); - println!( - "Executed init entry point: {:?}", - entry_point.initialize_entry_point() - ); } - let elapsed_micros = execute_and_time_entry_point( + let measurement = execute_and_time_entry_point( &entry_point, &package, publisher.address(), &mut executor, - if expected_time > 10000.0 { + if expected_time_micros > 10000.0 { 6 - } else if expected_time > 1000.0 { + } else if expected_time_micros > 1000.0 { 10 } else { 100 }, ); - let diff = (elapsed_micros as f32 - expected_time) / expected_time * 100.0; + let elapsed_micros = measurement.elapsed_micros_f64(); + let diff = (elapsed_micros - expected_time_micros) / expected_time_micros * 100.0; + let execution_gas_units = measurement.execution_gas_units(); + let io_gas_units = measurement.io_gas_units(); + let gps = (execution_gas_units + io_gas_units) / measurement.elapsed_secs_f64(); println!( - "{:15} {:15.1} {:14.1}% {:?}", - elapsed_micros, expected_time, diff, entry_point + "{:13.1} {:13.1} {:12.1}% {:13.0} {:13.2} {:13.2} {:?}", + elapsed_micros, + expected_time_micros, + diff, + gps, + execution_gas_units, + io_gas_units, + entry_point ); json_lines.push(json!({ "grep": "grep_json_aptos_move_vm_perf", "transaction_type": entry_point_name, "wall_time_us": elapsed_micros, - "expected_wall_time_us": expected_time, + "gas_units_per_second": gps, + "execution_gas_units": execution_gas_units, + "io_gas_units": io_gas_units, + "expected_wall_time_us": expected_time_micros, "test_index": index, })); - if elapsed_micros as f32 - > expected_time as f32 * (1.0 + ALLOWED_REGRESSION) + ABSOLUTE_BUFFER_US - { + if elapsed_micros > expected_time_micros * (1.0 + ALLOWED_REGRESSION) + ABSOLUTE_BUFFER_US { failures.push(format!( - "Performance regression detected: {}us, expected: {}us, diff: {}%, for {:?}", - elapsed_micros, expected_time, diff, entry_point + "Performance regression detected: {:.1}us, expected: {:.1}us, diff: {}%, for {:?}", + elapsed_micros, expected_time_micros, diff, entry_point )); - } else if elapsed_micros as f32 + ABSOLUTE_BUFFER_US - < expected_time as f32 * (1.0 - ALLOWED_IMPROVEMENT) + } else if elapsed_micros + ABSOLUTE_BUFFER_US + < expected_time_micros * (1.0 - ALLOWED_IMPROVEMENT) { failures.push(format!( - "Performance improvement detected: {}us, expected {}us, diff: {}%, for {:?}. You need to adjust expected time!", - elapsed_micros, expected_time, diff, entry_point + "Performance improvement detected: {:.1}us, expected {:.1}us, diff: {}%, for {:?}. You need to adjust expected time!", + elapsed_micros, expected_time_micros, diff, entry_point )); } } diff --git a/aptos-move/e2e-tests/src/executor.rs b/aptos-move/e2e-tests/src/executor.rs index ab1d4b7839513..9c9023c9c4b7d 100644 --- a/aptos-move/e2e-tests/src/executor.rs +++ b/aptos-move/e2e-tests/src/executor.rs @@ -21,7 +21,7 @@ use aptos_block_executor::{ use aptos_crypto::HashValue; use aptos_framework::ReleaseBundle; use aptos_gas_algebra::DynamicExpression; -use aptos_gas_meter::{StandardGasAlgebra, StandardGasMeter}; +use aptos_gas_meter::{AptosGasMeter, GasAlgebra, StandardGasAlgebra, StandardGasMeter}; use aptos_gas_profiling::{GasProfiler, TransactionGasLog}; use aptos_keygen::KeyGen; use aptos_types::{ @@ -89,7 +89,7 @@ use std::{ path::{Path, PathBuf}, str::FromStr, sync::{Arc, Mutex}, - time::Instant, + time::{Duration, Instant}, }; static RNG_SEED: [u8; 32] = [9u8; 32]; @@ -144,6 +144,39 @@ pub enum GasMeterType { UnmeteredGasMeter, } +#[derive(Clone)] +pub struct Measurement { + elapsed: Duration, + /// In internal gas units + execution_gas: u64, + /// In internal gas units + io_gas: u64, +} + +const GAS_SCALING_FACTOR: f64 = 1_000_000.0; + +impl Measurement { + pub fn elapsed_micros(&self) -> u128 { + self.elapsed.as_micros() + } + + pub fn elapsed_secs_f64(&self) -> f64 { + self.elapsed.as_secs_f64() + } + + pub fn elapsed_micros_f64(&self) -> f64 { + self.elapsed.as_secs_f64() * 1_000_000.0 + } + + pub fn execution_gas_units(&self) -> f64 { + self.execution_gas as f64 / GAS_SCALING_FACTOR + } + + pub fn io_gas_units(&self) -> f64 { + self.io_gas as f64 / GAS_SCALING_FACTOR + } +} + pub enum ExecFuncTimerDynamicArgs { NoArgs, DistinctSigners, @@ -973,7 +1006,7 @@ impl FakeExecutor { iterations: u64, dynamic_args: ExecFuncTimerDynamicArgs, gas_meter_type: GasMeterType, - ) -> u128 { + ) -> Measurement { let mut extra_accounts = match &dynamic_args { ExecFuncTimerDynamicArgs::DistinctSigners | ExecFuncTimerDynamicArgs::DistinctSignersAndFixed(_) => (0..iterations) @@ -993,7 +1026,7 @@ impl FakeExecutor { // start measuring here to reduce measurement errors (i.e., the time taken to load vm, module, etc.) let mut i = 0; - let mut times = Vec::new(); + let mut measurements = Vec::new(); while i < iterations { let mut session = vm.new_session(&resolver, SessionId::void(), None); @@ -1062,24 +1095,41 @@ impl FakeExecutor { let elapsed = start.elapsed(); if let Err(err) = result { if !should_error { - println!("Shouldn't error, but ignoring for now... {}", err); + println!( + "Entry function under measurement failed with an error. Continuing, but measurements are probably not what is expected. Error: {}", + err + ); } } - times.push(elapsed.as_micros()); + measurements.push(Measurement { + elapsed, + execution_gas: regular + .as_ref() + .map_or(0, |gas| gas.algebra().execution_gas_used().into()), + io_gas: regular + .as_ref() + .map_or(0, |gas| gas.algebra().io_gas_used().into()), + }); i += 1; } // take median of all running time iterations as a more robust measurement - times.sort(); - let length = times.len(); + measurements.sort_by_key(|v| v.elapsed); + let length = measurements.len(); let mid = length / 2; - let mut running_time = times[mid]; + let mut measurement = measurements[mid].clone(); if length % 2 == 0 { - running_time = (times[mid - 1] + times[mid]) / 2; + measurement = Measurement { + elapsed: (measurements[mid - 1].elapsed + measurements[mid].elapsed) / 2, + execution_gas: (measurements[mid - 1].execution_gas + + measurements[mid].execution_gas) + / 2, + io_gas: (measurements[mid - 1].io_gas + measurements[mid].io_gas) / 2, + }; } - running_time + measurement } /// record abstract usage using a modified gas meter diff --git a/execution/executor-benchmark/src/lib.rs b/execution/executor-benchmark/src/lib.rs index 6f9683ad7e706..ef9b88e284c16 100644 --- a/execution/executor-benchmark/src/lib.rs +++ b/execution/executor-benchmark/src/lib.rs @@ -43,7 +43,7 @@ use aptos_transaction_generator_lib::{ create_txn_generator_creator, AlwaysApproveRootAccountHandle, TransactionGeneratorCreator, TransactionType::{self, CoinTransfer}, }; -use aptos_types::on_chain_config::Features; +use aptos_types::on_chain_config::{FeatureFlag, Features}; use aptos_vm::VMBlockExecutor; use db_reliable_submitter::DbReliableTransactionSubmitter; use metrics::TIMER; @@ -57,6 +57,12 @@ use std::{ }; use tokio::runtime::Runtime; +pub fn default_benchmark_features() -> Features { + let mut init_features = Features::default(); + init_features.disable(FeatureFlag::REMOVE_DETAILED_ERROR_FROM_HASH); + init_features +} + pub fn init_db_and_executor(config: &NodeConfig) -> (DbReaderWriter, BlockExecutor) where V: VMBlockExecutor, @@ -778,7 +784,7 @@ fn log_total_supply(db_reader: &Arc) { #[cfg(test)] mod tests { use crate::{ - db_generator::bootstrap_with_genesis, init_db_and_executor, + db_generator::bootstrap_with_genesis, default_benchmark_features, init_db_and_executor, native::native_config::NativeConfig, pipeline::PipelineConfig, transaction_executor::BENCHMARKS_BLOCK_EXECUTOR_ONCHAIN_CONFIG, transaction_generator::TransactionGenerator, BenchmarkWorkload, @@ -789,10 +795,7 @@ mod tests { use aptos_sdk::{transaction_builder::aptos_stdlib, types::LocalAccount}; use aptos_temppath::TempPath; use aptos_transaction_generator_lib::{args::TransactionTypeArg, WorkflowProgress}; - use aptos_types::{ - on_chain_config::{FeatureFlag, Features}, - transaction::Transaction, - }; + use aptos_types::{on_chain_config::FeatureFlag, transaction::Transaction}; use aptos_vm::{aptos_vm::AptosVMBlockExecutor, AptosVM, VMBlockExecutor}; use rand::thread_rng; use std::fs; @@ -805,7 +808,7 @@ mod tests { fs::create_dir_all(db_dir.as_ref()).unwrap(); - let mut init_features = Features::default(); + let mut init_features = default_benchmark_features(); init_features.enable(FeatureFlag::NEW_ACCOUNTS_DEFAULT_TO_FA_APT_STORE); init_features.enable(FeatureFlag::OPERATIONS_DEFAULT_TO_FA_APT_STORE); @@ -898,7 +901,7 @@ mod tests { println!("db_generator::create_db_with_accounts"); - let mut features = Features::default(); + let mut features = default_benchmark_features(); features.enable(FeatureFlag::NEW_ACCOUNTS_DEFAULT_TO_FA_APT_STORE); features.enable(FeatureFlag::OPERATIONS_DEFAULT_TO_FA_APT_STORE); diff --git a/execution/executor-benchmark/src/main.rs b/execution/executor-benchmark/src/main.rs index da9e054cdecb7..90e479caa932b 100644 --- a/execution/executor-benchmark/src/main.rs +++ b/execution/executor-benchmark/src/main.rs @@ -14,8 +14,8 @@ use aptos_config::config::{ EpochSnapshotPrunerConfig, LedgerPrunerConfig, PrunerConfig, StateMerklePrunerConfig, }; use aptos_executor_benchmark::{ - native::native_config::NativeConfig, native_executor::NativeExecutor, pipeline::PipelineConfig, - BenchmarkWorkload, + default_benchmark_features, native::native_config::NativeConfig, + native_executor::NativeExecutor, pipeline::PipelineConfig, BenchmarkWorkload, }; use aptos_executor_service::remote_executor_client; use aptos_experimental_ptx_executor::PtxBlockExecutor; @@ -413,7 +413,7 @@ fn get_init_features( "Enable and disable feature flags cannot overlap." ); - let mut init_features = Features::default(); + let mut init_features = default_benchmark_features(); for feature in enable_feature.iter() { init_features.enable(*feature); }