From 6677f170b202aa4e3e8bbc2a801493c864bba684 Mon Sep 17 00:00:00 2001
From: xudaquan2003 <xudaquan2003@gmail.com>
Date: Tue, 17 Oct 2023 15:26:19 +0800
Subject: [PATCH 1/2] add feature 'enable_execution_duration_record'

---
 bin/reth/Cargo.toml                           | 34 ++++++--
 bin/reth/src/node/mod.rs                      |  2 +-
 .../src/performance_metrics/metric_handler.rs |  4 +
 .../src/performance_metrics/metric_recoder.rs |  5 ++
 .../src/performance_metrics/metric_storage.rs |  8 ++
 crates/stages/Cargo.toml                      |  1 +
 crates/stages/src/metrics/listener.rs         | 84 ++++++++++---------
 crates/stages/src/metrics/mod.rs              |  2 +
 crates/stages/src/metrics/sync_metrics.rs     | 11 ++-
 crates/stages/src/metrics/util.rs             | 67 +++++++++++++++
 crates/stages/src/stages/execution.rs         | 81 ++++++++++--------
 11 files changed, 213 insertions(+), 86 deletions(-)
 create mode 100644 crates/stages/src/metrics/util.rs

diff --git a/bin/reth/Cargo.toml b/bin/reth/Cargo.toml
index fd19e879dfee..d44635399d23 100644
--- a/bin/reth/Cargo.toml
+++ b/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,7 +136,11 @@ 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",
@@ -130,9 +148,13 @@ 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"] }
diff --git a/bin/reth/src/node/mod.rs b/bin/reth/src/node/mod.rs
index 92874eefa9e3..63845b7cb97f 100644
--- a/bin/reth/src/node/mod.rs
+++ b/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;
         }),
     );
 }
diff --git a/bin/reth/src/performance_metrics/metric_handler.rs b/bin/reth/src/performance_metrics/metric_handler.rs
index b2be27b18af8..3f52003f88b4 100644
--- a/bin/reth/src/performance_metrics/metric_handler.rs
+++ b/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);
diff --git a/bin/reth/src/performance_metrics/metric_recoder.rs b/bin/reth/src/performance_metrics/metric_recoder.rs
index 8e331f1951a4..890d1be6d7de 100644
--- a/bin/reth/src/performance_metrics/metric_recoder.rs
+++ b/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 =
diff --git a/bin/reth/src/performance_metrics/metric_storage.rs b/bin/reth/src/performance_metrics/metric_storage.rs
index c4a66b118a8b..23e13508370d 100644
--- a/bin/reth/src/performance_metrics/metric_storage.rs
+++ b/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,
diff --git a/crates/stages/Cargo.toml b/crates/stages/Cargo.toml
index 2cd495909126..c295b90fa432 100644
--- a/crates/stages/Cargo.toml
+++ b/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"
diff --git a/crates/stages/src/metrics/listener.rs b/crates/stages/src/metrics/listener.rs
index fb5ecba6dbd1..544a85dadd05 100644
--- a/crates/stages/src/metrics/listener.rs
+++ b/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));
             }
         }
     }
diff --git a/crates/stages/src/metrics/mod.rs b/crates/stages/src/metrics/mod.rs
index bed2742c25fc..4b725df2c696 100644
--- a/crates/stages/src/metrics/mod.rs
+++ b/crates/stages/src/metrics/mod.rs
@@ -1,5 +1,7 @@
 mod listener;
 mod sync_metrics;
+mod util;
 
 pub use listener::{MetricEvent, MetricEventsSender, MetricsListener};
+pub(crate) use util::*;
 use sync_metrics::*;
diff --git a/crates/stages/src/metrics/sync_metrics.rs b/crates/stages/src/metrics/sync_metrics.rs
index 3f99082e9b31..bc65d6f781f4 100644
--- a/crates/stages/src/metrics/sync_metrics.rs
+++ b/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,
 }
diff --git a/crates/stages/src/metrics/util.rs b/crates/stages/src/metrics/util.rs
new file mode 100644
index 000000000000..725f8cfe3d6a
--- /dev/null
+++ b/crates/stages/src/metrics/util.rs
@@ -0,0 +1,67 @@
+
+#[cfg(feature = "enable_execution_duration_record")]
+#[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,
+}
+
+#[cfg(feature = "enable_execution_duration_record")]
+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");
+    }
+}
diff --git a/crates/stages/src/stages/execution.rs b/crates/stages/src/stages/execution.rs
index 50b1f00ce406..b96e600565b4 100644
--- a/crates/stages/src/stages/execution.rs
+++ b/crates/stages/src/stages/execution.rs
@@ -2,6 +2,8 @@ use crate::{
     stages::MERKLE_STAGE_DEFAULT_CLEAN_THRESHOLD, ExecInput, ExecOutput, MetricEvent,
     MetricEventsSender, Stage, StageError, UnwindInput, UnwindOutput,
 };
