From 613457b48d78c565524509411c63e2aa6b04d9fc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E4=BB=A4=E7=8B=90=E4=B8=80=E5=86=B2?= <43949039+anonymousGiga@users.noreply.github.com> Date: Fri, 1 Dec 2023 14:43:42 +0800 Subject: [PATCH] Perf: Add metrics for execution txs (#27) --- Cargo.lock | 1 + bin/reth/Cargo.toml | 6 + .../performance_metrics/dashboard_display.rs | 75 ++++++- .../performance_metrics/dashboard_listener.rs | 12 ++ crates/revm/Cargo.toml | 5 +- crates/revm/src/executor.rs | 16 ++ crates/revm/src/lib.rs | 4 + crates/revm/src/utils.rs | 199 ++++++++++++++++++ crates/stages/Cargo.toml | 2 + crates/stages/src/metrics/listener.rs | 12 ++ crates/stages/src/stages/execution.rs | 7 + 11 files changed, 336 insertions(+), 3 deletions(-) create mode 100644 crates/revm/src/utils.rs diff --git a/Cargo.lock b/Cargo.lock index 617fb402fb73..bd9698587734 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5895,6 +5895,7 @@ dependencies = [ name = "reth-revm" version = "0.1.0-alpha.8" dependencies = [ + "ctor 0.2.5", "once_cell", "reth-consensus-common", "reth-interfaces", diff --git a/bin/reth/Cargo.toml b/bin/reth/Cargo.toml index 6a0980a635fb..edfce9d7890b 100644 --- a/bin/reth/Cargo.toml +++ b/bin/reth/Cargo.toml @@ -172,6 +172,12 @@ enable_db_speed_record = [ "reth-stages/enable_db_speed_record", "open_performance_dashboard", ] +enable_execute_measure = [ + "reth-revm/enable_execute_measure", + "reth-stages/enable_execute_measure", + "revm-utils", + "open_performance_dashboard", +] [build-dependencies] vergen = { version = "8.0.0", features = ["build", "cargo", "git", "gitcl"] } diff --git a/bin/reth/src/performance_metrics/dashboard_display.rs b/bin/reth/src/performance_metrics/dashboard_display.rs index 975c3c53792c..91e69595619d 100644 --- a/bin/reth/src/performance_metrics/dashboard_display.rs +++ b/bin/reth/src/performance_metrics/dashboard_display.rs @@ -25,9 +25,13 @@ use reth_stages::DbSpeedRecord; #[cfg(feature = "enable_opcode_metrics")] const MGAS_TO_GAS: u64 = 1_000_000u64; -#[cfg(any(feature = "enable_opcode_metrics", feature = "enable_cache_record"))] +#[cfg(any( + feature = "enable_opcode_metrics", + feature = "enable_cache_record", + feature = "enable_execute_measure" +))] const COL_WIDTH_MIDDLE: usize = 14; -#[cfg(feature = "enable_cache_record")] +#[cfg(any(feature = "enable_cache_record", feature = "enable_execute_measure"))] const COL_WIDTH_BIG: usize = 20; #[cfg(feature = "enable_cache_record")] const COL_WIDTH_LARGE: usize = 30; @@ -532,3 +536,70 @@ impl Default for TpsAndGasRecordDisplayer { Self { delta_txs: 0, delta_gas: 0, last_instant: Instant::now() } } } + +#[cfg(feature = "enable_execute_measure")] +use reth_revm::utils::ExecuteTxsRecord; +#[cfg(feature = "enable_execute_measure")] +#[derive(Debug, Default)] +pub(crate) struct ExecuteTxsDisplayer { + record: ExecuteTxsRecord, +} + +#[cfg(feature = "enable_execute_measure")] +impl ExecuteTxsDisplayer { + pub(crate) fn record(&mut self, record: ExecuteTxsRecord) { + self.record = record; + } + + pub(crate) fn print(&self) { + let total = time_in_secs(self.record.total()); + let transact = time_in_secs(self.record.transact()); + let commit_changes = time_in_secs(self.record.commit_changes()); + let add_receipt = time_in_secs(self.record.add_receipt()); + let apply_post_block_changes = time_in_secs(self.record.apply_post_block_changes()); + let verify_receipt = time_in_secs(self.record.verify_receipt()); + let execute = + transact + commit_changes + add_receipt + apply_post_block_changes + verify_receipt; + let misc = total - execute; + + let transact_pct = transact as f64 / total as f64; + let commit_changes_pct = commit_changes as f64 / total as f64; + let add_receipt_pct = add_receipt as f64 / total as f64; + let apply_post_block_changes_pct = apply_post_block_changes as f64 / total as f64; + let verify_receipt_pct = verify_receipt as f64 / total as f64; + let misc_pct = misc as f64 / total as f64; + + println!(); + println!("===============================Metric of execute txs ===================================================="); + println!( + "{: COL_WIDTH_MIDDLE$}{: >COL_WIDTH_MIDDLE$}", + "Cat.", "Time (s)", "Time (%)", + ); + + self.print_line("total", total, 100.0); + self.print_line("misc", misc, misc_pct); + self.print_line("transact", transact, transact_pct); + self.print_line("commit_changes", commit_changes, commit_changes_pct); + self.print_line("add_receipt", add_receipt, add_receipt_pct); + self.print_line( + "apply_block_changes", + apply_post_block_changes, + apply_post_block_changes_pct, + ); + self.print_line("verify_receipt", verify_receipt, verify_receipt_pct); + + println!(); + } + + fn print_line(&self, cat: &str, time: f64, percent: f64) { + println!( + "{: COL_WIDTH_MIDDLE$.3}{: >COL_WIDTH_MIDDLE$.2}", + cat, time, percent, + ); + } +} + +#[cfg(feature = "enable_execute_measure")] +fn time_in_secs(cycles: u64) -> f64 { + revm_utils::time_utils::convert_cycles_to_duration(cycles).as_secs_f64() +} diff --git a/bin/reth/src/performance_metrics/dashboard_listener.rs b/bin/reth/src/performance_metrics/dashboard_listener.rs index d868584c28ef..32055109f29d 100644 --- a/bin/reth/src/performance_metrics/dashboard_listener.rs +++ b/bin/reth/src/performance_metrics/dashboard_listener.rs @@ -24,6 +24,9 @@ use super::dashboard_display::CacheDBRecordDisplayer; #[cfg(feature = "enable_tps_gas_record")] use super::dashboard_display::TpsAndGasRecordDisplayer; +#[cfg(feature = "enable_execute_measure")] +use super::dashboard_display::ExecuteTxsDisplayer; + #[derive(Debug)] pub(crate) struct DashboardListener { events_rx: UnboundedReceiver, @@ -42,6 +45,8 @@ pub(crate) struct DashboardListener { #[cfg(feature = "enable_tps_gas_record")] tps_gas_displayer: TpsAndGasRecordDisplayer, + #[cfg(feature = "enable_execute_measure")] + execute_txs_displayer: ExecuteTxsDisplayer, } impl DashboardListener { @@ -64,6 +69,8 @@ impl DashboardListener { #[cfg(feature = "enable_tps_gas_record")] tps_gas_displayer: TpsAndGasRecordDisplayer::default(), + #[cfg(feature = "enable_execute_measure")] + execute_txs_displayer: ExecuteTxsDisplayer::default(), } } @@ -110,6 +117,11 @@ impl DashboardListener { self.cache_db_displayer.update_cache_db_record(cache_db_record); self.cache_db_displayer.print(); } + #[cfg(feature = "enable_execute_measure")] + MetricEvent::ExecuteTxsInfo { execute_txs_record } => { + self.execute_txs_displayer.record(execute_txs_record); + self.execute_txs_displayer.print(); + } } } } diff --git a/crates/revm/Cargo.toml b/crates/revm/Cargo.toml index e2ea2a643dab..64b32687f833 100644 --- a/crates/revm/Cargo.toml +++ b/crates/revm/Cargo.toml @@ -25,6 +25,8 @@ revm-utils = { workspace = true, optional = true } # common tracing.workspace = true +ctor = "0.2.5" + [dev-dependencies] reth-rlp.workspace = true once_cell = "1.17.0" @@ -40,4 +42,5 @@ enable_cache_record = [ "revm/enable_cache_record", "reth-provider/enable_cache_record", "revm-utils", -] \ No newline at end of file +] +enable_execute_measure = ["revm-utils"] \ No newline at end of file diff --git a/crates/revm/src/executor.rs b/crates/revm/src/executor.rs index 7a97ec36b5f8..17fd7d3bd5e6 100644 --- a/crates/revm/src/executor.rs +++ b/crates/revm/src/executor.rs @@ -247,6 +247,9 @@ where let mut cumulative_gas_used = 0; let mut post_state = PostState::with_tx_capacity(block.number, block.body.len()); + #[cfg(feature = "enable_execute_measure")] + crate::utils::start_execute_tx_sub_recorder(); + for (transaction, sender) in block.body.iter().zip(senders) { // The sum of the transaction’s gas limit, Tg, and the gas utilised in this block prior, // must be no greater than the block’s gasLimit. @@ -260,6 +263,8 @@ where } // Execute transaction. let ResultAndState { result, state } = self.transact(transaction, sender)?; + #[cfg(feature = "enable_execute_measure")] + crate::utils::transact_record(); #[cfg(feature = "enable_opcode_metrics")] { @@ -276,6 +281,8 @@ where self.chain_spec.fork(Hardfork::SpuriousDragon).active_at_block(block.number), &mut post_state, ); + #[cfg(feature = "enable_execute_measure")] + crate::utils::commit_changes_record(); // append gas used cumulative_gas_used += result.gas_used(); @@ -300,6 +307,8 @@ where logs: result.into_logs().into_iter().map(into_reth_log).collect(), }, ); + #[cfg(feature = "enable_execute_measure")] + crate::utils::add_receipt_record(); } Ok((post_state, cumulative_gas_used)) @@ -349,6 +358,8 @@ where .into()) } + #[cfg(feature = "enable_execute_measure")] + let _record = crate::utils::ApplyPostBlockChangesRecord::new(); self.apply_post_block_changes(block, total_difficulty, post_state) } @@ -358,6 +369,9 @@ where total_difficulty: U256, senders: Option>, ) -> Result { + #[cfg(feature = "enable_execute_measure")] + crate::utils::start_execute_tx_record(); + let post_state = self.execute(block, total_difficulty, senders)?; // TODO Before Byzantium, receipts contained state root that would mean that expensive @@ -371,6 +385,8 @@ where post_state.receipts(block.number).iter(), )?; } + #[cfg(feature = "enable_execute_measure")] + crate::utils::verify_receipt_record(); Ok(post_state) } diff --git a/crates/revm/src/lib.rs b/crates/revm/src/lib.rs index 6a99b020381d..4e8dcd218808 100644 --- a/crates/revm/src/lib.rs +++ b/crates/revm/src/lib.rs @@ -33,3 +33,7 @@ pub use revm; /// Etereum DAO hardfork state change data. pub mod eth_dao_fork; + +/// For perf test. +#[cfg(feature = "enable_execute_measure")] +pub mod utils; diff --git a/crates/revm/src/utils.rs b/crates/revm/src/utils.rs new file mode 100644 index 000000000000..bb074891aa1d --- /dev/null +++ b/crates/revm/src/utils.rs @@ -0,0 +1,199 @@ +use revm_utils::time_utils::instant::Instant; + +/// ExecuteTxsRecord +#[derive(Debug, Clone, Copy, Default)] +pub struct ExecuteTxsRecord { + start_record: Instant, + sub_record: Instant, + + /// time of execute_and_verify_receipt. + total: u64, + /// time of transact. + transact: u64, + /// time of commit changes. + commit_changes: u64, + /// time of add receipt. + add_receipt: u64, + /// time of apply_post_block_changes. + apply_post_block_changes: u64, + /// time of verify_receipt. + verify_receipt: u64, +} + +impl ExecuteTxsRecord { + /// Start record. + fn start_record(&mut self) { + self.start_record = Instant::now(); + } + /// Start sub record. + fn start_sub_recorder(&mut self) { + self.sub_record = Instant::now(); + } + + /// Add time of transact. + fn transact_record(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.transact = self.transact.checked_add(cycles).expect("overflow"); + } + /// Add time of commit changes. + fn commit_changes_record(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.commit_changes = self.commit_changes.checked_add(cycles).expect("overflow"); + } + /// Add time of add receipt. + fn add_receipt_record(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.add_receipt = self.add_receipt.checked_add(cycles).expect("overflow"); + } + /// Add time of apply_post_block_changes. + fn apply_post_block_changes_record(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.apply_post_block_changes = + self.apply_post_block_changes.checked_add(cycles).expect("overflow"); + } + /// Add time of verify_receipt. + fn verify_receipt_record(&mut self) { + let (cycles, now) = self.record_sub_time(); + self.verify_receipt = self.verify_receipt.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.total = self.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) + } +} + +impl ExecuteTxsRecord { + /// Return total. + pub fn total(&self) -> u64 { + self.total + } + /// Return transact. + pub fn transact(&self) -> u64 { + self.transact + } + /// Return commit changes. + pub fn commit_changes(&self) -> u64 { + self.commit_changes + } + /// Return add_receipt. + pub fn add_receipt(&self) -> u64 { + self.add_receipt + } + /// Return apply_post_block_changes. + pub fn apply_post_block_changes(&self) -> u64 { + self.apply_post_block_changes + } + /// Return verify_receipt. + pub fn verify_receipt(&self) -> u64 { + self.verify_receipt + } +} + +// TODO: This variable needs to be merged into a large structural variable later. +static mut METRIC_EXECUTE_TX_RECORD: Option = None; + +#[ctor::ctor] +unsafe fn init() { + METRIC_EXECUTE_TX_RECORD = Some(ExecuteTxsRecord::default()); +} + +/// start execute_tx record. +pub fn start_execute_tx_record() { + unsafe { + METRIC_EXECUTE_TX_RECORD + .as_mut() + .expect("Metric recorder should not empty!") + .start_record(); + } +} + +/// start execute_tx sub record. +pub fn start_execute_tx_sub_recorder() { + unsafe { + METRIC_EXECUTE_TX_RECORD + .as_mut() + .expect("Metric recorder should not empty!") + .start_sub_recorder(); + } +} + +/// transact record +pub fn transact_record() { + unsafe { + METRIC_EXECUTE_TX_RECORD + .as_mut() + .expect("Metric recorder should not empty!") + .transact_record(); + } +} + +/// commit_changes_record +pub fn commit_changes_record() { + unsafe { + METRIC_EXECUTE_TX_RECORD + .as_mut() + .expect("Metric recorder should not empty!") + .commit_changes_record(); + } +} + +/// add_receipt_record +pub fn add_receipt_record() { + unsafe { + METRIC_EXECUTE_TX_RECORD + .as_mut() + .expect("Metric recorder should not empty!") + .add_receipt_record(); + } +} + +/// apply_post_block_changes_record +pub fn apply_post_block_changes_record() { + unsafe { + METRIC_EXECUTE_TX_RECORD + .as_mut() + .expect("Metric recorder should not empty!") + .apply_post_block_changes_record() + } +} + +/// verify_receipt_record +pub fn verify_receipt_record() { + unsafe { + METRIC_EXECUTE_TX_RECORD + .as_mut() + .expect("Metric recorder should not empty!") + .verify_receipt_record(); + } +} + +/// get_execute_tx_record +pub fn get_execute_tx_record() -> ExecuteTxsRecord { + unsafe { METRIC_EXECUTE_TX_RECORD.as_mut().expect("Metric recorder should not empty!").clone() } +} + +/// Record for apply_post_block_changes +pub struct ApplyPostBlockChangesRecord; + +impl ApplyPostBlockChangesRecord { + /// Return ApplyPostBlockChangesRecord. + pub fn new() -> Self { + start_execute_tx_sub_recorder(); + ApplyPostBlockChangesRecord + } +} + +impl Drop for ApplyPostBlockChangesRecord { + fn drop(&mut self) { + apply_post_block_changes_record(); + } +} diff --git a/crates/stages/Cargo.toml b/crates/stages/Cargo.toml index 342b7c46f228..3165fc14470e 100644 --- a/crates/stages/Cargo.toml +++ b/crates/stages/Cargo.toml @@ -50,6 +50,7 @@ num-traits = "0.2.15" serde_json.workspace = true # revm-utils = { git = "https://github.com/megaeth-labs/revm", branch = "andy/debug/performance-dashboard" } revm-utils = { workspace = true, optional = true } +reth-revm = { path = "../revm", optional = true } minstant = { version = "0.1.3", optional = true } @@ -88,6 +89,7 @@ enable_execution_duration_record = ["revm-utils"] enable_tps_gas_record = [] enable_test_max_th = [] enable_db_speed_record =["reth-provider/enable_db_speed_record"] +enable_execute_measure = ["reth-revm/enable_execute_measure"] [[bench]] name = "criterion" diff --git a/crates/stages/src/metrics/listener.rs b/crates/stages/src/metrics/listener.rs index 65e7689618c5..4fda6ac84e56 100644 --- a/crates/stages/src/metrics/listener.rs +++ b/crates/stages/src/metrics/listener.rs @@ -95,6 +95,12 @@ pub enum MetricEvent { /// cache db record. cache_db_record: CacheDbRecord, }, + /// the time required to execute transaction subfunctions + #[cfg(feature = "enable_execute_measure")] + ExecuteTxsInfo { + /// execute txs record + execute_txs_record: reth_revm::utils::ExecuteTxsRecord, + }, } /// Metrics routine that listens to new metric events on the `events_rx` receiver. @@ -195,6 +201,12 @@ impl MetricsListener { MetricEvent::CacheDbInfo { cache_db_record } => { let _ = self.dashboard_events_tx.send(MetricEvent::CacheDbInfo { cache_db_record }); } + #[cfg(feature = "enable_execute_measure")] + MetricEvent::ExecuteTxsInfo { execute_txs_record } => { + let _ = self + .dashboard_events_tx + .send(MetricEvent::ExecuteTxsInfo { execute_txs_record }); + } } } } diff --git a/crates/stages/src/stages/execution.rs b/crates/stages/src/stages/execution.rs index 162f0ff35ce5..9b62a800615f 100644 --- a/crates/stages/src/stages/execution.rs +++ b/crates/stages/src/stages/execution.rs @@ -271,6 +271,13 @@ impl ExecutionStage { let _ = metrics_tx.send(MetricEvent::RevmMetricTime { revm_metric_record: record }); } } + #[cfg(feature = "enable_execute_measure")] + { + let record = reth_revm::utils::get_execute_tx_record(); + if let Some(metrics_tx) = &mut self.metrics_tx { + let _ = metrics_tx.send(MetricEvent::ExecuteTxsInfo { execute_txs_record: record }); + } + } // Write remaining changes trace!(target: "sync::stages::execution", accounts = state.accounts().len(), "Writing updated state to database");