feat: more metrics (#55)

* add more metrics

* range adjustment

* fix

* update grafana

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 = ZkMemoryDb::new();
-            measure_duration_histogram!(
-                build_zktrie_db_duration_microseconds,
+            measure_duration_millis!(
+                build_zktrie_db_duration_milliseconds,
                 l2_trace.build_zktrie_db(&mut zktrie_db)
             );
             Rc::new(zktrie_db)

crates/core/src/chunk.rs

@@ -43,8 +43,8 @@ impl ChunkInfo {
 
         let mut zktrie_db = ZkMemoryDb::new();
         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)
             );
         }

crates/core/src/database.rs

@@ -121,7 +121,7 @@ impl ReadOnlyDB {
 
     /// 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<()> {
@@ -162,41 +162,42 @@ impl DatabaseRef for ReadOnlyDB {
 
     /// Get basic account information.
     fn basic_ref(&self, address: Address) -> Result<Option<AccountInfo>, Self::Error> {
-        Ok(self
-            .zktrie_db_ref
-            .get_account(address.as_slice())
-            .map(|account_data| {
-                let code_size =
-                    u64::from_be_bytes((&account_data[0][16..24]).try_into().unwrap()) as usize;
-                let nonce = u64::from_be_bytes((&account_data[0][24..]).try_into().unwrap());
-                let balance = U256::from_be_bytes(account_data[1]);
-                let code_hash = B256::from(account_data[3]);
-                let poseidon_code_hash = B256::from(account_data[4]);
-
-                let storage_root = B256::from(account_data[2]);
-                self.prev_storage_roots
-                    .borrow_mut()
-                    .entry(address)
-                    .or_insert(storage_root.0.into());
-
-                let zktrie_db = self.zktrie_db.clone();
-                self.storage_trie_refs.borrow_mut().insert(
-                    address,
-                    Lazy::new(Box::new(move || {
-                        zktrie_db
-                            .new_ref_trie(&storage_root.0)
-                            .expect("storage trie associated with account not found")
-                    })),
-                );
-                AccountInfo {
-                    balance,
-                    nonce,
-                    code_size,
-                    code_hash,
-                    poseidon_code_hash,
-                    code: self.code_db.get(&code_hash).cloned(),
-                }
-            }))
+        Ok(measure_duration_micros!(
+            zktrie_get_duration_microseconds,
+            self.zktrie_db_ref.get_account(address.as_slice())
+        )
+        .map(|account_data| {
+            let code_size =
+                u64::from_be_bytes((&account_data[0][16..24]).try_into().unwrap()) as usize;
+            let nonce = u64::from_be_bytes((&account_data[0][24..]).try_into().unwrap());
+            let balance = U256::from_be_bytes(account_data[1]);
+            let code_hash = B256::from(account_data[3]);
+            let poseidon_code_hash = B256::from(account_data[4]);
+
+            let storage_root = B256::from(account_data[2]);
+            self.prev_storage_roots
+                .borrow_mut()
+                .entry(address)
+                .or_insert(storage_root.0.into());
+
+            let zktrie_db = self.zktrie_db.clone();
+            self.storage_trie_refs.borrow_mut().insert(
+                address,
+                Lazy::new(Box::new(move || {
+                    zktrie_db
+                        .new_ref_trie(&storage_root.0)
+                        .expect("storage trie associated with account not found")
+                })),
+            );
+            AccountInfo {
+                balance,
+                nonce,
+                code_size,
+                code_hash,
+                poseidon_code_hash,
+                code: self.code_db.get(&code_hash).cloned(),
+            }
+        }))
     }
 
     /// Get account code by its code hash.
@@ -220,11 +221,12 @@ impl DatabaseRef for ReadOnlyDB {
         let trie = storage_trie_refs
             .entry(address)
             .or_insert_with_key(|address| {
-                let storage_root = self
-                    .zktrie_db_ref
-                    .get_account(address.as_slice())
-                    .map(|account_data| B256::from(account_data[2]))
-                    .unwrap_or_default();
+                let storage_root = measure_duration_micros!(
+                    zktrie_get_duration_microseconds,
+                    self.zktrie_db_ref.get_account(address.as_slice())
+                )
+                .map(|account_data| B256::from(account_data[2]))
+                .unwrap_or_default();
                 let zktrie_db = self.zktrie_db.clone();
                 Lazy::new(Box::new(move || {
                     zktrie_db
@@ -234,10 +236,12 @@ impl DatabaseRef for ReadOnlyDB {
                 }))
             });
 
-        Ok(trie
-            .get_store(&index.to_be_bytes::<32>())
-            .map(|store_data| U256::from_be_bytes(store_data))
-            .unwrap_or_default())
+        Ok(measure_duration_micros!(
+            zktrie_get_duration_microseconds,
+            trie.get_store(&index.to_be_bytes::<32>())
+        )
+        .map(|store_data| U256::from_be_bytes(store_data))
+        .unwrap_or_default())
     }
 
     /// Get block hash by block number.

crates/core/src/executor/mod.rs

@@ -43,8 +43,8 @@ impl EvmExecutor<'_> {
 
     /// 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)
         )?;
 
@@ -139,13 +139,15 @@ impl EvmExecutor<'_> {
 
                 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:#?}");
             }
@@ -159,8 +161,8 @@ impl EvmExecutor<'_> {
 
     /// Commit pending changes in cache db to zktrie
     pub fn commit_changes(&mut self, zktrie_db: &Rc<ZkMemoryDb>) -> B256 {
-        measure_duration_histogram!(
-            commit_changes_duration_microseconds,
+        measure_duration_millis!(
+            commit_changes_duration_milliseconds,
             cycle_track!(self.commit_changes_inner(zktrie_db), "commit_changes")
         )
     }
@@ -203,26 +205,35 @@ impl EvmExecutor<'_> {
                     .expect("unable to get storage trie");
                 for (key, value) in db_acc.storage.iter() {
                     if !value.is_zero() {
-                        cycle_track!(
-                            storage_trie
-                                .update_store(&key.to_be_bytes::<32>(), &value.to_be_bytes())
-                                .expect("failed to update storage"),
-                            "Zktrie::update_store"
+                        measure_duration_micros!(
+                            zktrie_update_duration_microseconds,
+                            cycle_track!(
+                                storage_trie
+                                    .update_store(&key.to_be_bytes::<32>(), &value.to_be_bytes())
+                                    .expect("failed to update storage"),
+                                "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);
                 }
 
-                if storage_trie.is_trie_dirty() {
-                    storage_trie.prepare_root();
-                }
+                measure_duration_micros!(
+                    zktrie_commit_duration_microseconds,
+                    if storage_trie.is_trie_dirty() {
+                        storage_trie.prepare_root();
+                    }
+                );
 
                 cycle_tracker_end!("update storage_tire");
                 storage_root = storage_trie.root().into();
@@ -268,19 +279,25 @@ impl EvmExecutor<'_> {
                 code_hash.0,
                 poseidon_code_hash.0,
             ];
-            cycle_track!(
-                zktrie
-                    .update_account(addr.as_slice(), &acc_data)
-                    .expect("failed to update account"),
-                "Zktrie::update_account"
+            measure_duration_micros!(
+                zktrie_update_duration_microseconds,
+                cycle_track!(
+                    zktrie
+                        .update_account(addr.as_slice(), &acc_data)
+                        .expect("failed to update account"),
+                    "Zktrie::update_account"
+                )
             );
 
             cycle_tracker_end!("commit account {}", addr);
         }
 
-        if zktrie.is_trie_dirty() {
-            zktrie.prepare_root();
-        }
+        measure_duration_micros!(
+            zktrie_commit_duration_microseconds,
+            if zktrie.is_trie_dirty() {
+                zktrie.prepare_root();
+            }
+        );
 
         let root_after = zktrie.root();
 

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,37 @@ 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;
+
+        #[cfg(feature = "metrics")]
+        let __measure_duration_histogram_elasped = __measure_duration_histogram_start.elapsed();
+        #[cfg(feature = "metrics")]
+        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 +133,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