+#[cfg(feature = "enable_execution_duration_record")]
+use crate::ExecutionDurationRecord;
 use num_traits::Zero;
 use reth_db::{
     cursor::{DbCursorRO, DbCursorRW, DbDupCursorRO},
@@ -24,8 +26,8 @@ use reth_provider::{
 use std::{ops::RangeInclusive, time::Instant};
 use tracing::*;
 
-#[cfg(feature = "open_performance_dashboard")]
-use revm_utils::time::{get_cpu_frequency, TimeRecorder};
+// #[cfg(feature = "open_performance_dashboard")]
+// use revm_utils::time::{get_cpu_frequency, TimeRecorder};
 
 /// The execution stage executes all transactions and
 /// update history indexes.
@@ -117,6 +119,11 @@ impl<EF: ExecutorFactory> ExecutionStage<EF> {
             return Ok(ExecOutput::done(input.checkpoint()))
         }
 
+        #[cfg(feature = "enable_execution_duration_record")]
+        let mut duration_record = ExecutionDurationRecord::default();
+        #[cfg(feature = "enable_execution_duration_record")]
+        duration_record.start_inner_time_recorder();
+
         let start_block = input.next_block();
         let max_block = input.target();
         let prune_modes = self.adjust_prune_modes(provider, start_block, max_block)?;
@@ -142,8 +149,8 @@ impl<EF: ExecutorFactory> ExecutionStage<EF> {
         let mut total_gas = 0u64;
         #[cfg(feature = "open_performance_dashboard")]
         const N: u64 = 1;
-        #[cfg(feature = "open_performance_dashboard")]
-        let cpu_frequency = get_cpu_frequency().expect("Get cpu frequency error!");
+        // #[cfg(feature = "open_performance_dashboard")]
+        // let cpu_frequency = get_cpu_frequency().expect("Get cpu frequency error!");
 
         #[cfg(feature = "open_revm_metrics_record")]
         let mut cnt1 = 0u64;
@@ -151,38 +158,32 @@ impl<EF: ExecutorFactory> ExecutionStage<EF> {
         const N1: u64 = 100;
 
         for block_number in start_block..=max_block {
-            #[cfg(feature = "open_performance_dashboard")]
-            let mut time_record = TimeRecorder::now();
+            #[cfg(feature = "enable_execution_duration_record")]
+            duration_record.start_time_recorder();
             let td = provider
                 .header_td_by_number(block_number)?
                 .ok_or_else(|| ProviderError::HeaderNotFound(block_number.into()))?;
             let block = provider
                 .block_with_senders(block_number)?
                 .ok_or_else(|| ProviderError::BlockNotFound(block_number.into()))?;
-            #[cfg(feature = "open_performance_dashboard")]
-            if let Some(metrics_tx) = &mut self.metrics_tx {
-                let time = time_record.elapsed().to_nanoseconds(cpu_frequency);
-                let _ = metrics_tx.send(MetricEvent::ReadBlockInfoTime { time });
-            }
+            #[cfg(feature = "enable_execution_duration_record")]
+            duration_record.add_read_block();
 
             // Configure the executor to use the current state.
             trace!(target: "sync::stages::execution", number = block_number, txs = block.body.len(), "Executing block");
 
             // Execute the block
             let (block, senders) = block.into_components();
-            #[cfg(feature = "open_performance_dashboard")]
-            let mut time_record = TimeRecorder::now();
+            #[cfg(feature = "enable_execution_duration_record")]
+            duration_record.start_time_recorder();
             let block_state = executor
                 .execute_and_verify_receipt(&block, td, Some(senders))
                 .map_err(|error| StageError::ExecutionError {
                     block: block.header.clone().seal_slow(),
                     error,
                 })?;
-            #[cfg(feature = "open_performance_dashboard")]
-            if let Some(metrics_tx) = &mut self.metrics_tx {
-                let time = time_record.elapsed().to_nanoseconds(cpu_frequency);
-                let _ = metrics_tx.send(MetricEvent::RevmExecuteTxTime { time });
-            }
+            #[cfg(feature = "enable_execution_duration_record")]
+            duration_record.add_execute_tx();
 
             // Gas and txs metrics
             if let Some(metrics_tx) = &mut self.metrics_tx {
@@ -196,8 +197,8 @@ impl<EF: ExecutorFactory> ExecutionStage<EF> {
                         let _ = metrics_tx.send(MetricEvent::ExecutionStageTxs { txs: total_txs });
 
                         println!(
-                            "cnt: {:?}, block_number: {:?}, txs: {:?}, gas: {:?}",
-                            cnt, block_number, total_txs, total_gas
+                        "cnt: {:?}, block_number: {:?}, txs: {:?}, gas: {:?}",
+                        cnt, block_number, total_txs, total_gas
                         );
 
                         total_txs = block.body.len() as u64;
@@ -226,16 +227,13 @@ impl<EF: ExecutorFactory> ExecutionStage<EF> {
             }
 
             // Merge state changes
-            #[cfg(feature = "open_performance_dashboard")]
-            let mut time_record = TimeRecorder::now();
+            #[cfg(feature = "enable_execution_duration_record")]
+            duration_record.start_time_recorder();
             state.extend(block_state);
             stage_progress = block_number;
             stage_checkpoint.progress.processed += block.gas_used;
-            #[cfg(feature = "open_performance_dashboard")]
-            if let Some(metrics_tx) = &mut self.metrics_tx {
-                let time = time_record.elapsed().to_nanoseconds(cpu_frequency);
-                let _ = metrics_tx.send(MetricEvent::PostProcessTime { time });
-            }
+            #[cfg(feature = "enable_execution_duration_record")]
+            duration_record.add_process_state();
 
             // Check if we should commit now
             if self.thresholds.is_end_of_batch(block_number - start_block, state.size_hint() as u64)
@@ -248,20 +246,29 @@ impl<EF: ExecutorFactory> ExecutionStage<EF> {
         // Write remaining changes
         trace!(target: "sync::stages::execution", accounts = state.accounts().len(), "Writing updated state to database");
         let start = Instant::now();
-        #[cfg(feature = "open_performance_dashboard")]
+        #[cfg(feature = "enable_execution_duration_record")]
+        duration_record.start_time_recorder();
+        state.write_to_db(provider.tx_ref(), max_block)?;
+        #[cfg(feature = "enable_execution_duration_record")]
+        duration_record.add_write_to_db();
+        trace!(target: "sync::stages::execution", took = ?start.elapsed(), "Wrote state");
+
+        #[cfg(feature = "enable_execution_duration_record")]
         {
-            let mut time_record = TimeRecorder::now();
-            state.write_to_db(provider.tx_ref(), max_block)?;
-            let time = time_record.elapsed().to_nanoseconds(cpu_frequency);
+            duration_record.add_execute_inner();
+
             if let Some(metrics_tx) = &mut self.metrics_tx {
-                let _ = metrics_tx.send(MetricEvent::WriteToDbTime { time });
+                let _ = metrics_tx.send(MetricEvent::ExecutionStageTime {
+                    execute_inner: duration_record.execute_inner,
+                    read_block: duration_record.read_block,
+                    execute_tx: duration_record.execute_tx,
+                    process_state: duration_record.process_state,
+                    write_to_db: duration_record.write_to_db,
+                });
             }
-            println!("write_to_db ============ {:?} ns", time);
-        }
 
-        #[cfg(not(feature = "open_performance_dashboard"))]
-        state.write_to_db(provider.tx_ref(), max_block)?;
-        trace!(target: "sync::stages::execution", took = ?start.elapsed(), "Wrote state");
+            println!("duration_record: {:?}", duration_record);
+        }
 
         let done = stage_progress == max_block;
         Ok(ExecOutput {

From e0471bbbb4cee4af2a79708e181ef01f2fb4a822 Mon Sep 17 00:00:00 2001
From: xudaquan2003 <xudaquan2003@gmail.com>
Date: Tue, 17 Oct 2023 18:07:33 +0800
Subject: [PATCH 2/2] set 'enable_execution_duration_record' feature for util
 mod

---
 crates/stages/src/metrics/mod.rs  | 2 ++
 crates/stages/src/metrics/util.rs | 3 ---
 2 files changed, 2 insertions(+), 3 deletions(-)

diff --git a/crates/stages/src/metrics/mod.rs b/crates/stages/src/metrics/mod.rs
index 4b725df2c696..fc2ad3f3ab55 100644
--- a/crates/stages/src/metrics/mod.rs
+++ b/crates/stages/src/metrics/mod.rs
@@ -1,7 +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::*;
diff --git a/crates/stages/src/metrics/util.rs b/crates/stages/src/metrics/util.rs
index 725f8cfe3d6a..6a575ed09f46 100644
--- a/crates/stages/src/metrics/util.rs
+++ b/crates/stages/src/metrics/util.rs
@@ -1,5 +1,3 @@
-
-#[cfg(feature = "enable_execution_duration_record")]
 #[derive(Debug, Default)]
 pub(crate) struct ExecutionDurationRecord {
     /// execute inner time recorder
@@ -19,7 +17,6 @@ pub(crate) struct ExecutionDurationRecord {
     pub(crate) write_to_db: u64,
 }
 
-#[cfg(feature = "enable_execution_duration_record")]
 impl ExecutionDurationRecord {
     /// start inner time recorder
     pub(crate) fn start_inner_time_recorder(&mut self) {