diff --git a/Cargo.lock b/Cargo.lock index 29a03cd699..c10ea67e32 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -739,6 +739,16 @@ dependencies = [ "typenum", ] +[[package]] +name = "ctor" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "37e366bff8cd32dd8754b0991fb66b279dc48f598c3a18914852a6673deef583" +dependencies = [ + "quote", + "syn 2.0.48", +] + [[package]] name = "data-encoding" version = "2.5.0" @@ -2325,9 +2335,11 @@ dependencies = [ "ethers-core", "ethers-providers", "futures", + "hashbrown", "indicatif", "revm-interpreter", "revm-precompile", + "revm-utils", "serde", "serde_json", "tokio", @@ -2338,6 +2350,7 @@ name = "revm-interpreter" version = "3.0.0" dependencies = [ "revm-primitives", + "revm-utils", "serde", ] @@ -2373,6 +2386,7 @@ dependencies = [ "hashbrown", "hex", "once_cell", + "revm-utils", "serde", ] @@ -2390,6 +2404,17 @@ dependencies = [ "revm", ] +[[package]] +name = "revm-utils" +version = "0.1.0" +dependencies = [ + "allocator-api2", + "ctor", + "serde", + "serde_arrays", + "serde_json", +] + [[package]] name = "revme" version = "0.2.1" @@ -2728,6 +2753,15 @@ dependencies = [ "serde_derive", ] +[[package]] +name = "serde_arrays" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "38636132857f68ec3d5f3eb121166d2af33cb55174c4d5ff645db6165cbef0fd" +dependencies = [ + "serde", +] + [[package]] name = "serde_derive" version = "1.0.196" diff --git a/crates/interpreter/Cargo.toml b/crates/interpreter/Cargo.toml index afa42a6a4e..e1ce8fb0cd 100644 --- a/crates/interpreter/Cargo.toml +++ b/crates/interpreter/Cargo.toml @@ -21,6 +21,7 @@ serde = { version = "1.0", default-features = false, features = [ "derive", "rc", ], optional = true } +revm-utils = {path = "../utils", optional = true} [features] default = ["std"] @@ -55,3 +56,5 @@ optional_eip3607 = ["revm-primitives/optional_eip3607"] optional_gas_refund = ["revm-primitives/optional_gas_refund"] optional_no_base_fee = ["revm-primitives/optional_no_base_fee"] optional_beneficiary_reward = ["revm-primitives/optional_beneficiary_reward"] +enable_opcode_metrics = ["revm-utils"] +enable_cache_record = ["revm-primitives/enable_cache_record"] diff --git a/crates/interpreter/src/instructions/arithmetic.rs b/crates/interpreter/src/instructions/arithmetic.rs index 724f5ff9c3..b18205fdd1 100644 --- a/crates/interpreter/src/instructions/arithmetic.rs +++ b/crates/interpreter/src/instructions/arithmetic.rs @@ -67,7 +67,10 @@ pub fn mulmod(interpreter: &mut Interpreter, _host: &mut H) { pub fn exp(interpreter: &mut Interpreter, _host: &mut H) { pop_top!(interpreter, op1, op2); - gas_or_fail!(interpreter, gas::exp_cost::(*op2)); + let cost = gas::exp_cost::(*op2); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::EXP, cost.unwrap_or(0)); *op2 = op1.pow(*op2); } diff --git a/crates/interpreter/src/instructions/host.rs b/crates/interpreter/src/instructions/host.rs index 4919b644a6..c1efb60f71 100644 --- a/crates/interpreter/src/instructions/host.rs +++ b/crates/interpreter/src/instructions/host.rs @@ -19,17 +19,17 @@ pub fn balance(interpreter: &mut Interpreter, host: &mut H) interpreter.instruction_result = InstructionResult::FatalExternalError; return; }; - gas!( - interpreter, - if SPEC::enabled(ISTANBUL) { - // EIP-1884: Repricing for trie-size-dependent opcodes - gas::account_access_gas::(is_cold) - } else if SPEC::enabled(TANGERINE) { - 400 - } else { - 20 - } - ); + let cost = if SPEC::enabled(ISTANBUL) { + // EIP-1884: Repricing for trie-size-dependent opcodes + gas::account_access_gas::(is_cold) + } else if SPEC::enabled(TANGERINE) { + 400 + } else { + 20 + }; + gas!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::BALANCE, cost); push!(interpreter, balance); } @@ -50,21 +50,20 @@ pub fn extcodesize(interpreter: &mut Interpreter, host: &mu interpreter.instruction_result = InstructionResult::FatalExternalError; return; }; - if SPEC::enabled(BERLIN) { - gas!( - interpreter, - if is_cold { - COLD_ACCOUNT_ACCESS_COST - } else { - WARM_STORAGE_READ_COST - } - ); + let cost = if SPEC::enabled(BERLIN) { + if is_cold { + COLD_ACCOUNT_ACCESS_COST + } else { + WARM_STORAGE_READ_COST + } } else if SPEC::enabled(TANGERINE) { - gas!(interpreter, 700); + 700 } else { - gas!(interpreter, 20); - } - + 20 + }; + gas!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::EXTCODESIZE, cost); push!(interpreter, U256::from(code.len())); } @@ -76,20 +75,20 @@ pub fn extcodehash(interpreter: &mut Interpreter, host: &mu interpreter.instruction_result = InstructionResult::FatalExternalError; return; }; - if SPEC::enabled(BERLIN) { - gas!( - interpreter, - if is_cold { - COLD_ACCOUNT_ACCESS_COST - } else { - WARM_STORAGE_READ_COST - } - ); + let cost = if SPEC::enabled(BERLIN) { + if is_cold { + COLD_ACCOUNT_ACCESS_COST + } else { + WARM_STORAGE_READ_COST + } } else if SPEC::enabled(ISTANBUL) { - gas!(interpreter, 700); + 700 } else { - gas!(interpreter, 400); - } + 400 + }; + gas!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::EXTCODEHASH, cost); push_b256!(interpreter, code_hash); } @@ -103,10 +102,10 @@ pub fn extcodecopy(interpreter: &mut Interpreter, host: &mu }; let len = as_usize_or_fail!(interpreter, len_u256); - gas_or_fail!( - interpreter, - gas::extcodecopy_cost::(len as u64, is_cold) - ); + let cost = gas::extcodecopy_cost::(len as u64, is_cold); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::EXTCODECOPY, cost.unwrap_or(0)); if len == 0 { return; } @@ -146,7 +145,10 @@ pub fn sload(interpreter: &mut Interpreter, host: &mut H) { interpreter.instruction_result = InstructionResult::FatalExternalError; return; }; - gas!(interpreter, gas::sload_cost::(is_cold)); + let cost = gas::sload_cost::(is_cold); + gas!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::SLOAD, cost); push!(interpreter, value); } @@ -160,10 +162,13 @@ pub fn sstore(interpreter: &mut Interpreter, host: &mut H) interpreter.instruction_result = InstructionResult::FatalExternalError; return; }; - gas_or_fail!(interpreter, { + let cost = { let remaining_gas = interpreter.gas.remaining(); gas::sstore_cost::(original, old, new, remaining_gas, is_cold) - }); + }; + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::SSTORE, cost.unwrap_or(0)); refund!(interpreter, gas::sstore_refund::(original, old, new)); } @@ -195,7 +200,22 @@ pub fn log(interpreter: &mut Interpreter, host: &mut H) pop!(interpreter, offset, len); let len = as_usize_or_fail!(interpreter, len); - gas_or_fail!(interpreter, gas::log_cost(N as u8, len as u64)); + let cost = gas::log_cost(N as u8, len as u64); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + { + use crate::opcode::*; + let opcode = match N { + 0 => LOG0, + 1 => LOG1, + 2 => LOG2, + 3 => LOG3, + 4 => LOG4, + _ => unreachable!(), + }; + revm_utils::metrics::record_gas(opcode, cost.unwrap_or(0)); + } + let data = if len == 0 { Bytes::new() } else { @@ -236,7 +256,10 @@ pub fn selfdestruct(interpreter: &mut Interpreter, host: &m if !SPEC::enabled(LONDON) && !res.previously_destroyed { refund!(interpreter, gas::SELFDESTRUCT) } - gas!(interpreter, gas::selfdestruct_cost::(res)); + let cost = gas::selfdestruct_cost::(res); + gas!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::SELFDESTRUCT, cost); interpreter.instruction_result = InstructionResult::SelfDestruct; } @@ -248,9 +271,12 @@ pub fn create( check_staticcall!(interpreter); // EIP-1014: Skinny CREATE2 - if IS_CREATE2 { + let _opcode: u8 = if IS_CREATE2 { check!(interpreter, PETERSBURG); - } + crate::opcode::CREATE2 + } else { + crate::opcode::CREATE + }; pop!(interpreter, value, code_offset, len); let len = as_usize_or_fail!(interpreter, len); @@ -270,7 +296,10 @@ pub fn create( interpreter.instruction_result = InstructionResult::CreateInitCodeSizeLimit; return; } - gas!(interpreter, gas::initcode_cost(len as u64)); + let cost = gas::initcode_cost(len as u64); + gas!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(_opcode, cost); } let code_offset = as_usize_or_fail!(interpreter, code_offset); @@ -281,10 +310,15 @@ pub fn create( // EIP-1014: Skinny CREATE2 let scheme = if IS_CREATE2 { pop!(interpreter, salt); - gas_or_fail!(interpreter, gas::create2_cost(len)); + let cost = gas::create2_cost(len); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(_opcode, cost.unwrap_or(0)); CreateScheme::Create2 { salt } } else { gas!(interpreter, gas::CREATE); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(_opcode, gas::CREATE); CreateScheme::Create }; @@ -296,6 +330,8 @@ pub fn create( gas_limit -= gas_limit / 64 } gas!(interpreter, gas_limit); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(_opcode, gas_limit); // Call host to interact with target contract interpreter.next_action = InterpreterAction::Create { @@ -334,11 +370,14 @@ pub fn call(interpreter: &mut Interpreter, host: &mut H) { local_gas_limit, true, true, + crate::opcode::CALL, ) else { return; }; gas!(interpreter, gas_limit); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::CALL, gas_limit); // add call stipend if there is value to be transferred. if value != U256::ZERO { @@ -389,11 +428,14 @@ pub fn call_code(interpreter: &mut Interpreter, host: &mut local_gas_limit, true, false, + crate::opcode::CALLCODE, ) else { return; }; gas!(interpreter, gas_limit); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::CALLCODE, gas_limit); // add call stipend if there is value to be transferred. if value != U256::ZERO { @@ -436,13 +478,22 @@ pub fn delegate_call(interpreter: &mut Interpreter, host: & return; }; - let Some(gas_limit) = - calc_call_gas::(interpreter, host, to, false, local_gas_limit, false, false) - else { + let Some(gas_limit) = calc_call_gas::( + interpreter, + host, + to, + false, + local_gas_limit, + false, + false, + crate::opcode::DELEGATECALL, + ) else { return; }; gas!(interpreter, gas_limit); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::DELEGATECALL, gas_limit); // Call host to interact with target contract interpreter.next_action = InterpreterAction::Call { @@ -483,12 +534,21 @@ pub fn static_call(interpreter: &mut Interpreter, host: &mu return; }; - let Some(gas_limit) = - calc_call_gas::(interpreter, host, to, false, local_gas_limit, false, true) - else { + let Some(gas_limit) = calc_call_gas::( + interpreter, + host, + to, + false, + local_gas_limit, + false, + true, + crate::opcode::STATICCALL, + ) else { return; }; gas!(interpreter, gas_limit); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::STATICCALL, gas_limit); // Call host to interact with target contract interpreter.next_action = InterpreterAction::Call { diff --git a/crates/interpreter/src/instructions/host/call_helpers.rs b/crates/interpreter/src/instructions/host/call_helpers.rs index fc9509c25d..97992f26f8 100644 --- a/crates/interpreter/src/instructions/host/call_helpers.rs +++ b/crates/interpreter/src/instructions/host/call_helpers.rs @@ -42,6 +42,7 @@ pub fn calc_call_gas( local_gas_limit: u64, is_call_or_callcode: bool, is_call_or_staticcall: bool, + _opcode: u8, ) -> Option { let Some((is_cold, exist)) = host.load_account(to) else { interpreter.instruction_result = InstructionResult::FatalExternalError; @@ -58,6 +59,8 @@ pub fn calc_call_gas( ); gas!(interpreter, call_cost, None); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(_opcode, call_cost); // EIP-150: Gas cost changes for IO-heavy operations let gas_limit = if SPEC::enabled(TANGERINE) { diff --git a/crates/interpreter/src/instructions/memory.rs b/crates/interpreter/src/instructions/memory.rs index 6a63eb6b03..21f38aaa97 100644 --- a/crates/interpreter/src/instructions/memory.rs +++ b/crates/interpreter/src/instructions/memory.rs @@ -42,7 +42,10 @@ pub fn mcopy(interpreter: &mut Interpreter, _host: &mut H) // into usize or fail let len = as_usize_or_fail!(interpreter, len); // deduce gas - gas_or_fail!(interpreter, gas::verylowcopy_cost(len as u64)); + let cost = gas::verylowcopy_cost(len as u64); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::MCOPY, cost.unwrap_or(0)); if len == 0 { return; } diff --git a/crates/interpreter/src/instructions/system.rs b/crates/interpreter/src/instructions/system.rs index 07df7a6604..d66e47914c 100644 --- a/crates/interpreter/src/instructions/system.rs +++ b/crates/interpreter/src/instructions/system.rs @@ -7,7 +7,10 @@ use crate::{ pub fn keccak256(interpreter: &mut Interpreter, _host: &mut H) { pop!(interpreter, from, len); let len = as_usize_or_fail!(interpreter, len); - gas_or_fail!(interpreter, gas::keccak256_cost(len as u64)); + let cost = gas::keccak256_cost(len as u64); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::KECCAK256, cost.unwrap_or(0)); let hash = if len == 0 { KECCAK_EMPTY } else { @@ -37,7 +40,10 @@ pub fn codesize(interpreter: &mut Interpreter, _host: &mut H) { pub fn codecopy(interpreter: &mut Interpreter, _host: &mut H) { pop!(interpreter, memory_offset, code_offset, len); let len = as_usize_or_fail!(interpreter, len); - gas_or_fail!(interpreter, gas::verylowcopy_cost(len as u64)); + let cost = gas::verylowcopy_cost(len as u64); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::CODECOPY, cost.unwrap_or(0)); if len == 0 { return; } @@ -83,7 +89,10 @@ pub fn callvalue(interpreter: &mut Interpreter, _host: &mut H) { pub fn calldatacopy(interpreter: &mut Interpreter, _host: &mut H) { pop!(interpreter, memory_offset, data_offset, len); let len = as_usize_or_fail!(interpreter, len); - gas_or_fail!(interpreter, gas::verylowcopy_cost(len as u64)); + let cost = gas::verylowcopy_cost(len as u64); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::CALLDATACOPY, cost.unwrap_or(0)); if len == 0 { return; } @@ -115,7 +124,10 @@ pub fn returndatacopy(interpreter: &mut Interpreter, _host: check!(interpreter, BYZANTIUM); pop!(interpreter, memory_offset, offset, len); let len = as_usize_or_fail!(interpreter, len); - gas_or_fail!(interpreter, gas::verylowcopy_cost(len as u64)); + let cost = gas::verylowcopy_cost(len as u64); + gas_or_fail!(interpreter, cost); + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::record_gas(crate::opcode::RETURNDATACOPY, cost.unwrap_or(0)); let data_offset = as_usize_saturated!(offset); let (data_end, overflow) = data_offset.overflowing_add(len); if overflow || data_end > interpreter.return_data_buffer.len() { diff --git a/crates/interpreter/src/interpreter.rs b/crates/interpreter/src/interpreter.rs index 4cddf3ca6d..3094f5c9d0 100644 --- a/crates/interpreter/src/interpreter.rs +++ b/crates/interpreter/src/interpreter.rs @@ -288,6 +288,8 @@ impl Interpreter { { // Get current opcode. let opcode = unsafe { *self.instruction_pointer }; + #[cfg(feature = "enable_opcode_metrics")] + let _opcode = revm_utils::metrics::OpcodeExecuteRecord::new(opcode); // SAFETY: In analysis we are doing padding of bytecode so that we are sure that last // byte instruction is STOP so we are safe to just increment program_counter bcs on last instruction @@ -295,7 +297,7 @@ impl Interpreter { self.instruction_pointer = unsafe { self.instruction_pointer.offset(1) }; // execute instruction. - (instruction_table[opcode as usize])(self, host) + (instruction_table[opcode as usize])(self, host); } /// Take memory and replace it with empty memory. @@ -317,6 +319,8 @@ impl Interpreter { self.instruction_result = InstructionResult::Continue; self.shared_memory = shared_memory; // main loop + #[cfg(feature = "enable_opcode_metrics")] + revm_utils::metrics::start_record_op(); while self.instruction_result == InstructionResult::Continue { self.step(instruction_table, host); } diff --git a/crates/primitives/Cargo.toml b/crates/primitives/Cargo.toml index e59afd1100..3d3240c50e 100644 --- a/crates/primitives/Cargo.toml +++ b/crates/primitives/Cargo.toml @@ -41,6 +41,7 @@ serde = { version = "1.0", default-features = false, features = [ "derive", "rc", ], optional = true } +revm-utils = {path = "../utils", optional = true} [build-dependencies] hex = { version = "0.4", default-features = false } @@ -97,3 +98,4 @@ c-kzg = [ "dep:blst", "blst?/portable", ] +enable_cache_record = ["revm-utils"] diff --git a/crates/primitives/src/state.rs b/crates/primitives/src/state.rs index 8f6736bd79..c6e54d9877 100644 --- a/crates/primitives/src/state.rs +++ b/crates/primitives/src/state.rs @@ -9,7 +9,16 @@ pub type State = HashMap; pub type TransientStorage = HashMap<(Address, U256), U256>; /// An account's Storage is a mapping from 256-bit integer keys to [StorageSlot]s. +#[cfg(not(feature = "enable_cache_record"))] pub type Storage = HashMap; +#[cfg(feature = "enable_cache_record")] +pub type Storage = HashMap< + U256, + StorageSlot, + hashbrown::hash_map::DefaultHashBuilder, + // tracking_allocator::TrackingAllocator, + revm_utils::TrackingAllocator, +>; #[derive(Debug, Clone, PartialEq, Eq, Default)] #[cfg_attr(feature = "serde", derive(serde::Serialize, serde::Deserialize))] @@ -55,7 +64,11 @@ impl Account { pub fn new_not_existing() -> Self { Self { info: AccountInfo::default(), + #[cfg(not(feature = "enable_cache_record"))] storage: HashMap::new(), + #[cfg(feature = "enable_cache_record")] + // storage: HashMap::new_in(tracking_allocator::TrackingAllocator), + storage: HashMap::new_in(revm_utils::TrackingAllocator), status: AccountStatus::LoadedAsNotExisting, } } @@ -129,7 +142,11 @@ impl From for Account { fn from(info: AccountInfo) -> Self { Self { info, + #[cfg(not(feature = "enable_cache_record"))] storage: HashMap::new(), + #[cfg(feature = "enable_cache_record")] + // storage: HashMap::new_in(tracking_allocator::TrackingAllocator), + storage: HashMap::new_in(revm_utils::TrackingAllocator), status: AccountStatus::Loaded, } } diff --git a/crates/revm/Cargo.toml b/crates/revm/Cargo.toml index 40ddb2623b..137d6220b1 100644 --- a/crates/revm/Cargo.toml +++ b/crates/revm/Cargo.toml @@ -40,6 +40,10 @@ ethers-providers = { version = "2.0", optional = true } ethers-core = { version = "2.0", optional = true } futures = { version = "0.3.30", optional = true } +# metric +revm-utils = {path = "../utils", optional = true} +hashbrown = {version = "0.14", optional = true } + [dev-dependencies] ethers-contract = { version = "2.0.13", default-features = false } anyhow = "1.0.79" @@ -103,6 +107,11 @@ optional_beneficiary_reward = ["revm-interpreter/optional_beneficiary_reward"] secp256k1 = ["revm-precompile/secp256k1"] c-kzg = ["revm-precompile/c-kzg"] +# support perf test +enable_opcode_metrics = ["revm-interpreter/enable_opcode_metrics"] +enable_cache_record = ["revm-utils", "hashbrown", "revm-interpreter/enable_cache_record"] +enable_transact_measure = ["revm-utils"] + [[example]] name = "fork_ref_transact" path = "../../examples/fork_ref_transact.rs" diff --git a/crates/revm/src/db/states.rs b/crates/revm/src/db/states.rs index 2c58f2d632..8147e3c04f 100644 --- a/crates/revm/src/db/states.rs +++ b/crates/revm/src/db/states.rs @@ -4,6 +4,8 @@ pub mod bundle_state; pub mod cache; pub mod cache_account; pub mod changes; +#[cfg(feature = "enable_cache_record")] +pub mod mem_usage; pub mod plain_account; pub mod reverts; pub mod state; diff --git a/crates/revm/src/db/states/bundle_account.rs b/crates/revm/src/db/states/bundle_account.rs index 4c86210024..acc01c4873 100644 --- a/crates/revm/src/db/states/bundle_account.rs +++ b/crates/revm/src/db/states/bundle_account.rs @@ -93,7 +93,16 @@ impl BundleAccount { AccountInfoRevert::DeleteIt => { self.info = None; if self.original_info.is_none() { - self.storage = HashMap::new(); + #[cfg(not(feature = "enable_cache_record"))] + { + self.storage = HashMap::new(); + } + + #[cfg(feature = "enable_cache_record")] + { + self.storage = HashMap::new_in(revm_utils::TrackingAllocator); + } + return true; } else { // set all storage to zero but preserve original values. diff --git a/crates/revm/src/db/states/bundle_state.rs b/crates/revm/src/db/states/bundle_state.rs index f524b08ecb..0e5aa61b19 100644 --- a/crates/revm/src/db/states/bundle_state.rs +++ b/crates/revm/src/db/states/bundle_state.rs @@ -641,12 +641,20 @@ impl BundleState { Entry::Vacant(entry) => { // create empty account that we will revert on. // Only place where this account is not existing is if revert is DeleteIt. + #[cfg(not(feature = "enable_cache_record"))] let mut account = BundleAccount::new( None, None, HashMap::new(), AccountStatus::LoadedNotExisting, ); + #[cfg(feature = "enable_cache_record")] + let mut account = BundleAccount::new( + None, + None, + HashMap::new_in(revm_utils::TrackingAllocator), + AccountStatus::LoadedNotExisting, + ); if !account.revert(revert_account) { self.state_size += account.size_hint(); entry.insert(account); diff --git a/crates/revm/src/db/states/cache.rs b/crates/revm/src/db/states/cache.rs index a3232029ad..59888d402b 100644 --- a/crates/revm/src/db/states/cache.rs +++ b/crates/revm/src/db/states/cache.rs @@ -2,9 +2,13 @@ use super::{ plain_account::PlainStorage, transition_account::TransitionAccount, CacheAccount, PlainAccount, }; use alloc::vec::Vec; +#[cfg(feature = "enable_cache_record")] +use hashbrown::hash_map::DefaultHashBuilder; use revm_interpreter::primitives::{ Account, AccountInfo, Address, Bytecode, HashMap, State as EVMState, B256, }; +#[cfg(feature = "enable_cache_record")] +use revm_utils::TrackingAllocator; /// Cache state contains both modified and original values. /// @@ -15,10 +19,16 @@ use revm_interpreter::primitives::{ #[derive(Clone, Debug, PartialEq, Eq)] pub struct CacheState { /// Block state account with account state + #[cfg(not(feature = "enable_cache_record"))] pub accounts: HashMap, + #[cfg(feature = "enable_cache_record")] + pub accounts: HashMap, /// created contracts /// TODO add bytecode counter for number of bytecodes added/removed. + #[cfg(not(feature = "enable_cache_record"))] pub contracts: HashMap, + #[cfg(feature = "enable_cache_record")] + pub contracts: HashMap, /// Has EIP-161 state clear enabled (Spurious Dragon hardfork). pub has_state_clear: bool, } @@ -33,8 +43,14 @@ impl CacheState { /// New default state. pub fn new(has_state_clear: bool) -> Self { Self { + #[cfg(not(feature = "enable_cache_record"))] accounts: HashMap::default(), + #[cfg(feature = "enable_cache_record")] + accounts: HashMap::new_in(TrackingAllocator), + #[cfg(not(feature = "enable_cache_record"))] contracts: HashMap::default(), + #[cfg(feature = "enable_cache_record")] + contracts: HashMap::new_in(TrackingAllocator), has_state_clear, } } diff --git a/crates/revm/src/db/states/cache_account.rs b/crates/revm/src/db/states/cache_account.rs index 126ce2ffe7..ea1ff0facc 100644 --- a/crates/revm/src/db/states/cache_account.rs +++ b/crates/revm/src/db/states/cache_account.rs @@ -162,7 +162,10 @@ impl CacheAccount { status: self.status, previous_info, previous_status, + #[cfg(not(feature = "enable_cache_record"))] storage: HashMap::default(), + #[cfg(feature = "enable_cache_record")] + storage: HashMap::new_in(revm_utils::TrackingAllocator), storage_was_destroyed: true, }) } @@ -186,7 +189,10 @@ impl CacheAccount { status: self.status, previous_info, previous_status, + #[cfg(not(feature = "enable_cache_record"))] storage: HashMap::new(), + #[cfg(feature = "enable_cache_record")] + storage: HashMap::new_in(revm_utils::TrackingAllocator), storage_was_destroyed: true, }) } @@ -259,7 +265,10 @@ impl CacheAccount { status: self.status, previous_info, previous_status, + #[cfg(not(feature = "enable_cache_record"))] storage: HashMap::new(), + #[cfg(feature = "enable_cache_record")] + storage: HashMap::new_in(revm_utils::TrackingAllocator), storage_was_destroyed: false, }, ) diff --git a/crates/revm/src/db/states/mem_usage.rs b/crates/revm/src/db/states/mem_usage.rs new file mode 100644 index 0000000000..8fe941a9c2 --- /dev/null +++ b/crates/revm/src/db/states/mem_usage.rs @@ -0,0 +1,129 @@ +//! This module defines the method for obtaining the memory size occupied by the State. +use super::{ + cache::CacheState, transition_account::TransitionAccount, BundleAccount, BundleState, + CacheAccount, State, TransitionState, +}; +use revm_interpreter::primitives::{db::Database, AccountInfo}; + +/// This trait is used to support types in obtaining the dynamically allocated memory +/// size used by them +pub trait DynMemUsage { + fn dyn_mem_usage(&self) -> usize; +} + +impl DynMemUsage for AccountInfo { + fn dyn_mem_usage(&self) -> usize { + self.code.as_ref().map(|c| c.len()).unwrap_or(0) + } +} + +impl DynMemUsage for CacheAccount { + fn dyn_mem_usage(&self) -> usize { + self.account + .as_ref() + .map(|a| a.info.dyn_mem_usage()) + .unwrap_or(0) + } +} + +impl DynMemUsage for CacheState { + fn dyn_mem_usage(&self) -> usize { + let accounts_dyn_size = self + .accounts + .iter() + .map(|(_k, v)| v.dyn_mem_usage()) + .sum::(); + let contracts_dyn_size = self.contracts.iter().map(|(_k, v)| v.len()).sum::(); + accounts_dyn_size + contracts_dyn_size + } +} + +impl DynMemUsage for TransitionAccount { + fn dyn_mem_usage(&self) -> usize { + let info_dyn_size = self.info.as_ref().map(|a| a.dyn_mem_usage()).unwrap_or(0); + + let pre_info_dyn_size = self + .previous_info + .as_ref() + .map(|a| a.dyn_mem_usage()) + .unwrap_or(0); + + info_dyn_size + pre_info_dyn_size + } +} + +impl DynMemUsage for TransitionState { + fn dyn_mem_usage(&self) -> usize { + self.transitions + .iter() + .map(|(_k, v)| v.dyn_mem_usage()) + .sum::() + } +} + +impl DynMemUsage for BundleAccount { + fn dyn_mem_usage(&self) -> usize { + let info_dyn_size = self.info.as_ref().map(|v| v.dyn_mem_usage()).unwrap_or(0); + let original_info_dyn_size = self + .original_info + .as_ref() + .map(|v| v.dyn_mem_usage()) + .unwrap_or(0); + info_dyn_size + original_info_dyn_size + } +} + +impl DynMemUsage for BundleState { + fn dyn_mem_usage(&self) -> usize { + let state_dyn_size = self + .state + .iter() + .map(|(_, v)| v.dyn_mem_usage()) + .sum::(); + let contracts_dyn_size = self.contracts.iter().map(|(_, v)| v.len()).sum::(); + state_dyn_size + contracts_dyn_size + } +} + +impl State { + fn dyn_mem_size(&self) -> usize { + // Calculate the memory size of the State on the heap (excluding the HashMap section). + let cache = self.cache.dyn_mem_usage(); + let transaction_state = self + .transition_state + .as_ref() + .map(|v| v.dyn_mem_usage() + std::mem::size_of::()) + .unwrap_or(0); + let bundle_state = self.bundle_state.dyn_mem_usage(); + // block_hashes is a BTreeMap, and here we use the following formula to estimate its + // memory usage: + // memory_size = ( sizeof(key) + sizeof(value) ) * block_hashes.len() + let block_hashes = self.block_hashes.len() * (64 + 32); + + // The size of the hashmap calculated using a memory allocator. + let map_size = revm_utils::allocator::stats().diff as usize; + + // Total dynamic memory size. + let total_dyn_size = cache + transaction_state + bundle_state + block_hashes + map_size; + println!("cache_heap_size: {:?}", cache); + println!("transaction_size: {:?}", transaction_state); + println!("bundle_state: {:?}", bundle_state); + println!("block_hashes_size: {:?}", block_hashes); + println!("map_size: {:?}", map_size); + println!("total_dyn_size: {:?}", total_dyn_size); + + total_dyn_size + } + + fn static_mem_size(&self) -> usize { + let state_size = std::mem::size_of::>(); + println!("state_size: {:?}", state_size); + state_size + } + + pub fn mem_usage(&self) -> usize { + let total = self.dyn_mem_size() + self.static_mem_size(); + println!("total_size: {:?}", total); + total + } +} diff --git a/crates/revm/src/db/states/plain_account.rs b/crates/revm/src/db/states/plain_account.rs index f6cb76618c..d28a1cd703 100644 --- a/crates/revm/src/db/states/plain_account.rs +++ b/crates/revm/src/db/states/plain_account.rs @@ -1,4 +1,8 @@ +#[cfg(feature = "enable_cache_record")] +use hashbrown::hash_map::DefaultHashBuilder; use revm_interpreter::primitives::{AccountInfo, HashMap, StorageSlot, U256}; +#[cfg(feature = "enable_cache_record")] +use revm_utils::TrackingAllocator; // TODO rename this to BundleAccount. As for the block level we have original state. #[derive(Clone, Debug, Default, PartialEq, Eq)] @@ -23,17 +27,27 @@ impl PlainAccount { /// This storage represent values that are before block changed. /// /// Note: Storage that we get EVM contains original values before t +#[cfg(not(feature = "enable_cache_record"))] pub type StorageWithOriginalValues = HashMap; +#[cfg(feature = "enable_cache_record")] +pub type StorageWithOriginalValues = + HashMap; /// Simple plain storage that does not have previous value. /// This is used for loading from database, cache and for bundle state. +#[cfg(not(feature = "enable_cache_record"))] pub type PlainStorage = HashMap; +#[cfg(feature = "enable_cache_record")] +pub type PlainStorage = HashMap; impl From for PlainAccount { fn from(info: AccountInfo) -> Self { Self { info, + #[cfg(not(feature = "enable_cache_record"))] storage: HashMap::new(), + #[cfg(feature = "enable_cache_record")] + storage: HashMap::new_in(TrackingAllocator), } } } diff --git a/crates/revm/src/db/states/state.rs b/crates/revm/src/db/states/state.rs index ec82cb87ff..02e44aec9e 100644 --- a/crates/revm/src/db/states/state.rs +++ b/crates/revm/src/db/states/state.rs @@ -62,6 +62,11 @@ pub struct State { impl State { /// Return the builder that build the State. pub fn builder() -> StateBuilder { + #[cfg(feature = "enable_cache_record")] + { + revm_utils::allocator::reset(); + println!("Reset HashMap size of State!"); + } StateBuilder::default() } } @@ -179,21 +184,45 @@ impl State { if let Some(account) = self.bundle_state.account(&address).cloned().map(Into::into) { + #[cfg(feature = "enable_cache_record")] + let _record = + revm_utils::HitRecord::new(revm_utils::Function::LoadCacheAccount); return Ok(entry.insert(account)); } } + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::MissRecord::new(revm_utils::Function::LoadCacheAccount); // if not found in bundle, load it from database let info = self.database.basic(address)?; let account = match info { None => CacheAccount::new_loaded_not_existing(), Some(acc) if acc.is_empty() => { - CacheAccount::new_loaded_empty_eip161(HashMap::new()) + #[cfg(not(feature = "enable_cache_record"))] + let ret = CacheAccount::new_loaded_empty_eip161(HashMap::new()); + #[cfg(feature = "enable_cache_record")] + let ret = CacheAccount::new_loaded_empty_eip161(HashMap::new_in( + revm_utils::TrackingAllocator, + )); + ret + } + Some(acc) => { + #[cfg(not(feature = "enable_cache_record"))] + let ret = CacheAccount::new_loaded(acc, HashMap::new()); + #[cfg(feature = "enable_cache_record")] + let ret = CacheAccount::new_loaded( + acc, + HashMap::new_in(revm_utils::TrackingAllocator), + ); + ret } - Some(acc) => CacheAccount::new_loaded(acc, HashMap::new()), }; Ok(entry.insert(account)) } - hash_map::Entry::Occupied(entry) => Ok(entry.into_mut()), + hash_map::Entry::Occupied(entry) => { + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::HitRecord::new(revm_utils::Function::LoadCacheAccount); + Ok(entry.into_mut()) + } } } @@ -221,14 +250,22 @@ impl Database for State { fn code_by_hash(&mut self, code_hash: B256) -> Result { let res = match self.cache.contracts.entry(code_hash) { - hash_map::Entry::Occupied(entry) => Ok(entry.get().clone()), + hash_map::Entry::Occupied(entry) => { + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::HitRecord::new(revm_utils::Function::CodeByHash); + Ok(entry.get().clone()) + } hash_map::Entry::Vacant(entry) => { if self.use_preloaded_bundle { if let Some(code) = self.bundle_state.contracts.get(&code_hash) { + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::HitRecord::new(revm_utils::Function::CodeByHash); entry.insert(code.clone()); return Ok(code.clone()); } } + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::MissRecord::new(revm_utils::Function::CodeByHash); // if not found in bundle ask database let code = self.database.code_by_hash(code_hash)?; entry.insert(code.clone()); @@ -248,13 +285,22 @@ impl Database for State { .account .as_mut() .map(|account| match account.storage.entry(index) { - hash_map::Entry::Occupied(entry) => Ok(*entry.get()), + hash_map::Entry::Occupied(entry) => { + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::HitRecord::new(revm_utils::Function::Storage); + Ok(*entry.get()) + } hash_map::Entry::Vacant(entry) => { // if account was destroyed or account is newly built // we return zero and don't ask database. let value = if is_storage_known { + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::HitRecord::new(revm_utils::Function::Storage); U256::ZERO } else { + #[cfg(feature = "enable_cache_record")] + let _record = + revm_utils::MissRecord::new(revm_utils::Function::Storage); self.database.storage(address, index)? }; entry.insert(value); @@ -272,8 +318,14 @@ impl Database for State { // block number is never bigger then u64::MAX. let u64num: u64 = number.to(); match self.block_hashes.entry(u64num) { - btree_map::Entry::Occupied(entry) => Ok(*entry.get()), + btree_map::Entry::Occupied(entry) => { + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::HitRecord::new(revm_utils::Function::BlockHash); + Ok(*entry.get()) + } btree_map::Entry::Vacant(entry) => { + #[cfg(feature = "enable_cache_record")] + let _record = revm_utils::MissRecord::new(revm_utils::Function::BlockHash); let ret = *entry.insert(self.database.block_hash(number)?); // prune all hashes that are older then BLOCK_HASH_HISTORY diff --git a/crates/revm/src/db/states/transition_account.rs b/crates/revm/src/db/states/transition_account.rs index 1dc6bc33dd..6c39ed45ef 100644 --- a/crates/revm/src/db/states/transition_account.rs +++ b/crates/revm/src/db/states/transition_account.rs @@ -139,7 +139,10 @@ impl TransitionAccount { BundleAccount { info: self.previous_info.clone(), original_info: self.previous_info.clone(), + #[cfg(not(feature = "enable_cache_record"))] storage: StorageWithOriginalValues::new(), + #[cfg(feature = "enable_cache_record")] + storage: StorageWithOriginalValues::new_in(revm_utils::TrackingAllocator), status: self.previous_status, } } diff --git a/crates/revm/src/evm.rs b/crates/revm/src/evm.rs index 9db4c50854..d1127067ad 100644 --- a/crates/revm/src/evm.rs +++ b/crates/revm/src/evm.rs @@ -158,6 +158,11 @@ impl Evm<'_, EXT, DB> { /// This function will validate the transaction. #[inline] pub fn transact(&mut self) -> EVMResult { + #[cfg(feature = "enable_transact_measure")] + { + revm_utils::metrics::transact_start_record(); + revm_utils::metrics::transact_sub_record(); + } self.handler.validation().env(&self.context.evm.env)?; let initial_gas_spend = self .handler @@ -166,6 +171,8 @@ impl Evm<'_, EXT, DB> { self.handler .validation() .tx_against_state(&mut self.context)?; + #[cfg(feature = "enable_transact_measure")] + revm_utils::metrics::preverify_transaction_inner_record(); let output = self.transact_preverified_inner(initial_gas_spend); self.handler.post_execution().end(&mut self.context, output) @@ -311,6 +318,8 @@ impl Evm<'_, EXT, DB> { /// Transact pre-verified transaction. fn transact_preverified_inner(&mut self, initial_gas_spend: u64) -> EVMResult { + #[cfg(feature = "enable_transact_measure")] + revm_utils::metrics::transact_sub_record(); let ctx = &mut self.context; let pre_exec = self.handler.pre_execution(); @@ -325,6 +334,8 @@ impl Evm<'_, EXT, DB> { pre_exec.deduct_caller(ctx)?; let gas_limit = ctx.evm.env.tx.gas_limit - initial_gas_spend; + #[cfg(feature = "enable_transact_measure")] + revm_utils::metrics::before_execute_record(); let exec = self.handler.execution(); // call inner handling of call/create @@ -344,6 +355,8 @@ impl Evm<'_, EXT, DB> { FrameOrResult::Frame(first_frame) => self.start_the_loop(first_frame), FrameOrResult::Result(result) => result, }; + #[cfg(feature = "enable_transact_measure")] + let _record = revm_utils::metrics::ExecuteEndRecord::new(); let ctx = &mut self.context; diff --git a/crates/revm/src/lib.rs b/crates/revm/src/lib.rs index 2b2b161174..1ed9cd8c1e 100644 --- a/crates/revm/src/lib.rs +++ b/crates/revm/src/lib.rs @@ -54,3 +54,6 @@ pub use revm_interpreter as interpreter; pub use revm_interpreter::primitives; #[doc(inline)] pub use revm_precompile as precompile; + +#[cfg(feature = "enable_opcode_metrics")] +pub use revm_interpreter::opcode::{self as revm_opcode, OpCode}; diff --git a/crates/utils/Cargo.toml b/crates/utils/Cargo.toml new file mode 100644 index 0000000000..96e1e7e86a --- /dev/null +++ b/crates/utils/Cargo.toml @@ -0,0 +1,17 @@ +[package] +name = "revm-utils" +version = "0.1.0" +edition = "2021" + +# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html + +[dependencies] +serde = { version = "1.0", features = ["derive", "rc"] } +serde_json = "1.0" +serde_arrays = "0.1.0" +ctor = "0.2.5" + +# This dependency provides a version of the unstable nightly Rust `Allocator` +# trait on stable Rust. Enabling this feature means that `alloc` will +# implement its `Allocator` trait. +allocator-api2 = { version = "0.2.8", default-features = false, features = ["alloc"]} \ No newline at end of file diff --git a/crates/utils/src/allocator/mod.rs b/crates/utils/src/allocator/mod.rs new file mode 100644 index 0000000000..49e8571566 --- /dev/null +++ b/crates/utils/src/allocator/mod.rs @@ -0,0 +1,74 @@ +//! This module is used to support memory size measurement for Vec and hashbrown:: HashMap. +//! It provides a memory allocator to record the allocated memory size, and also provides +//! a separate Vec type for specifying the memory allocator during creation. +use allocator_api2::alloc::{AllocError, Allocator}; +pub use allocator_api2::vec::Vec; +use std::{ + alloc::Layout, + sync::atomic::{AtomicUsize, Ordering::SeqCst}, +}; +use std::{ + alloc::{GlobalAlloc, System}, + ptr::NonNull, + slice, +}; + +static ALLOC: AtomicUsize = AtomicUsize::new(0); +static DEALLOC: AtomicUsize = AtomicUsize::new(0); + +#[derive(Debug, Copy, Clone, Default)] +pub struct TrackingAllocator; + +pub fn reset() { + ALLOC.store(0, SeqCst); + DEALLOC.store(0, SeqCst); +} + +pub fn record_alloc(layout: Layout) { + ALLOC.fetch_add(layout.size(), SeqCst); +} + +pub fn record_dealloc(layout: Layout) { + DEALLOC.fetch_add(layout.size(), SeqCst); +} + +pub struct Stats { + pub alloc: usize, + pub dealloc: usize, + pub diff: isize, +} + +pub fn stats() -> Stats { + let alloc: usize = ALLOC.load(SeqCst); + let dealloc: usize = DEALLOC.load(SeqCst); + let diff = (alloc as isize) - (dealloc as isize); + + Stats { + alloc, + dealloc, + diff, + } +} + +unsafe impl Allocator for TrackingAllocator { + fn allocate(&self, layout: Layout) -> Result, AllocError> { + unsafe { + let ptr = System.alloc(layout); + if ptr.is_null() { + Err(AllocError) + } else { + let slice_ptr: *mut [u8] = slice::from_raw_parts_mut(ptr, layout.size()); + let non_null_slice: NonNull<[u8]> = NonNull::new_unchecked(slice_ptr); + record_alloc(layout); + + Ok(non_null_slice) + } + } + } + + unsafe fn deallocate(&self, ptr: NonNull, layout: Layout) { + record_dealloc(layout); + let raw_ptr: *mut u8 = ptr.as_ptr(); + System.dealloc(raw_ptr, layout); + } +} diff --git a/crates/utils/src/lib.rs b/crates/utils/src/lib.rs new file mode 100644 index 0000000000..8641efc3f8 --- /dev/null +++ b/crates/utils/src/lib.rs @@ -0,0 +1,8 @@ +//! This is a library used to support performance testing of revm. +pub mod allocator; +pub mod metrics; +pub mod time_utils; + +pub use allocator::{TrackingAllocator, Vec}; +pub use metrics::Function; +pub use metrics::{HitRecord, MissRecord}; diff --git a/crates/utils/src/metrics/instruction.rs b/crates/utils/src/metrics/instruction.rs new file mode 100644 index 0000000000..1f00f443d1 --- /dev/null +++ b/crates/utils/src/metrics/instruction.rs @@ -0,0 +1,113 @@ +//! This module defines a structure to support the recording of metrics +//! during instruction execution. +use super::types::*; +use crate::time_utils::{convert_cycles_to_ns_f64, instant::Instant}; + +/// This struct is used to record information during instruction execution +/// and finally stores the data in the opcode_record field. +#[derive(Debug, Default)] +pub(super) struct InstructionMetricRecoder { + record: OpcodeRecord, + start_time: Option, + pre_time: Option, + pre_opcode: Option, + started: bool, +} + +impl InstructionMetricRecoder { + /// Start record. + pub(super) fn start_record(&mut self) { + let now = Instant::now(); + + if !self.started { + self.start_time = Some(now); + self.pre_time = Some(now); + } else if self.has_call_opcode() { + let opcode = self.pre_opcode.expect("pre code is empty"); + self.record_time(now, opcode); + self.record.add_additional_count(opcode, 1); + } + self.started = true; + } + + /// Determine whether an instruction is a call related instruction. + fn has_call_opcode(&self) -> bool { + if let Some(opcode) = self.pre_opcode { + match opcode { + // CALL | CALLCODE | DELEGATECALL | STATICCALL + 0xF1 | 0xF2 | 0xF4 | 0xFA => return true, + // other opcode + _ => return false, + } + } + false + } + + /// Called before each instruction execution, it is mainly used to handle + /// the situation that the INTERPRETER will be created circularly when the + /// call related instructions are executed. + pub(super) fn record_before_op(&mut self, opcode: u8) { + self.pre_opcode = Some(opcode) + } + + /// Record the time taken for instruction execution. + fn record_time(&mut self, now: Instant, opcode: u8) -> u64 { + let cycles = now + .checked_cycles_since(self.pre_time.expect("pre time is empty")) + .expect("overflow"); + self.record.opcode_record[opcode as usize].1 = self.record.opcode_record[opcode as usize] + .1 + .checked_add(cycles.into()) + .expect("overflow"); + self.pre_time = Some(now); + + // update total time + self.record.total_time = now + .checked_cycles_since(self.start_time.expect("start time is empty")) + .expect("overflow") + .into(); + + cycles + } + + /// Record opcode execution information, recording: count, time and sload percentile. + pub(super) fn record_op(&mut self, opcode: u8) { + let now = Instant::now(); + + // record count + self.record.opcode_record[opcode as usize].0 = self.record.opcode_record[opcode as usize] + .0 + .checked_add(1) + .expect("overflow"); + + // record time + let cycles = self.record_time(now, opcode); + + // SLOAD = 0x54, + // statistical percentile of sload duration + if opcode == 0x54 { + self.record + .add_sload_opcode_record(convert_cycles_to_ns_f64(cycles)); + } + + self.record.is_updated = true; + } + + /// Retrieve the records of opcode execution, which will be reset after retrieval. + pub(super) fn get_record(&mut self) -> OpcodeRecord { + self.start_time = None; + self.pre_time = None; + self.pre_opcode = None; + self.started = false; + std::mem::replace(&mut self.record, OpcodeRecord::default()) + } + + /// Record the gas consumption during opcode execution. + pub(super) fn record_gas(&mut self, opcode: u8, gas_used: u64) { + // calculate gas + self.record.opcode_record[opcode as usize].2 = self.record.opcode_record[opcode as usize] + .2 + .checked_add(gas_used.into()) + .expect("overflow"); + } +} diff --git a/crates/utils/src/metrics/metric.rs b/crates/utils/src/metrics/metric.rs new file mode 100644 index 0000000000..336a4aa4eb --- /dev/null +++ b/crates/utils/src/metrics/metric.rs @@ -0,0 +1,207 @@ +//! In this module, a large structure is used to record all the measurement +//! metrics of Revm, while providing some functions for measuring metrics +//! in the source code and some functions for obtaining the final metrics +//! externally. +use super::instruction::*; +use super::transact::*; +use super::types::*; + +/// This structure records all metric information for measuring Revm. +#[derive(Default)] +struct Metric { + /// Recording instruction metrics. + instruction_record: InstructionMetricRecoder, + /// Recording cache metrics. + cachedb_record: CacheDbRecord, + /// Recording transact metrics. + transact_record: TransactDurationRecorder, +} + +static mut METRIC_RECORDER: Option = None; + +// This function will be called directly during program initialization. +#[ctor::ctor] +unsafe fn init() { + METRIC_RECORDER = Some(Metric::default()); +} + +/// Start to record the information of opcode execution, which will be called +/// in the source code. +pub fn start_record_op() { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .instruction_record + .start_record(); + } +} + +/// Called before each instruction execution, it is mainly used to handle +/// the situation that the INTERPRETER will be created circularly when the +/// call related instructions are executed. +pub fn record_before_op(opcode: u8) { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .instruction_record + .record_before_op(opcode); + } +} + +/// Record the information of opcode execution, which will be called in the +/// source code. +pub fn record_op(opcode: u8) { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .instruction_record + .record_op(opcode); + } +} + +/// Record the gas of opcode execution, which will be called in the source code. +pub fn record_gas(opcode: u8, gas_used: u64) { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .instruction_record + .record_gas(opcode, gas_used); + } +} + +/// Retrieve the records of opcode execution, which will be reset after retrieval. +/// It will be called by the code of reth. +pub fn get_op_record() -> OpcodeRecord { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .instruction_record + .get_record() + } +} + +/// The function called upon cache hit, which is encapsulated in HitRecord. +pub(super) fn hit_record(function: Function) { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .cachedb_record + .hit(function); + } +} + +/// The function called upon cache miss, which is encapsulated in MissRecord. +pub(super) fn miss_record(function: Function, cycles: u64) { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .cachedb_record + .miss(function, cycles); + } +} + +/// Retrieve the records of cachedb, which will be reset after retrieval. +/// It will be called by the code of reth. +pub fn get_cache_record() -> CacheDbRecord { + unsafe { + let record = METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!"); + std::mem::replace(&mut record.cachedb_record, CacheDbRecord::default()) + } +} + +/// Record the start time of transact. +pub fn transact_start_record() { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record + .start_record() + } +} + +/// Record the start time of sub function. +pub fn transact_sub_record() { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record + .start_sub_record(); + } +} + +/// Record time of preverify_transaction_inner. +pub fn preverify_transaction_inner_record() { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record + .preverify_transaction_inner_record(); + } +} + +/// Record the time before execute opcode in transact_preverified_inner. +pub fn before_execute_record() { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record + .before_execute_record(); + } +} + +/// Record the time of execute opcode in transact_preverified_inner. +pub fn execute_record() { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record + .execute_record(); + } +} + +/// Record the time after execute opcode in transact_preverified_inner. +pub fn after_execute_record() { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record + .after_execute_record(); + } +} + +/// Record the time of handler.end(). +pub fn handler_end_record() { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record + .handler_end_record(); + } +} + +/// Retrieve transact time, which will be reset after retrieval. +pub fn get_transact_time() -> TransactTime { + unsafe { + METRIC_RECORDER + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record + .get_transact_time() + } +} diff --git a/crates/utils/src/metrics/mod.rs b/crates/utils/src/metrics/mod.rs new file mode 100644 index 0000000000..91fd47de98 --- /dev/null +++ b/crates/utils/src/metrics/mod.rs @@ -0,0 +1,9 @@ +mod instruction; +mod metric; +mod transact; +pub mod types; +mod wrapper; + +pub use metric::*; +pub use types::Function; +pub use wrapper::*; diff --git a/crates/utils/src/metrics/transact.rs b/crates/utils/src/metrics/transact.rs new file mode 100644 index 0000000000..5aa1bc295d --- /dev/null +++ b/crates/utils/src/metrics/transact.rs @@ -0,0 +1,102 @@ +//! This module is used to measure the time consumption of various parts of function +//! transact in Revm. +use super::types::*; +use crate::time_utils::instant::Instant; + +#[derive(Debug, Default)] +pub(super) struct TransactDurationRecorder { + /// Record the starting time of function execute_and_verify_receipt. + start_record: Instant, + /// Record the start time of each subfunction. + sub_record: Instant, + /// Record the time consumption of each part of function transact. + transact_time: TransactTime, +} + +impl TransactDurationRecorder { + /// Start record. + pub(super) fn start_record(&mut self) { + self.start_record = Instant::now(); + } + /// Start sub record. + pub(super) fn start_sub_record(&mut self) { + self.sub_record = Instant::now(); + } + + /// Add time of preverify_transaction_inner. + pub(super) fn preverify_transaction_inner_record(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.transact_time.preverify_transaction_inner = self + .transact_time + .preverify_transaction_inner + .checked_add(cycles) + .expect("overflow"); + } + + /// Add the time before execute opcode in transact_preverified_inner. + pub(super) fn before_execute_record(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.transact_time.transact_preverified_inner.before_execute = self + .transact_time + .transact_preverified_inner + .before_execute + .checked_add(cycles) + .expect("overflow"); + } + + /// Add the time of execute opcode in transact_preverified_inner. + pub(super) fn execute_record(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.transact_time.transact_preverified_inner.execute = self + .transact_time + .transact_preverified_inner + .execute + .checked_add(cycles) + .expect("overflow"); + } + + /// Add the time after execute opcode in transact_preverified_inner. + pub(super) fn after_execute_record(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.transact_time.transact_preverified_inner.after_execute = self + .transact_time + .transact_preverified_inner + .after_execute + .checked_add(cycles) + .expect("overflow"); + } + + /// Add the time of handler.end(). + pub(super) fn handler_end_record(&mut self) { + let (cycles, now) = self.record_sub_time(); + self.transact_time.handle_end = self + .transact_time + .handle_end + .checked_add(cycles) + .expect("overflow"); + self.record_total_time(now); + } + + /// Record total time. + fn record_total_time(&mut self, now: Instant) { + let cycles = now.checked_cycles_since(self.start_record).unwrap_or(0); + self.transact_time.total = self + .transact_time + .total + .checked_add(cycles) + .expect("overflow"); + } + + /// Record time of sub function. + fn record_sub_time(&mut self) -> (u64, Instant) { + let now = Instant::now(); + let cycles = now.checked_cycles_since(self.sub_record).unwrap_or(0); + self.sub_record = now; + (cycles, now) + } + + /// Retrieve transact time, which will be reset after retrieval. + pub(super) fn get_transact_time(&mut self) -> TransactTime { + std::mem::replace(&mut self.transact_time, TransactTime::default()) + } +} diff --git a/crates/utils/src/metrics/types.rs b/crates/utils/src/metrics/types.rs new file mode 100644 index 0000000000..896ca0ffdc --- /dev/null +++ b/crates/utils/src/metrics/types.rs @@ -0,0 +1,356 @@ +//! This module defines some types used for revm metrics. +use serde::{Deserialize, Serialize}; + +use crate::time_utils; + +const STEP_IN_US: usize = 1; +const STEP_IN_NS: usize = 100; + +const US_SPAN_SIZE: usize = 200; +const NS_SPAN_SIZE: usize = 40; +const MAX_ARRAY_SIZE: usize = 200; +/// This is a structure for statistical time distribution, which records the +/// distribution of time from two levels: subtle and nanosecond. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)] + +pub struct TimeDistributionStats { + /// The subtle range of statistical distribution, step is STEP_IN_US. + pub span_in_us: usize, + /// The nanosecond range of statistical distribution, step is STEP_IN_NS. + pub span_in_ns: usize, + /// Record the time distribution at a subtle level. + #[serde(with = "serde_arrays")] + pub us_percentile: [u64; MAX_ARRAY_SIZE], + /// Record the time distribution at a nanosecond level. + #[serde(with = "serde_arrays")] + pub ns_percentile: [u64; MAX_ARRAY_SIZE], +} + +impl Default for TimeDistributionStats { + fn default() -> Self { + Self::new(US_SPAN_SIZE, NS_SPAN_SIZE) + } +} + +impl TimeDistributionStats { + pub fn new(span_in_us: usize, span_in_ns: usize) -> Self { + TimeDistributionStats { + span_in_us, + span_in_ns, + us_percentile: [0; MAX_ARRAY_SIZE], + ns_percentile: [0; MAX_ARRAY_SIZE], + } + } + + pub fn update(&mut self, other: &TimeDistributionStats) { + for index in 0..self.span_in_us { + self.us_percentile[index] = self.us_percentile[index] + .checked_add(other.us_percentile[index]) + .expect("overflow"); + } + for index in 0..self.span_in_ns { + self.ns_percentile[index] = self.ns_percentile[index] + .checked_add(other.ns_percentile[index]) + .expect("overflow"); + } + } + + pub fn record(&mut self, time_in_ns: f64) { + // Record the time distribution at a subtle level. + let mut index = (time_in_ns / (1000.0 * STEP_IN_US as f64)) as usize; + if index > self.span_in_us - 1 { + index = self.span_in_us - 1; + } + self.us_percentile[index] = self.us_percentile[index].checked_add(1).expect("overflow"); + + // When the time is less than 4 us, record the distribution of time at the nanosecond level. + if time_in_ns < (self.span_in_ns * STEP_IN_NS) as f64 { + let index = (time_in_ns / STEP_IN_NS as f64) as usize; + self.ns_percentile[index] = self.ns_percentile[index].checked_add(1).expect("overflow"); + } + } +} + +const CALL_OPCODE_LEN: usize = 4; +/// The OpcodeRecord contains all performance information for opcode executions. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)] +pub struct OpcodeRecord { + /// The abscissa is opcode type, tuple means: (opcode counter, time, gas). + #[serde(with = "serde_arrays")] + pub opcode_record: [(u64, u64, i128); 256], + /// Record the time distribution of the sload. + pub sload_percentile: TimeDistributionStats, + /// The total time (cpu cycles) of all opcode. + pub total_time: u64, + /// Update flag. + pub is_updated: bool, + /// Additional rdtsc counts that may be added when measuring call related instructions. + /// array means: (call, call_code, delegate_call, static_call) + pub additional_count: [u64; CALL_OPCODE_LEN], +} + +impl Default for OpcodeRecord { + fn default() -> Self { + let sload_percentile = TimeDistributionStats::new(US_SPAN_SIZE, NS_SPAN_SIZE); + Self { + opcode_record: [(0, 0, 0); 256], + sload_percentile, + total_time: 0, + is_updated: false, + additional_count: [0u64; CALL_OPCODE_LEN], + } + } +} + +impl OpcodeRecord { + /// Update this struct with the other's data. + pub fn update(&mut self, other: &mut OpcodeRecord) { + if !other.is_updated { + return; + } + + self.total_time = self + .total_time + .checked_add(other.total_time) + .expect("overflow"); + + for i in 0..CALL_OPCODE_LEN { + self.additional_count[i] = self.additional_count[i] + .checked_add(other.additional_count[i]) + .expect("overflow"); + } + + if !self.is_updated { + self.opcode_record = std::mem::replace(&mut other.opcode_record, self.opcode_record); + self.sload_percentile = other.sload_percentile; + self.is_updated = true; + return; + } + + for i in 0..256 { + self.opcode_record[i].0 = self.opcode_record[i] + .0 + .checked_add(other.opcode_record[i].0) + .expect("overflow"); + self.opcode_record[i].1 = self.opcode_record[i] + .1 + .checked_add(other.opcode_record[i].1) + .expect("overflow"); + self.opcode_record[i].2 = self.opcode_record[i] + .2 + .checked_add(other.opcode_record[i].2) + .expect("overflow"); + } + + self.sload_percentile.update(&other.sload_percentile); + } + + /// Record sload duration percentile. + pub fn add_sload_opcode_record(&mut self, op_time_ns: f64) { + self.sload_percentile.record(op_time_ns); + } + + pub fn not_empty(&self) -> bool { + self.is_updated + } + + pub fn add_additional_count(&mut self, opcode: u8, count: u64) { + let index = match opcode { + // CALL + 0xF1 => 0, + // CALLCODE + 0xF2 => 1, + // DELEGATECALL + 0xF4 => 2, + // STATICCALL + 0xFA => 3, + _ => { + println!("Add additional_count with error opcode!"); + 4 + } + }; + + if index < 4 { + self.additional_count[index] = self.additional_count[index] + .checked_add(count) + .expect("overflow"); + } + } +} + +/// This type represents in which function the access cache is accessed. +#[derive(Copy, Clone)] +pub enum Function { + CodeByHash = 0, + Storage, + BlockHash, + LoadCacheAccount, +} +/// This structure records the number of times cache hits/misses are accessed in each function. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize, Default)] +pub struct AccessStats { + /// This array is used to store the number of hits/misses/penalty in each function, + /// and the index of the function corresponds to the order of the FunctionType. + #[serde(with = "serde_arrays")] + pub function: [u64; 5], +} + +impl AccessStats { + pub fn update(&mut self, other: &Self) { + for i in 0..self.function.len() { + self.function[i] = self.function[i] + .checked_add(other.function[i]) + .expect("overflow"); + } + } + + fn increment(&mut self, function: Function) { + self.add(function, 1); + } + + fn add(&mut self, function: Function, value: u64) { + let index = function as usize; + self.function[index] = self.function[index].checked_add(value).expect("overflow"); + } +} + +/// The additional cost (cpu cycles) incurred when CacheDb is not hit. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)] +pub struct MissesPenalty { + // Record the penalty when each function hits the cache. + pub time: AccessStats, + /// Record the time distribution at a subtle level. + pub percentile: TimeDistributionStats, +} + +impl Default for MissesPenalty { + fn default() -> Self { + let percentile = TimeDistributionStats::new(US_SPAN_SIZE, NS_SPAN_SIZE); + MissesPenalty { + time: AccessStats::default(), + percentile, + } + } +} + +impl MissesPenalty { + pub fn update(&mut self, other: &Self) { + self.time.update(&other.time); + self.percentile.update(&other.percentile); + } + + fn percentile(&mut self, time_in_ns: f64) { + self.percentile.record(time_in_ns); + } +} + +/// CacheDbRecord records the relevant information of CacheDb hits during the execution process. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize, Default)] +pub struct CacheDbRecord { + /// The number of cache hits when accessing CacheDB. + hits: AccessStats, + /// The number of cache miss when accessing CacheDB. + misses: AccessStats, + /// The additional cost incurred when accessing CacheDb without a cache hit. + penalty: MissesPenalty, +} + +impl CacheDbRecord { + /// Update this struct with the other's data. + pub fn update(&mut self, other: &Self) { + self.hits.update(&other.hits); + self.misses.update(&other.misses); + self.penalty.update(&other.penalty); + } + + /// Returns the total number of times cache has been accessed in each function. + pub fn access_count(&self) -> AccessStats { + let mut stats = self.hits; + stats.update(&self.misses); + stats + } + + /// Returns the number of hits in each function. + pub fn hit_stats(&self) -> AccessStats { + self.hits + } + + /// Returns the number of misses in each function. + pub fn miss_stats(&self) -> AccessStats { + self.misses + } + + /// Return the penalties missed in each function and their distribution. + pub fn penalty_stats(&self) -> MissesPenalty { + self.penalty + } + + /// When hit, increase the number of hits count. + pub(super) fn hit(&mut self, function: Function) { + self.hits.increment(function); + } + + /// When a miss occurs, it is necessary to increase the number of misses count, + /// record the increased penalty, and record the distribution of penalty. + pub(super) fn miss(&mut self, function: Function, penalty: u64) { + self.misses.increment(function); + self.penalty.time.add(function, penalty); + self.penalty + .percentile(time_utils::convert_cycles_to_ns_f64(penalty)); + } +} + +/// This structure is used to record the time consumption of each part of function +/// transact_preverified_inner. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize, Default)] +pub struct TransactPreverifiedInnerTime { + pub before_execute: u64, + pub execute: u64, + pub after_execute: u64, +} + +impl TransactPreverifiedInnerTime { + /// Update this struct with the other's data. + pub fn update(&mut self, other: &Self) { + self.before_execute = self + .before_execute + .checked_add(other.before_execute) + .expect("overflow"); + self.execute = self.execute.checked_add(other.execute).expect("overflow"); + self.after_execute = self + .after_execute + .checked_add(other.after_execute) + .expect("overflow"); + } +} + +/// This structure is used to record the time consumption of each part of function +/// transact. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize, Default)] +pub struct TransactTime { + /// Record total time of trasact. + pub total: u64, + /// Record the time consumption of function preverify_transaction_inner. + pub preverify_transaction_inner: u64, + /// Record the time consumption of function transact_preverified_inner. + pub transact_preverified_inner: TransactPreverifiedInnerTime, + /// Record the time consumption of function handler.end(). + pub handle_end: u64, +} + +impl TransactTime { + /// Update this struct with the other's data. + pub fn update(&mut self, other: &Self) { + self.total = self.total.checked_add(other.total).expect("overflow"); + self.preverify_transaction_inner = self + .preverify_transaction_inner + .checked_add(other.preverify_transaction_inner) + .expect("overflow"); + self.transact_preverified_inner + .update(&other.transact_preverified_inner); + self.handle_end = self + .handle_end + .checked_add(other.handle_end) + .expect("overflow"); + } +} diff --git a/crates/utils/src/metrics/wrapper.rs b/crates/utils/src/metrics/wrapper.rs new file mode 100644 index 0000000000..2e40bc8b24 --- /dev/null +++ b/crates/utils/src/metrics/wrapper.rs @@ -0,0 +1,103 @@ +//! This module encapsulates functions to support recording metrics in a RAII manner. +use super::metric::*; +use super::types::*; +use crate::time_utils::instant::Instant; + +pub struct HitRecord { + function: Function, +} + +impl HitRecord { + pub fn new(function: Function) -> HitRecord { + HitRecord { function } + } +} + +impl Drop for HitRecord { + fn drop(&mut self) { + hit_record(self.function); + } +} + +pub struct MissRecord { + function: Function, + start_time: Instant, +} + +impl MissRecord { + pub fn new(function: Function) -> MissRecord { + MissRecord { + function, + start_time: Instant::now(), + } + } +} + +impl Drop for MissRecord { + fn drop(&mut self) { + let now = Instant::now(); + let cycles = now.checked_cycles_since(self.start_time).expect("overflow"); + + miss_record(self.function, cycles); + } +} + +pub struct PreverifyTransactionInnerRecord; + +impl PreverifyTransactionInnerRecord { + pub fn new() -> Self { + transact_sub_record(); + Self + } +} + +impl Drop for PreverifyTransactionInnerRecord { + fn drop(&mut self) { + preverify_transaction_inner_record(); + } +} + +pub struct HandlerEndRecord; + +impl HandlerEndRecord { + pub fn new() -> Self { + transact_sub_record(); + Self + } +} + +impl Drop for HandlerEndRecord { + fn drop(&mut self) { + handler_end_record(); + } +} + +pub struct ExecuteEndRecord; + +impl ExecuteEndRecord { + pub fn new() -> Self { + execute_record(); + Self + } +} + +impl Drop for ExecuteEndRecord { + fn drop(&mut self) { + after_execute_record(); + } +} + +pub struct OpcodeExecuteRecord(u8); + +impl OpcodeExecuteRecord { + pub fn new(opcode: u8) -> Self { + record_before_op(opcode); + OpcodeExecuteRecord(opcode) + } +} + +impl Drop for OpcodeExecuteRecord { + fn drop(&mut self) { + record_op(self.0) + } +} diff --git a/crates/utils/src/time_utils/cycles.rs b/crates/utils/src/time_utils/cycles.rs new file mode 100644 index 0000000000..cd51fbd290 --- /dev/null +++ b/crates/utils/src/time_utils/cycles.rs @@ -0,0 +1,97 @@ +//! This module provides static methods that read the fine-grain CPU +//! cycle counter and translate between cycle-level times and absolute +//! time. +use std::cell::UnsafeCell; +use std::time::{Duration, Instant}; + +struct Cycles { + nanos_per_cycle: UnsafeCell, + cycles_per_sec: UnsafeCell, +} + +unsafe impl Sync for Cycles {} + +static CYCLES: Cycles = Cycles { + nanos_per_cycle: UnsafeCell::new(1.0), + cycles_per_sec: UnsafeCell::new(1.0), +}; + +#[ctor::ctor] +unsafe fn init() { + let cycles_per_sec = _cycles_per_sec(); + *CYCLES.cycles_per_sec.get() = cycles_per_sec; + *CYCLES.nanos_per_cycle.get() = 1_000_000_000.0 / cycles_per_sec; +} + +#[inline] +pub fn per_sec() -> f64 { + unsafe { *CYCLES.cycles_per_sec.get() } +} + +#[inline] +pub(crate) fn nanos_per_cycle() -> f64 { + unsafe { *CYCLES.nanos_per_cycle.get() } +} + +fn _cycles_per_sec() -> f64 { + // Compute the frequency of the fine-grained CPU timer: to do this, + // take parallel time readings using both rdtsc and std::time::Instant. + // After 10ms have elapsed, take the ratio between these readings. + let mut old_cycles: f64 = 0.0; + let mut cycles_per_sec: f64; + + loop { + let (start_time, start_cycles) = (Instant::now(), rdtsc()); + + loop { + let (stop_time, stop_cycles) = (Instant::now(), rdtsc()); + + let nanos = (stop_time - start_time).as_nanos(); + if nanos > 10_000_000 { + cycles_per_sec = + (stop_cycles - start_cycles) as f64 * 1000_000_000.0 / nanos as f64; + break; + } + } + + let delta = f64::abs(cycles_per_sec - old_cycles); + if delta < cycles_per_sec / 100_000.0 { + break; + } + old_cycles = cycles_per_sec; + } + + cycles_per_sec +} + +#[inline(always)] +pub(crate) fn rdtsc() -> u64 { + #[cfg(target_arch = "x86")] + unsafe { + core::arch::x86::_rdtsc() + } + #[cfg(target_arch = "x86_64")] + unsafe { + core::arch::x86_64::_rdtsc() + } +} + +#[inline(always)] +pub fn convert_cycles_to_ns(cycles: u64) -> u64 { + convert_cycles_to_ns_f64(cycles) as u64 +} + +#[inline(always)] +pub fn convert_cycles_to_ns_f64(cycles: u64) -> f64 { + cycles as f64 * nanos_per_cycle() +} + +#[inline(always)] +pub fn convert_cycles_to_ms(cycles: u64) -> u64 { + (cycles as f64 * nanos_per_cycle() / 1_000.0) as u64 +} + +#[inline(always)] +pub fn convert_cycles_to_duration(cycles: u64) -> Duration { + Duration::from_nanos(convert_cycles_to_ns(cycles)) +} diff --git a/crates/utils/src/time_utils/instant.rs b/crates/utils/src/time_utils/instant.rs new file mode 100644 index 0000000000..75b15330b6 --- /dev/null +++ b/crates/utils/src/time_utils/instant.rs @@ -0,0 +1,37 @@ +//! This Instant measures time with high performance and high accuracy powered by TSC. +use super::cycles; +use std::time::Duration; + +/// A measurement of a monotonically nondecreasing clock. +#[derive(Debug, Default, Clone, Copy)] +pub struct Instant(u64); + +impl Instant { + /// Returns an instant corresponding to "now". + #[inline] + pub fn now() -> Instant { + Instant(cycles::rdtsc()) + } + + /// Returns the amount of cpu cycles from another instant to this one, + /// or None if that instant is later than this one. + pub fn checked_cycles_since(&self, earlier: Instant) -> Option { + Some(self.0.checked_sub(earlier.0)?) + } + + /// Returns the amount of nanos from another instant to this one, + /// or None if that instant is later than this one. + pub fn checked_nanos_since(&self, earlier: Instant) -> Option { + Some(cycles::convert_cycles_to_ns_f64( + self.0.checked_sub(earlier.0)?, + )) + } + + /// Returns the amount of duration from another instant to this one, + /// or None if that instant is later than this one. + pub fn checked_duration_since(&self, earlier: Instant) -> Option { + Some(cycles::convert_cycles_to_duration( + self.0.checked_sub(earlier.0)?, + )) + } +} diff --git a/crates/utils/src/time_utils/mod.rs b/crates/utils/src/time_utils/mod.rs new file mode 100644 index 0000000000..16351a461a --- /dev/null +++ b/crates/utils/src/time_utils/mod.rs @@ -0,0 +1,9 @@ +//! Provide some time measurement related functions and types. +mod cycles; +pub mod instant; +pub mod time_trace; + +pub use cycles::{ + convert_cycles_to_duration, convert_cycles_to_ms, convert_cycles_to_ns, + convert_cycles_to_ns_f64, per_sec, +}; diff --git a/crates/utils/src/time_utils/time_trace.rs b/crates/utils/src/time_utils/time_trace.rs new file mode 100644 index 0000000000..de37c3ffc4 --- /dev/null +++ b/crates/utils/src/time_utils/time_trace.rs @@ -0,0 +1,173 @@ +//! This time trace can only be used in single threads. +use super::cycles; + +static mut TIME_RECORDER: TimeTrace = TimeTrace { + buffer: INIT_BUFFER, +}; + +/// Determines the number of events we can retain as an exponent of 2 +const BUFFER_SIZE_EXP: u8 = 20; +/// Total number of events that we can retain any given time. +const BUFFER_SIZE: usize = 1 << BUFFER_SIZE_EXP; +/// Bit mask used to implement a circular event buffer +const BUFFER_MASK: usize = BUFFER_SIZE - 1; + +/// Identify whether to save historical data. +const KEEP_OLD_EVENTS: bool = false; + +const INIT_EVENT: Event = Event { + timestamp: 0, + format: None, +}; + +const INIT_BUFFER: Buffer = Buffer { + events: [INIT_EVENT; BUFFER_SIZE], + next_index: 0, + has_record: false, +}; + +/// This structure holds one entry in the TimeTrace. +#[derive(Default, Clone)] +struct Event { + /// Time when a particular event occurred. + timestamp: u64, + /// Format string describing the event. + format: Option, +} + +/// Represents a sequence of events. Has a fixed capacity, so slots are re-used on a +/// circular basis. +struct Buffer { + /// Holds information from the most recent calls to the record method. + events: [Event; BUFFER_SIZE], + /// Index within events of the slot to use for the next call to the record method. + next_index: usize, + /// Indicating that there is a record. + has_record: bool, +} + +impl Buffer { + /// Record an event in the buffer. + fn record(&mut self, timestamp: u64, format: String) { + self.events[self.next_index].timestamp = timestamp; + self.events[self.next_index].format = Some(format); + self.next_index = (self.next_index + 1) & BUFFER_MASK; + self.has_record = true; + // println!("index: {:?}, format: {:?}", self.next_index-1, self.events[self.next_index-1].format); + } + + /// Print all existing trace records to stdout. + fn print(&self) { + if self.has_record { + self.print_internal(); + } + } + + fn print_internal(&self) { + // Find the first (oldest) event in trace. This will be events[0] if we + // never completely filled the buffer, otherwise events[nextIndex+1]. + let index = (self.next_index + 1) % BUFFER_SIZE; + let mut current = if self.events[index].format.is_some() { + index + } else { + 0 + }; + + // Get the starting time. + let start_time = if !KEEP_OLD_EVENTS { + let mut time = 0; + if self.events[current].format.is_some() && self.events[current].timestamp > time { + time = self.events[current].timestamp; + } + time + } else { + let mut time = u64::MAX; + if self.events[current].format.is_some() && self.events[current].timestamp < time { + time = self.events[current].timestamp; + } + time + }; + + // Skip all events before the starting time. + loop { + if self.events[current].format.is_some() + && self.events[current].timestamp < start_time as u64 + && current != self.next_index + { + current = (current + 1) % BUFFER_SIZE; + } else { + break; + } + } + + // Print all events + let mut pre_time = 0.0; + let mut printed_anything = false; + loop { + if !printed_anything { + println!("CYCLES_PER_SECOND {:?}", cycles::per_sec()); + println!("START_CYCLES {:?}", start_time); + + printed_anything = true; + } + + if self.events[current].timestamp < start_time { + break; + } + + let cycles = self.events[current].timestamp - start_time; + let ns = cycles::convert_cycles_to_ns_f64(cycles); + println!( + "{:13.3} ns | (+{:10.3} ns): {}", + ns, + ns - pre_time, + self.events[current].format.clone().unwrap_or_default(), + ); + pre_time = ns; + + current = (current + 1) & BUFFER_MASK; + } + } +} + +struct TimeTrace { + buffer: Buffer, +} + +impl TimeTrace { + fn record(&mut self, format: String) { + self.buffer.record(cycles::rdtsc(), format); + } + + fn print(&self) { + self.buffer.print(); + } +} + +pub fn record(format: String) { + unsafe { + TIME_RECORDER.record(format); + } +} + +pub fn trace_print() { + unsafe { + TIME_RECORDER.print(); + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::time::Duration; + + #[test] + fn test_record_and_print() { + record("1".to_string()); + std::thread::sleep(Duration::from_nanos(1_000_000_000)); + record("2".to_string()); + std::thread::sleep(Duration::from_nanos(2_000_000_000)); + record("3".to_string()); + trace_print(); + } +}