add more metrics

Author: lightsing

crates/bin/src/utils.rs

@@ -9,8 +9,8 @@ pub fn verify<T: Block + Clone>(
     l2_trace: T,
     fork_config: &HardforkConfig,
 ) -> Result<(), VerificationError> {
-    measure_duration_histogram!(
-        total_block_verification_duration_microseconds,
+    measure_duration_millis!(
+        total_block_verification_duration_milliseconds,
         verify_inner(l2_trace, fork_config)
     )
 }
@@ -40,8 +40,8 @@ fn verify_inner<T: Block + Clone>(
     let zktrie_db = cycle_track!(
         {
             let mut zktrie_db = HashMapDb::default();
-            measure_duration_histogram!(
-                build_zktrie_db_duration_microseconds,
+            measure_duration_millis!(
+                build_zktrie_db_duration_milliseconds,
                 l2_trace.build_zktrie_db(&mut zktrie_db).unwrap()
             );
             Rc::new(RefCell::new(zktrie_db))

crates/core/src/chunk.rs

@@ -42,8 +42,8 @@ impl ChunkInfo {
 
         let mut zktrie_db = HashMapDb::default();
         for trace in traces.iter() {
-            measure_duration_histogram!(
-                build_zktrie_db_duration_microseconds,
+            measure_duration_millis!(
+                build_zktrie_db_duration_milliseconds,
                 trace.build_zktrie_db(&mut zktrie_db).unwrap()
             );
         }

crates/core/src/database.rs

@@ -111,7 +111,7 @@ impl<CodeDb: KVDatabase, ZkDb: KVDatabase + Clone + 'static> EvmDatabase<CodeDb,
 
     /// Update the database with a new block trace.
     pub fn update<T: Block>(&mut self, l2_trace: T) -> Result<()> {
-        measure_duration_histogram!(update_db_duration_microseconds, self.update_inner(l2_trace))
+        measure_duration_millis!(update_db_duration_milliseconds, self.update_inner(l2_trace))
     }
 
     fn update_inner<T: Block>(&mut self, l2_trace: T) -> Result<()> {
@@ -155,10 +155,11 @@ impl<CodeDb: KVDatabase, ZkDb: KVDatabase + Clone + 'static> DatabaseRef
 
     /// Get basic account information.
     fn basic_ref(&self, address: Address) -> Result<Option<AccountInfo>> {
-        let Some(account) = self
-            .zktrie
-            .get::<Account, _>(address)
-            .map_err(DatabaseError::zk_trie)?
+        let Some(account) = measure_duration_micros!(
+            zktrie_get_duration_microseconds,
+            self.zktrie.get::<Account, _>(address)
+        )
+        .map_err(DatabaseError::zk_trie)?
         else {
             return Ok(None);
         };
@@ -214,12 +215,13 @@ impl<CodeDb: KVDatabase, ZkDb: KVDatabase + Clone + 'static> DatabaseRef
         let trie = storage_trie_refs
             .entry(address)
             .or_insert_with_key(|address| {
-                let storage_root = self
-                    .zktrie
-                    .get::<Account, _>(address)
-                    .expect("unexpected zktrie error")
-                    .map(|acc| acc.storage_root)
-                    .unwrap_or_default();
+                let storage_root = measure_duration_micros!(
+                    zktrie_get_duration_microseconds,
+                    self.zktrie.get::<Account, _>(address)
+                )
+                .expect("unexpected zktrie error")
+                .map(|acc| acc.storage_root)
+                .unwrap_or_default();
                 dev_debug!("storage root of {:?} is {:?}", address, storage_root);
 
                 let zktrie_db = self.zktrie_db.clone();

crates/core/src/executor/mod.rs

@@ -55,8 +55,8 @@ impl<CodeDb: KVDatabase, ZkDb: KVDatabase + Clone + 'static> EvmExecutor<'_, Cod
 
     /// Handle a block.
     pub fn handle_block<T: Block>(&mut self, l2_trace: &T) -> Result<(), VerificationError> {
-        measure_duration_histogram!(
-            handle_block_duration_microseconds,
+        measure_duration_millis!(
+            handle_block_duration_milliseconds,
             self.handle_block_inner(l2_trace)
         )?;
 
@@ -151,13 +151,15 @@ impl<CodeDb: KVDatabase, ZkDb: KVDatabase + Clone + 'static> EvmExecutor<'_, Cod
 
                 dev_trace!("handler cfg: {:?}", revm.handler.cfg);
 
-                let _result =
+                let _result = measure_duration_millis!(
+                    transact_commit_duration_milliseconds,
                     cycle_track!(revm.transact_commit(), "transact_commit").map_err(|e| {
                         VerificationError::EvmExecution {
                             tx_hash: *tx.tx_hash(),
                             source: e,
                         }
-                    })?;
+                    })?
+                );
 
                 dev_trace!("{_result:#?}");
             }
@@ -171,8 +173,8 @@ impl<CodeDb: KVDatabase, ZkDb: KVDatabase + Clone + 'static> EvmExecutor<'_, Cod
 
     /// Commit pending changes in cache db to zktrie
     pub fn commit_changes(&mut self, zktrie_db: ZkDb) -> Result<B256, DatabaseError> {
-        measure_duration_histogram!(
-            commit_changes_duration_microseconds,
+        measure_duration_millis!(
+            commit_changes_duration_milliseconds,
             cycle_track!(
                 self.commit_changes_inner(zktrie_db)
                     .map_err(DatabaseError::zk_trie),
@@ -225,22 +227,31 @@ impl<CodeDb: KVDatabase, ZkDb: KVDatabase + Clone + 'static> EvmExecutor<'_, Cod
                 .expect("unable to get storage trie");
                 for (key, value) in db_acc.storage.iter() {
                     if !value.is_zero() {
-                        cycle_track!(
-                            storage_trie.update(key.to_be_bytes::<32>(), value)?,
-                            "Zktrie::update_store"
+                        measure_duration_micros!(
+                            zktrie_update_duration_microseconds,
+                            cycle_track!(
+                                storage_trie.update(key.to_be_bytes::<32>(), value)?,
+                                "Zktrie::update_store"
+                            )
                         );
                     } else {
-                        cycle_track!(
-                            storage_trie.delete(key.to_be_bytes::<32>())?,
-                            "Zktrie::delete"
+                        measure_duration_micros!(
+                            zktrie_delete_duration_microseconds,
+                            cycle_track!(
+                                storage_trie.delete(key.to_be_bytes::<32>())?,
+                                "Zktrie::delete"
+                            )
                         );
                     }
 
                     #[cfg(feature = "debug-storage")]
                     debug_recorder.record_storage(*addr, *key, *value);
                 }
 
-                storage_trie.commit()?;
+                measure_duration_micros!(
+                    zktrie_commit_duration_microseconds,
+                    storage_trie.commit()?
+                );
 
                 cycle_tracker_end!("update storage_tire");
                 storage_root = *storage_trie.root().unwrap_ref();
@@ -272,17 +283,20 @@ impl<CodeDb: KVDatabase, ZkDb: KVDatabase + Clone + 'static> EvmExecutor<'_, Cod
             debug_recorder.record_account(*addr, info.clone(), storage_root);
 
             let acc_data = Account::from_revm_account_with_storage_root(info, storage_root);
-            cycle_track!(
-                zktrie
-                    .update(addr, acc_data)
-                    .expect("failed to update account"),
-                "Zktrie::update_account"
+            measure_duration_micros!(
+                zktrie_update_duration_microseconds,
+                cycle_track!(
+                    zktrie
+                        .update(addr, acc_data)
+                        .expect("failed to update account"),
+                    "Zktrie::update_account"
+                )
             );
 
             cycle_tracker_end!("commit account {}", addr);
         }
 
-        zktrie.commit()?;
+        measure_duration_micros!(zktrie_commit_duration_microseconds, zktrie.commit()?);
 
         let root_after = *zktrie.root().unwrap_ref();
 

crates/sbv/src/lib.rs

@@ -6,5 +6,5 @@ pub use sbv_utils as utils;
 
 pub use sbv_utils::{
     cycle_track, cycle_tracker_end, cycle_tracker_start, dev_debug, dev_error, dev_info, dev_trace,
-    dev_warn, measure_duration_histogram, update_metrics_counter, update_metrics_gauge,
+    dev_warn, measure_duration_millis, update_metrics_counter, update_metrics_gauge,
 };

crates/utils/src/macros.rs

@@ -92,7 +92,35 @@ macro_rules! dev_warn {
 
 /// This macro is for measuring duration to metrics
 #[macro_export]
-macro_rules! measure_duration_histogram {
+macro_rules! measure_duration_millis {
+    ($label:ident, $e:expr) => {{
+        #[cfg(feature = "metrics")]
+        let __measure_duration_histogram_start = std::time::Instant::now();
+
+        #[allow(clippy::let_and_return)]
+        let __measure_duration_histogram_result = $e;
+
+        let __measure_duration_histogram_elasped = __measure_duration_histogram_start.elapsed();
+        let __duration_millis = __measure_duration_histogram_elasped.as_secs() as f64 * 1_000.0
+            + __measure_duration_histogram_elasped.subsec_nanos() as f64 / 1_000_000.0;
+
+        #[cfg(feature = "metrics")]
+        $crate::metrics::REGISTRY.$label.observe(__duration_millis);
+
+        #[cfg(feature = "metrics")]
+        dev_debug!(
+            "measured duration {} = {:?}ms",
+            stringify!($label),
+            __duration_millis,
+        );
+
+        __measure_duration_histogram_result
+    }};
+}
+
+/// This macro is for measuring duration to metrics
+#[macro_export]
+macro_rules! measure_duration_micros {
     ($label:ident, $e:expr) => {{
         #[cfg(feature = "metrics")]
         let __measure_duration_histogram_start = std::time::Instant::now();
@@ -103,13 +131,13 @@ macro_rules! measure_duration_histogram {
         #[cfg(feature = "metrics")]
         $crate::metrics::REGISTRY
             .$label
-            .observe(__measure_duration_histogram_start.elapsed().as_millis() as f64);
+            .observe(__measure_duration_histogram_start.elapsed().as_micros() as f64);
 
         #[cfg(feature = "metrics")]
         dev_debug!(
-            "measured duration {} = {:?}",
+            "measured duration {} = {:?}us",
             stringify!($label),
-            __measure_duration_histogram_start.elapsed(),
+            __measure_duration_histogram_start.elapsed().as_micros() as f64,
         );
 
         __measure_duration_histogram_result

crates/utils/src/metrics/registry.rs

@@ -17,11 +17,19 @@ pub struct Registry {
 
     pub verification_error: Counter,
 
-    pub build_zktrie_db_duration_microseconds: Histogram,
-    pub update_db_duration_microseconds: Histogram,
-    pub handle_block_duration_microseconds: Histogram,
-    pub commit_changes_duration_microseconds: Histogram,
-    pub total_block_verification_duration_microseconds: Histogram,
+    // database metrics
+    pub build_zktrie_db_duration_milliseconds: Histogram,
+    pub update_db_duration_milliseconds: Histogram,
+    pub zktrie_get_duration_microseconds: Histogram,
+    pub zktrie_update_duration_microseconds: Histogram,
+    pub zktrie_delete_duration_microseconds: Histogram,
+    pub zktrie_commit_duration_microseconds: Histogram,
+
+    // executor metrics
+    pub transact_commit_duration_milliseconds: Histogram,
+    pub handle_block_duration_milliseconds: Histogram,
+    pub commit_changes_duration_milliseconds: Histogram,
+    pub total_block_verification_duration_milliseconds: Histogram,
 }
 
 pub(super) fn init() -> Registry {
@@ -55,40 +63,75 @@ pub(super) fn init() -> Registry {
         verification_error.clone(),
     );
 
-    let build_zktrie_db_duration_microseconds = Histogram::new(linear_buckets(50.0, 50.0, 10));
+    let build_zktrie_db_duration_milliseconds = Histogram::new(linear_buckets(50.0, 50.0, 10));
     registry.register(
         "build_zktrie_db_duration",
-        "Duration of build_zktrie_db_duration in microseconds",
-        build_zktrie_db_duration_microseconds.clone(),
+        "Duration of build_zktrie_db_duration in milliseconds",
+        build_zktrie_db_duration_milliseconds.clone(),
     );
 
-    let update_db_duration_microseconds = Histogram::new(linear_buckets(2.0, 4.0, 10));
+    let update_db_duration_milliseconds = Histogram::new(linear_buckets(2.0, 4.0, 10));
     registry.register(
         "update_db_duration",
-        "Duration of update_db in microseconds",
-        update_db_duration_microseconds.clone(),
+        "Duration of update_db in milliseconds",
+        update_db_duration_milliseconds.clone(),
     );
 
-    let handle_block_duration_microseconds = Histogram::new(linear_buckets(1.0, 5.0, 10));
+    let zktrie_get_duration_microseconds = Histogram::new(linear_buckets(0.1, 1.0, 10));
+    registry.register(
+        "zktrie_get_duration",
+        "Duration of zktrie_get in microseconds",
+        zktrie_get_duration_microseconds.clone(),
+    );
+
+    let zktrie_update_duration_microseconds = Histogram::new(linear_buckets(50.0, 500.0, 10));
+    registry.register(
+        "zktrie_update_duration",
+        "Duration of zktrie_update in microseconds",
+        zktrie_update_duration_microseconds.clone(),
+    );
+
+    let zktrie_delete_duration_microseconds = Histogram::new(linear_buckets(50.0, 500.0, 10));
+    registry.register(
+        "zktrie_delete_duration",
+        "Duration of zktrie_delete in microseconds",
+        zktrie_delete_duration_microseconds.clone(),
+    );
+
+    let zktrie_commit_duration_microseconds = Histogram::new(linear_buckets(100.0, 2000.0, 10));
+    registry.register(
+        "zktrie_commit_duration",
+        "Duration of zktrie_commit in microseconds",
+        zktrie_commit_duration_microseconds.clone(),
+    );
+
+    let transact_commit_duration_milliseconds = Histogram::new(linear_buckets(0.1, 15.0, 10));
+    registry.register(
+        "transact_commit_duration",
+        "Duration of transact_commit in milliseconds",
+        transact_commit_duration_milliseconds.clone(),
+    );
+
+    let handle_block_duration_milliseconds = Histogram::new(linear_buckets(1.0, 5.0, 10));
     registry.register(
         "handle_block_duration",
-        "Duration of handle_block in microseconds",
-        handle_block_duration_microseconds.clone(),
+        "Duration of handle_block in milliseconds",
+        handle_block_duration_milliseconds.clone(),
     );
 
-    let commit_changes_duration_microseconds = Histogram::new(linear_buckets(25.0, 50.0, 10));
+    let commit_changes_duration_milliseconds = Histogram::new(linear_buckets(25.0, 50.0, 10));
     registry.register(
         "commit_changes_duration",
-        "Duration of commit_changes in microseconds",
-        commit_changes_duration_microseconds.clone(),
+        "Duration of commit_changes in milliseconds",
+        commit_changes_duration_milliseconds.clone(),
     );
 
-    let total_block_verification_duration_microseconds =
+    let total_block_verification_duration_milliseconds =
         Histogram::new(linear_buckets(50.0, 50.0, 15));
     registry.register(
         "total_block_verification_duration",
-        "Total block verification duration in microseconds",
-        total_block_verification_duration_microseconds.clone(),
+        "Total block verification duration in milliseconds",
+        total_block_verification_duration_milliseconds.clone(),
     );
 
     Registry {
@@ -100,10 +143,16 @@ pub(super) fn init() -> Registry {
 
         verification_error,
 
-        build_zktrie_db_duration_microseconds,
-        update_db_duration_microseconds,
-        handle_block_duration_microseconds,
-        commit_changes_duration_microseconds,
-        total_block_verification_duration_microseconds,
+        build_zktrie_db_duration_milliseconds,
+        update_db_duration_milliseconds,
+        zktrie_get_duration_microseconds,
+        zktrie_update_duration_microseconds,
+        zktrie_delete_duration_microseconds,
+        zktrie_commit_duration_microseconds,
+
+        handle_block_duration_milliseconds,
+        transact_commit_duration_milliseconds,
+        commit_changes_duration_milliseconds,
+        total_block_verification_duration_milliseconds,
     }
 }