Perf: Add metrics for execution txs (#27)

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"] }

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_BIG$}{: >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_BIG$}{: >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()
+}

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<MetricEvent>,
@@ -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();
+            }
         }
     }
 }

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",
-]
+]
+enable_execute_measure = ["revm-utils"]

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<Vec<Address>>,
     ) -> Result<PostState, BlockExecutionError> {
+        #[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)
     }

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;