From 9126337e9a39878921fa68b2d5a159bb5508e4a3 Mon Sep 17 00:00:00 2001 From: Renato Dinhani <101204870+dinhani-cw@users.noreply.github.com> Date: Tue, 27 Feb 2024 12:05:57 -0300 Subject: [PATCH] feat: improving executor and evm metrics (#286) --- src/eth/evm/revm.rs | 37 ++++++++----- src/eth/executor.rs | 37 +++++++------ src/eth/storage/stratus_storage.rs | 22 ++++---- src/infra/metrics.rs | 87 +++++++++++++++++++----------- 4 files changed, 109 insertions(+), 74 deletions(-) diff --git a/src/eth/evm/revm.rs b/src/eth/evm/revm.rs index 1a070fd22..af1694a20 100644 --- a/src/eth/evm/revm.rs +++ b/src/eth/evm/revm.rs @@ -6,6 +6,7 @@ //! of the `Evm` trait, serving as a bridge between Ethereum's abstract operations and Stratus's storage mechanisms. use std::sync::Arc; +use std::time::Instant; use anyhow::anyhow; use itertools::Itertools; @@ -43,6 +44,7 @@ use crate::eth::primitives::SlotIndex; use crate::eth::storage::StratusStorage; use crate::ext::not; use crate::ext::OptionExt; +use crate::infra::metrics; /// Implementation of EVM using [`revm`](https://crates.io/crates/revm). pub struct Revm { @@ -69,6 +71,8 @@ impl Revm { impl Evm for Revm { fn execute(&mut self, input: EvmInput) -> anyhow::Result { + let start = Instant::now(); + // configure session let evm = &mut self.evm; let session = RevmDatabaseSession::new(Arc::clone(&self.storage), input.clone()); @@ -99,16 +103,20 @@ impl Evm for Revm { #[cfg(not(debug_assertions))] let evm_result = evm.transact(); - match evm_result { - Ok(result) => { - let session = evm.take_db(); - Ok(parse_revm_execution(result, session.input, session.storage_changes)?) - } + // parse result and track metrics + let session = evm.take_db(); + let point_in_time = session.input.point_in_time.clone(); + + let result = match evm_result { + Ok(result) => Ok(parse_revm_execution(result, session.input, session.storage_changes)), Err(e) => { tracing::warn!(reason = ?e, "evm execution error"); Err(anyhow!("Error executing EVM transaction. Check logs for more information.")) } - } + }; + metrics::inc_evm_execution(start.elapsed(), &point_in_time, result.is_ok()); + + result } } @@ -224,19 +232,19 @@ impl Inspector for RevmInspector { // Conversion // ----------------------------------------------------------------------------- -fn parse_revm_execution(revm_result: RevmResultAndState, input: EvmInput, execution_changes: ExecutionChanges) -> anyhow::Result { +fn parse_revm_execution(revm_result: RevmResultAndState, input: EvmInput, execution_changes: ExecutionChanges) -> Execution { let (result, output, logs, gas) = parse_revm_result(revm_result.result); - let execution_changes = parse_revm_state(revm_result.state, execution_changes)?; + let execution_changes = parse_revm_state(revm_result.state, execution_changes); tracing::info!(?result, %gas, output_len = %output.len(), %output, "evm executed"); - Ok(Execution { + Execution { result, output, logs, gas, block_timestamp: input.block_timestamp, changes: execution_changes.into_values().collect(), - }) + } } fn parse_revm_result(result: RevmExecutionResult) -> (ExecutionResult, Bytes, Vec, Gas) { @@ -263,7 +271,7 @@ fn parse_revm_result(result: RevmExecutionResult) -> (ExecutionResult, Bytes, Ve } } -fn parse_revm_state(revm_state: RevmState, mut execution_changes: ExecutionChanges) -> anyhow::Result { +fn parse_revm_state(revm_state: RevmState, mut execution_changes: ExecutionChanges) -> ExecutionChanges { for (revm_address, revm_account) in revm_state { let address: Address = revm_address.into(); if address.is_ignored() { @@ -299,11 +307,12 @@ fn parse_revm_state(revm_state: RevmState, mut execution_changes: ExecutionChang // status: touched (updated) else if account_updated { let Some(existing_account) = execution_changes.get_mut(&address) else { - tracing::error!(keys = ?execution_changes.keys(), reason = "account was updated, but it was not loaded by evm", %address); - return Err(anyhow!("Account '{}' was expected to be loaded by EVM, but it was not", address)); + tracing::error!(keys = ?execution_changes.keys(), %address, "account updated, but not loaded by evm"); + // TODO: panic! only when in dev-mode or try to refactor to avoid panic! + panic!("Account '{}' was expected to be loaded by EVM, but it was not", address); }; existing_account.apply_changes(account, account_modified_slots); } } - Ok(execution_changes) + execution_changes } diff --git a/src/eth/executor.rs b/src/eth/executor.rs index 2dd8b8480..f859ffc69 100644 --- a/src/eth/executor.rs +++ b/src/eth/executor.rs @@ -76,13 +76,13 @@ impl EthExecutor { /// Imports an external block using the offline flow. pub async fn import_offline(&self, block: ExternalBlock, receipts: &HashMap) -> anyhow::Result<()> { + let start = Instant::now(); tracing::info!(number = %block.number(), "importing offline block"); - let import_start = Instant::now(); // re-execute transactions let mut executions: Vec = Vec::with_capacity(block.transactions.len()); for tx in block.transactions.clone() { - let start = Instant::now(); + let tx_start = Instant::now(); // find receipt let Some(receipt) = receipts.get(&tx.hash()).cloned() else { tracing::error!(hash = %tx.hash, "receipt is missing"); @@ -107,8 +107,8 @@ impl EthExecutor { // temporarily save state to next transactions from the same block self.storage.save_account_changes_to_temp(execution.clone()).await?; - metrics::inc_execution(start.elapsed(), true); executions.push((tx, receipt, execution)); + metrics::inc_executor_import_offline_transaction(tx_start.elapsed()); } Err(e) => { let json_tx = serde_json::to_string(&tx).unwrap(); @@ -119,6 +119,7 @@ impl EthExecutor { } } + // commit block let block = Block::from_external(block, executions)?; self.storage.set_block_number(*block.number()).await?; if let Err(e) = self.storage.commit_to_perm(block.clone()).await { @@ -126,14 +127,16 @@ impl EthExecutor { tracing::error!(reason = ?e, %json_block); return Err(e.into()); }; - metrics::inc_execution_and_commit(import_start.elapsed(), true); + metrics::inc_executor_import_offline(start.elapsed()); Ok(()) } pub async fn import(&self, external_block: ExternalBlock, external_receipts: HashMap) -> anyhow::Result<()> { + let start = Instant::now(); + for external_transaction in >::from(external_block.clone()).transactions { - let start = Instant::now(); + let tx_start = Instant::now(); // Find the receipt for the current transaction. let external_receipt = external_receipts .get(&external_transaction.hash) @@ -147,21 +150,15 @@ impl EthExecutor { let evm_input = EvmInput::from_eth_transaction(transaction_input.clone()); let execution = self.execute_in_evm(evm_input).await?; - metrics::inc_execution(start.elapsed(), true); - execution.compare_with_receipt(external_receipt)?; + metrics::inc_executor_import_online_transaction(tx_start.elapsed()); let block = self.miner.lock().await.mine_with_one_transaction(transaction_input, execution).await?; - self.storage.commit_to_perm(block).await?; - metrics::inc_execution_and_commit(start.elapsed(), true); + metrics::inc_executor_import_online(tx_start.elapsed()); } - //TODO compare slots/changes - //TODO compare nonce - //TODO compare balance - //XXX panic in case of bad comparisson - + metrics::inc_executor_import_online(start.elapsed()); Ok(()) } @@ -175,6 +172,7 @@ impl EthExecutor { /// /// TODO: too much cloning that can be optimized here. pub async fn transact(&self, transaction: TransactionInput) -> anyhow::Result { + let start = Instant::now(); tracing::info!( hash = %transaction.hash, nonce = %transaction.nonce, @@ -193,7 +191,10 @@ impl EthExecutor { } // creates a block and performs the necessary notifications - self.mine_and_execute_transaction(transaction).await + let result = self.mine_and_execute_transaction(transaction).await; + metrics::inc_executor_transact(start.elapsed(), result.is_ok()); + + result } #[cfg(feature = "evm-mine")] @@ -250,6 +251,7 @@ impl EthExecutor { /// Execute a function and return the function output. State changes are ignored. pub async fn call(&self, input: CallInput, point_in_time: StoragePointInTime) -> anyhow::Result { + let start = Instant::now(); tracing::info!( from = ?input.from, to = ?input.to, @@ -259,8 +261,9 @@ impl EthExecutor { ); let evm_input = EvmInput::from_eth_call(input, point_in_time); - let execution = self.execute_in_evm(evm_input).await?; - Ok(execution) + let result = self.execute_in_evm(evm_input).await; + metrics::inc_executor_call(start.elapsed(), result.is_ok()); + result } /// Submits a transaction to the EVM and awaits for its execution. diff --git a/src/eth/storage/stratus_storage.rs b/src/eth/storage/stratus_storage.rs index 33ff553e6..a145a726e 100644 --- a/src/eth/storage/stratus_storage.rs +++ b/src/eth/storage/stratus_storage.rs @@ -21,9 +21,9 @@ use crate::eth::storage::StorageError; use crate::eth::storage::TemporaryStorage; use crate::infra::metrics; -static TEMP_ORIGIN: &str = "temporary"; -static PERM_ORIGIN: &str = "permanent"; -static DEFAULT_ORIGIN: &str = "default"; +const STORAGE_TEMP: &str = "temporary"; +const STORAGE_PERM: &str = "permanent"; +const DEFAULT_VALUE: &str = "default"; pub struct StratusStorage { temp: Arc, @@ -74,18 +74,18 @@ impl StratusStorage { match self.temp.maybe_read_account(address, point_in_time).await? { Some(account) => { tracing::debug!("account found in the temporary storage"); - metrics::inc_storage_read_account(start.elapsed(), TEMP_ORIGIN, point_in_time, true); + metrics::inc_storage_read_account(start.elapsed(), STORAGE_TEMP, point_in_time, true); Ok(account) } None => match self.perm.maybe_read_account(address, point_in_time).await? { Some(account) => { tracing::debug!("account found in the permanent storage"); - metrics::inc_storage_read_account(start.elapsed(), PERM_ORIGIN, point_in_time, true); + metrics::inc_storage_read_account(start.elapsed(), STORAGE_PERM, point_in_time, true); Ok(account) } None => { tracing::debug!("account not found, assuming default value"); - metrics::inc_storage_read_account(start.elapsed(), DEFAULT_ORIGIN, point_in_time, true); + metrics::inc_storage_read_account(start.elapsed(), DEFAULT_VALUE, point_in_time, true); Ok(Account { address: address.clone(), ..Account::default() @@ -102,18 +102,18 @@ impl StratusStorage { match self.temp.maybe_read_slot(address, slot_index, point_in_time).await? { Some(slot) => { tracing::debug!("slot found in the temporary storage"); - metrics::inc_storage_read_slot(start.elapsed(), TEMP_ORIGIN, point_in_time, true); + metrics::inc_storage_read_slot(start.elapsed(), STORAGE_TEMP, point_in_time, true); Ok(slot) } None => match self.perm.maybe_read_slot(address, slot_index, point_in_time).await? { Some(slot) => { tracing::debug!("slot found in the permanent storage"); - metrics::inc_storage_read_slot(start.elapsed(), PERM_ORIGIN, point_in_time, true); + metrics::inc_storage_read_slot(start.elapsed(), STORAGE_PERM, point_in_time, true); Ok(slot) } None => { tracing::debug!("slot not found, assuming default value"); - metrics::inc_storage_read_slot(start.elapsed(), DEFAULT_ORIGIN, point_in_time, true); + metrics::inc_storage_read_slot(start.elapsed(), DEFAULT_VALUE, point_in_time, true); Ok(Slot { index: slot_index.clone(), ..Default::default() @@ -184,7 +184,7 @@ impl StratusStorage { pub async fn reset_temp(&self) -> anyhow::Result<()> { let start = Instant::now(); let result = self.temp.reset().await; - metrics::inc_storage_reset(start.elapsed(), result.is_ok()); + metrics::inc_storage_reset(start.elapsed(), STORAGE_TEMP, result.is_ok()); result } @@ -192,7 +192,7 @@ impl StratusStorage { pub async fn reset_perm(&self, block_number: BlockNumber) -> anyhow::Result<()> { let start = Instant::now(); let result = self.perm.reset_at(block_number).await; - metrics::inc_storage_reset(start.elapsed(), result.is_ok()); + metrics::inc_storage_reset(start.elapsed(), STORAGE_PERM, result.is_ok()); result } diff --git a/src/infra/metrics.rs b/src/infra/metrics.rs index 001de3137..ef1e4d4c8 100644 --- a/src/infra/metrics.rs +++ b/src/infra/metrics.rs @@ -21,11 +21,18 @@ pub fn init_metrics() { tracing::info!("starting metrics"); PrometheusBuilder::new().install().expect("failed to start metrics"); + + // api metrics register_metrics_for_json_rpc(); - register_metrics_for_block_number(); + + // executor metrics + register_metrics_for_executor(); + register_metrics_for_evm(); + + // storage metrics + register_metrics_for_storage_block_number(); register_metrics_for_storage_read(); register_metrics_for_storage_write(); - register_metrics_for_executor(); } // JSON-RPC metrics. @@ -41,15 +48,15 @@ metrics! { // Storage block number metrics metrics! { - group: block_number, + group: storage_block_number, - "Duration of storage read_current_block_number operation." + "Time to execute storage read_current_block_number operation." histogram storage_read_current_block_number{success}, - "Duration of storage increment_block_number operation." + "Time to execute storage increment_block_number operation." histogram storage_increment_block_number{success}, - "Duration of storage set_block_number operation." + "Time to execute storage set_block_number operation." histogram storage_set_block_number{success} } @@ -57,22 +64,19 @@ metrics! { metrics! { group: storage_read, - "Duration of storage check_conflicts operation." - histogram storage_check_conflicts{conflicted, success}, - - "Duration of storage read_account operation." - histogram storage_read_account{origin, point_in_time, success}, + "Time to execute storage read_account operation." + histogram storage_read_account{kind, point_in_time, success}, - "Duration of storage read_block operation." + "Time to execute storage read_block operation." histogram storage_read_block{success}, - "Duration of storage read_logs operation." + "Time to execute storage read_logs operation." histogram storage_read_logs{success}, - "Duration of storage read_slot operation." - histogram storage_read_slot{origin, point_in_time, success}, + "Time to execute storage read_slot operation." + histogram storage_read_slot{kind, point_in_time, success}, - "Duration of storage read_mined_transaction operation." + "Time to execute storage read_mined_transaction operation." histogram storage_read_mined_transaction{success} } @@ -80,19 +84,19 @@ metrics! { metrics! { group: storage_write, - "Duration of storage save_accounts operation." + "Time to execute storage save_accounts operation." histogram storage_save_accounts{success}, - "Duration of storage save_account_changes operation." + "Time to execute storage save_account_changes operation." histogram storage_save_account_changes{success}, - "Duration of storage save_block operation." + "Time to execute storage save_block operation." histogram storage_save_block{success}, - "Duration of storage reset operation." - histogram storage_reset{success}, + "Time to execute storage reset operation." + histogram storage_reset{kind, success}, - "Duration of storage commit operation." + "Time to execute storage commit operation." histogram storage_commit{success} } @@ -100,11 +104,30 @@ metrics! { metrics! { group: executor, - "Duration of execution operation." - histogram execution{success}, + "Time to execute import_offline operation." + histogram executor_import_offline{}, + + "Time to execute and persist temporary changes of a single transaction inside import_offline operation." + histogram executor_import_offline_transaction{}, + + "Time to execute import_online operation." + histogram executor_import_online{}, - "Duration of execution and commit operation." - histogram execution_and_commit{success} + "Time to execute and persist a single transaction inside import_online operation." + histogram executor_import_online_transaction{}, + + "Time to execute a transaction received with eth_sendRawTransaction." + histogram executor_transact{success}, + + "Time to execute a transaction received with eth_call or eth_estimateGas." + histogram executor_call{success} +} + +metrics! { + group: evm, + + "Time to execute EVM execution." + histogram evm_execution{point_in_time, success} } // ----------------------------------------------------------------------------- @@ -174,7 +197,7 @@ macro_rules! metrics { group: $group:ident, $( $description:literal - $kind:ident $name:ident{ $($label:ident),+ } + $kind:ident $name:ident{ $($label:ident),* } ),+ ) => { // Register metrics with description with the provider @@ -188,7 +211,7 @@ macro_rules! metrics { // Record metrics $( - metrics_impl_fn_inc!($kind $name $group $($label)+); + metrics_impl_fn_inc!($kind $name $group $($label)*); )+ } } @@ -213,7 +236,7 @@ macro_rules! metrics_impl_describe { #[macro_export] #[doc(hidden)] macro_rules! metrics_impl_fn_inc { - (counter $name:ident $group:ident $($label:ident)+) => { + (counter $name:ident $group:ident $($label:ident)*) => { paste! { #[doc = "Add 1 to `" $name "` counter."] pub fn []($( $label: impl Into ),+) { @@ -229,16 +252,16 @@ macro_rules! metrics_impl_fn_inc { } } }; - (histogram $name:ident $group:ident $($label:ident)+) => { + (histogram $name:ident $group:ident $($label:ident)*) => { paste! { #[doc = "Add operation duration to `" $name "` histogram."] - pub fn [](duration: std::time::Duration, $( $label: impl Into ),+) { + pub fn [](duration: std::time::Duration, $( $label: impl Into ),*) { let labels = into_labels( vec![ ("group", stringify!($group).into()), $( (stringify!($label), $label.into()), - )+ + )* ] ); histogram!(stringify!([]), duration, labels)