add feature 'enable_execution_duration_record' (#6)

* add feature 'enable_execution_duration_record'

* set 'enable_execution_duration_record' feature for util mod

bin/reth/Cargo.toml

@@ -20,7 +20,10 @@ normal = [
 # reth
 reth-config = { path = "../../crates/config" }
 reth-primitives = { workspace = true, features = ["arbitrary"] }
-reth-db = { path = "../../crates/storage/db", features = ["mdbx", "test-utils"] }
+reth-db = { path = "../../crates/storage/db", features = [
+    "mdbx",
+    "test-utils",
+] }
 # TODO: Temporary use of the test-utils feature
 reth-provider = { workspace = true, features = ["test-utils"] }
 reth-revm = { path = "../../crates/revm" }
@@ -40,7 +43,9 @@ reth-rpc-api = { path = "../../crates/rpc/rpc-api" }
 reth-rlp.workspace = true
 reth-network = { path = "../../crates/net/network", features = ["serde"] }
 reth-network-api.workspace = true
-reth-downloaders = { path = "../../crates/net/downloaders", features = ["test-utils"] }
+reth-downloaders = { path = "../../crates/net/downloaders", features = [
+    "test-utils",
+] }
 reth-tracing = { path = "../../crates/tracing" }
 reth-tasks.workspace = true
 reth-net-nat = { path = "../../crates/net/nat" }
@@ -51,7 +56,11 @@ reth-prune = { path = "../../crates/prune" }
 reth-trie = { path = "../../crates/trie" }
 
 # crypto
-secp256k1 = { workspace = true, features = ["global-context", "rand-std", "recovery"] }
+secp256k1 = { workspace = true, features = [
+    "global-context",
+    "rand-std",
+    "recovery",
+] }
 
 # tracing
 tracing.workspace = true
@@ -83,7 +92,12 @@ tui = "0.19.0"
 human_bytes = "0.4.1"
 
 # async
-tokio = { workspace = true, features = ["sync", "macros", "time", "rt-multi-thread"] }
+tokio = { workspace = true, features = [
+    "sync",
+    "macros",
+    "time",
+    "rt-multi-thread",
+] }
 futures.workspace = true
 pin-project.workspace = true
 
@@ -122,17 +136,25 @@ min-warn-logs = ["tracing/release_max_level_warn"]
 min-info-logs = ["tracing/release_max_level_info"]
 min-debug-logs = ["tracing/release_max_level_debug"]
 min-trace-logs = ["tracing/release_max_level_trace"]
-open_performance_dashboard = ["reth-stages/open_performance_dashboard", "revm-utils", "parking_lot"]
+open_performance_dashboard = [
+    "reth-stages/open_performance_dashboard",
+    "revm-utils",
+    "parking_lot",
+]
 open_revm_metrics_record = [
     "reth-revm/open_revm_metrics_record",
     "reth-revm-inspectors/open_revm_metrics_record",
     "reth-rpc-builder/open_revm_metrics_record",
     "reth-basic-payload-builder/open_revm_metrics_record",
     "reth-provider/open_revm_metrics_record",
     "reth-stages/open_revm_metrics_record",
-    ]
+]
 open_revm_instruction_log = ["reth-revm/open_revm_instruction_log"]
 finish_after_execution_stage = ["reth-stages/finish_after_execution_stage"]
+enable_execution_duration_record = [
+    "reth-stages/enable_execution_duration_record",
+    "open_performance_dashboard",
+]
 
 [build-dependencies]
 vergen = { version = "8.0.0", features = ["build", "cargo", "git", "gitcl"] }

bin/reth/src/node/mod.rs

@@ -945,7 +945,7 @@ fn start_performance_dashboard(task_executor: &TaskExecutor) {
     task_executor.spawn_critical(
         "performance dashboard",
         Box::pin(async move {
-            performance_dashboard_handler.run(300).await;
+            performance_dashboard_handler.run(3).await;
         }),
     );
 }

bin/reth/src/performance_metrics/metric_handler.rs

@@ -51,6 +51,10 @@ impl PerformanceDashboardMetricHandler {
                     self.cnt += 1;
 
                     // 3. total
+                    let execute_inner_time = snapshot.execute_inner_time;
+                    if execute_inner_time != 0 {
+                        info!(target: "performance_dashboard_metrics.sync_stage.execution", "execute inner time =====> {:?}", execute_inner_time);
+                    }
                     let read_block_info_time = snapshot.read_block_info_time;
                     if read_block_info_time != 0 {
                         info!(target: "performance_dashboard_metrics.sync_stage.execution", "total read block info time =====> {:?}", read_block_info_time);

bin/reth/src/performance_metrics/metric_recoder.rs

@@ -24,6 +24,11 @@ impl CounterFn for Handle {
                 let mut guard = self.storage.total_txs_processed.lock();
                 *guard = (*guard).checked_add(value).expect("counter txs_processed_total overflow");
             }
+            "sync.execution.execute_inner_time" => {
+                let mut guard = self.storage.execute_inner_time.lock();
+                *guard =
+                    (*guard).checked_add(value).expect("counter execute_inner_time overflow");
+            }
             "sync.execution.read_block_info_time" => {
                 let mut guard = self.storage.read_block_info_time.lock();
                 *guard =

bin/reth/src/performance_metrics/metric_storage.rs

@@ -5,6 +5,7 @@ use std::sync::Arc;
 pub(crate) struct PerformanceDashboardMetricStorage {
     pub(crate) total_mgas_used: Arc<Mutex<f64>>,
     pub(crate) total_txs_processed: Arc<Mutex<u64>>,
+    pub(crate) execute_inner_time: Arc<Mutex<u64>>,
     pub(crate) read_block_info_time: Arc<Mutex<u64>>,
     pub(crate) revm_execute_time: Arc<Mutex<u64>>,
     pub(crate) post_process_time: Arc<Mutex<u64>>,
@@ -20,6 +21,7 @@ impl PerformanceDashboardMetricStorage {
 pub(crate) struct MetricsStorage {
     pub(crate) total_mgas_used: f64,
     pub(crate) total_txs_processed: u64,
+    pub(crate) execute_inner_time: u64,
     pub(crate) read_block_info_time: u64,
     pub(crate) revm_execute_time: u64,
     pub(crate) post_process_time: u64,
@@ -38,6 +40,11 @@ impl From<&PerformanceDashboardMetricStorage> for MetricsStorage {
             *guard
         };
 
+        let execute_inner_time = {
+            let guard = storage.execute_inner_time.lock();
+            *guard
+        };
+
         let read_block_info_time = {
             let guard = storage.read_block_info_time.lock();
             *guard
@@ -61,6 +68,7 @@ impl From<&PerformanceDashboardMetricStorage> for MetricsStorage {
         Self {
             total_mgas_used,
             total_txs_processed,
+            execute_inner_time,
             read_block_info_time,
             revm_execute_time,
             post_process_time,

crates/stages/Cargo.toml

@@ -80,6 +80,7 @@ test-utils = ["reth-interfaces/test-utils"]
 open_performance_dashboard = []
 open_revm_metrics_record = ["reth-provider/open_revm_metrics_record"]
 finish_after_execution_stage = []
+enable_execution_duration_record = []
 
 [[bench]]
 name = "criterion"

crates/stages/src/metrics/listener.rs

@@ -12,6 +12,9 @@ use std::{
 use tokio::sync::mpsc::{UnboundedReceiver, UnboundedSender};
 use tracing::trace;
 
+#[cfg(feature = "enable_execution_duration_record")]
+use revm_utils::time::{convert_to_nanoseconds, get_cpu_frequency};
+
 // #[cfg(feature = "open_revm_metrics_record")]
 // use revm_utils::types::RevmMetricRecord;
 
@@ -55,29 +58,19 @@ pub enum MetricEvent {
     //     /// size of cacheDb.
     //     cachedb_size: usize,
     // },
-    /// Time of get block info.
-    #[cfg(feature = "open_performance_dashboard")]
-    ReadBlockInfoTime {
-        /// time.
-        time: u64,
-    },
-    /// Time of revm execute tx.
-    #[cfg(feature = "open_performance_dashboard")]
-    RevmExecuteTxTime {
-        /// time.
-        time: u64,
-    },
-    /// Post process time.
-    #[cfg(feature = "open_performance_dashboard")]
-    PostProcessTime {
-        /// time.
-        time: u64,
-    },
-    /// Time of write to db.
-    #[cfg(feature = "open_performance_dashboard")]
-    WriteToDbTime {
-        /// time.
-        time: u64,
+    /// Execution stage processed .
+    #[cfg(feature = "enable_execution_duration_record")]
+    ExecutionStageTime {
+        /// total time of execute_inner
+        execute_inner: u64,
+        /// total time of  get block td and block_with_senders
+        read_block: u64,
+        /// time of revm execute tx(execute_and_verify_receipt)
+        execute_tx: u64,
+        /// time of process state(state.extend)
+        process_state: u64,
+        /// time of write to db
+        write_to_db: u64,
     },
 }
 
@@ -135,21 +128,36 @@ impl MetricsListener {
             MetricEvent::ExecutionStageTxs { txs } => {
                 self.sync_metrics.execution_stage.txs_processed_total.increment(txs)
             }
-            #[cfg(feature = "open_performance_dashboard")]
-            MetricEvent::ReadBlockInfoTime { time } => {
-                self.sync_metrics.execution_stage.read_block_info_time.increment(time)
-            }
-            #[cfg(feature = "open_performance_dashboard")]
-            MetricEvent::RevmExecuteTxTime { time } => {
-                self.sync_metrics.execution_stage.revm_execute_time.increment(time)
-            }
-            #[cfg(feature = "open_performance_dashboard")]
-            MetricEvent::PostProcessTime { time } => {
-                self.sync_metrics.execution_stage.post_process_time.increment(time)
-            }
-            #[cfg(feature = "open_performance_dashboard")]
-            MetricEvent::WriteToDbTime { time } => {
-                self.sync_metrics.execution_stage.write_to_db_time.increment(time)
+            #[cfg(feature = "enable_execution_duration_record")]
+            MetricEvent::ExecutionStageTime {
+                execute_inner,
+                read_block,
+                execute_tx,
+                process_state,
+                write_to_db,
+            } => {
+                let cpu_frequency = get_cpu_frequency().expect("Get cpu frequency error!");
+
+                self.sync_metrics
+                    .execution_stage
+                    .execute_inner_time
+                    .increment(convert_to_nanoseconds(execute_inner, cpu_frequency));
+                self.sync_metrics
+                    .execution_stage
+                    .read_block_info_time
+                    .increment(convert_to_nanoseconds(read_block, cpu_frequency));
+                self.sync_metrics
+                    .execution_stage
+                    .revm_execute_time
+                    .increment(convert_to_nanoseconds(execute_tx, cpu_frequency));
+                self.sync_metrics
+                    .execution_stage
+                    .post_process_time
+                    .increment(convert_to_nanoseconds(process_state, cpu_frequency));
+                self.sync_metrics
+                    .execution_stage
+                    .write_to_db_time
+                    .increment(convert_to_nanoseconds(write_to_db, cpu_frequency));
             }
         }
     }

crates/stages/src/metrics/mod.rs

@@ -1,5 +1,9 @@
 mod listener;
 mod sync_metrics;
+#[cfg(feature = "enable_execution_duration_record")]
+mod util;
 
 pub use listener::{MetricEvent, MetricEventsSender, MetricsListener};
+#[cfg(feature = "enable_execution_duration_record")]
+pub(crate) use util::*;
 use sync_metrics::*;

crates/stages/src/metrics/sync_metrics.rs

@@ -40,16 +40,19 @@ pub(crate) struct ExecutionStageMetrics {
     #[cfg(feature = "open_performance_dashboard")]
     pub(crate) txs_processed_total: Counter,
     #[cfg(feature = "open_performance_dashboard")]
+    /// Time of execute inner.
+    #[cfg(feature = "enable_execution_duration_record")]
+    pub(crate) execute_inner_time: Counter,
     /// Time of read block info.
-    #[cfg(feature = "open_performance_dashboard")]
+    #[cfg(feature = "enable_execution_duration_record")]
     pub(crate) read_block_info_time: Counter,
     /// Time of revm execute tx.
-    #[cfg(feature = "open_performance_dashboard")]
+    #[cfg(feature = "enable_execution_duration_record")]
     pub(crate) revm_execute_time: Counter,
     /// Post process time.
-    #[cfg(feature = "open_performance_dashboard")]
+    #[cfg(feature = "enable_execution_duration_record")]
     pub(crate) post_process_time: Counter,
     /// Time of write to db.
-    #[cfg(feature = "open_performance_dashboard")]
+    #[cfg(feature = "enable_execution_duration_record")]
     pub(crate) write_to_db_time: Counter,
 }

crates/stages/src/metrics/util.rs

@@ -0,0 +1,64 @@
+#[derive(Debug, Default)]
+pub(crate) struct ExecutionDurationRecord {
+    /// execute inner time recorder
+    inner_recorder: revm_utils::time::TimeRecorder,
+    /// time recorder
+    time_recorder: revm_utils::time::TimeRecorder,
+
+    /// total time of execute_inner
+    pub(crate) execute_inner: u64,
+    /// total time of  get block td and block_with_senders
+    pub(crate) read_block: u64,
+    /// time of revm execute tx(execute_and_verify_receipt)
+    pub(crate) execute_tx: u64,
+    /// time of process state(state.extend)
+    pub(crate) process_state: u64,
+    /// time of write to db
+    pub(crate) write_to_db: u64,
+}
+
+impl ExecutionDurationRecord {
+    /// start inner time recorder
+    pub(crate) fn start_inner_time_recorder(&mut self) {
+        self.inner_recorder = revm_utils::time::TimeRecorder::now();
+    }
+    /// start time recorder
+    pub(crate) fn start_time_recorder(&mut self) {
+        self.time_recorder = revm_utils::time::TimeRecorder::now();
+    }
+    /// add time of execute_inner
+    pub(crate) fn add_execute_inner(&mut self) {
+        self.execute_inner = self
+            .execute_inner
+            .checked_add(self.inner_recorder.elapsed().to_cycles())
+            .expect("overflow");
+    }
+    /// add time of get block td and block_with_senders
+    pub(crate) fn add_read_block(&mut self) {
+        self.read_block = self
+            .read_block
+            .checked_add(self.time_recorder.elapsed().to_cycles())
+            .expect("overflow");
+    }
+    /// add time of revm execute tx
+    pub(crate) fn add_execute_tx(&mut self) {
+        self.execute_tx = self
+            .execute_tx
+            .checked_add(self.time_recorder.elapsed().to_cycles())
+            .expect("overflow");
+    }
+    /// add time of process state
+    pub(crate) fn add_process_state(&mut self) {
+        self.process_state = self
+            .process_state
+            .checked_add(self.time_recorder.elapsed().to_cycles())
+            .expect("overflow");
+    }
+    /// add time of write to db
+    pub(crate) fn add_write_to_db(&mut self) {
+        self.write_to_db = self
+            .write_to_db
+            .checked_add(self.time_recorder.elapsed().to_cycles())
+            .expect("overflow");
+    }
+}