From 05381ab347a006c89c1a6cbcdf462a15cca92c3c Mon Sep 17 00:00:00 2001 From: Peter Zhang Date: Fri, 25 Oct 2024 13:03:45 +0800 Subject: [PATCH] add detailed metrics in slow operations --- Cargo.lock | 1 + common/append_merkle/Cargo.toml | 3 +++ common/append_merkle/src/lib.rs | 15 +++++++++++++++ common/append_merkle/src/metrics.rs | 11 +++++++++++ node/storage/src/log_store/flow_store.rs | 5 +++++ node/storage/src/log_store/log_manager.rs | 5 +++-- node/storage/src/log_store/metrics.rs | 12 ++++++++++-- 7 files changed, 48 insertions(+), 4 deletions(-) create mode 100644 common/append_merkle/src/metrics.rs diff --git a/Cargo.lock b/Cargo.lock index c964d02..64f030e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -226,6 +226,7 @@ dependencies = [ "itertools 0.13.0", "lazy_static", "lru 0.12.5", + "metrics", "once_cell", "serde", "tiny-keccak", diff --git a/common/append_merkle/Cargo.toml b/common/append_merkle/Cargo.toml index 2b1b8d6..7033875 100644 --- a/common/append_merkle/Cargo.toml +++ b/common/append_merkle/Cargo.toml @@ -13,5 +13,8 @@ serde = { version = "1.0.137", features = ["derive"] } lazy_static = "1.4.0" tracing = "0.1.36" once_cell = "1.19.0" + +metrics = { workspace = true } + itertools = "0.13.0" lru = "0.12.5" \ No newline at end of file diff --git a/common/append_merkle/src/lib.rs b/common/append_merkle/src/lib.rs index 86b550d..ccb7f6d 100644 --- a/common/append_merkle/src/lib.rs +++ b/common/append_merkle/src/lib.rs @@ -1,4 +1,5 @@ mod merkle_tree; +mod metrics; mod node_manager; mod proof; mod sha3; @@ -10,6 +11,7 @@ use std::collections::{BTreeMap, HashMap}; use std::fmt::Debug; use std::marker::PhantomData; use std::sync::Arc; +use std::time::Instant; use tracing::{trace, warn}; use crate::merkle_tree::MerkleTreeWrite; @@ -145,6 +147,7 @@ impl> AppendMerkleTree { } pub fn append(&mut self, new_leaf: E) { + let start_time = Instant::now(); if new_leaf == E::null() { // appending null is not allowed. return; @@ -152,10 +155,13 @@ impl> AppendMerkleTree { self.node_manager.start_transaction(); self.node_manager.push_node(0, new_leaf); self.recompute_after_append_leaves(self.leaves() - 1); + self.node_manager.commit(); + metrics::APPEND.update_since(start_time); } pub fn append_list(&mut self, leaf_list: Vec) { + let start_time = Instant::now(); if leaf_list.contains(&E::null()) { // appending null is not allowed. return; @@ -165,6 +171,7 @@ impl> AppendMerkleTree { self.node_manager.append_nodes(0, &leaf_list); self.recompute_after_append_leaves(start_index); self.node_manager.commit(); + metrics::APPEND_LIST.update_since(start_time); } /// Append a leaf list by providing their intermediate node hash. @@ -173,6 +180,7 @@ impl> AppendMerkleTree { /// Other nodes in the subtree will be set to `null` nodes. /// TODO: Optimize to avoid storing the `null` nodes? pub fn append_subtree(&mut self, subtree_depth: usize, subtree_root: E) -> Result<()> { + let start_time = Instant::now(); if subtree_root == E::null() { // appending null is not allowed. bail!("subtree_root is null"); @@ -182,10 +190,13 @@ impl> AppendMerkleTree { self.append_subtree_inner(subtree_depth, subtree_root)?; self.recompute_after_append_subtree(start_index, subtree_depth - 1); self.node_manager.commit(); + metrics::APPEND_SUBTREE.update_since(start_time); + Ok(()) } pub fn append_subtree_list(&mut self, subtree_list: Vec<(usize, E)>) -> Result<()> { + let start_time = Instant::now(); if subtree_list.iter().any(|(_, root)| root == &E::null()) { // appending null is not allowed. bail!("subtree_list contains null"); @@ -197,12 +208,15 @@ impl> AppendMerkleTree { self.recompute_after_append_subtree(start_index, subtree_depth - 1); } self.node_manager.commit(); + metrics::APPEND_SUBTREE_LIST.update_since(start_time); + Ok(()) } /// Change the value of the last leaf and return the new merkle root. /// This is needed if our merkle-tree in memory only keeps intermediate nodes instead of real leaves. pub fn update_last(&mut self, updated_leaf: E) { + let start_time = Instant::now(); if updated_leaf == E::null() { // updating to null is not allowed. return; @@ -216,6 +230,7 @@ impl> AppendMerkleTree { } self.recompute_after_append_leaves(self.leaves() - 1); self.node_manager.commit(); + metrics::UPDATE_LAST.update_since(start_time); } /// Fill an unknown `null` leaf with its real value. diff --git a/common/append_merkle/src/metrics.rs b/common/append_merkle/src/metrics.rs new file mode 100644 index 0000000..cafa42f --- /dev/null +++ b/common/append_merkle/src/metrics.rs @@ -0,0 +1,11 @@ +use std::sync::Arc; + +use metrics::{register_timer, Timer}; + +lazy_static::lazy_static! { + pub static ref APPEND: Arc = register_timer("append_merkle_append"); + pub static ref APPEND_LIST: Arc = register_timer("append_merkle_append_list"); + pub static ref APPEND_SUBTREE: Arc = register_timer("append_merkle_append_subtree"); + pub static ref APPEND_SUBTREE_LIST: Arc = register_timer("append_merkle_append_subtree_list"); + pub static ref UPDATE_LAST: Arc = register_timer("append_merkle_update_last"); +} diff --git a/node/storage/src/log_store/flow_store.rs b/node/storage/src/log_store/flow_store.rs index 6f75789..c1e3ad9 100644 --- a/node/storage/src/log_store/flow_store.rs +++ b/node/storage/src/log_store/flow_store.rs @@ -208,6 +208,7 @@ impl FlowWrite for FlowStore { /// Return the roots of completed chunks. The order is guaranteed to be increasing /// by chunk index. fn append_entries(&self, data: ChunkArray) -> Result> { + let start_time = Instant::now(); let mut to_seal_set = self.seal_manager.to_seal_set.write(); trace!("append_entries: {} {}", data.start_index, data.data.len()); if data.data.len() % BYTES_PER_SECTOR != 0 { @@ -250,6 +251,8 @@ impl FlowWrite for FlowStore { batch_list.push((chunk_index, batch)); } + + metrics::APPEND_ENTRIES.update_since(start_time); self.data_db.put_entry_batch_list(batch_list) } @@ -359,6 +362,7 @@ impl FlowDBStore { &self, batch_list: Vec<(u64, EntryBatch)>, ) -> Result> { + let start_time = Instant::now(); let mut completed_batches = Vec::new(); let mut tx = self.kvdb.transaction(); for (batch_index, batch) in batch_list { @@ -373,6 +377,7 @@ impl FlowDBStore { } } self.kvdb.write(tx)?; + metrics::PUT_ENTRY_BATCH_LIST.update_since(start_time); Ok(completed_batches) } diff --git a/node/storage/src/log_store/log_manager.rs b/node/storage/src/log_store/log_manager.rs index 874f37e..f94483c 100644 --- a/node/storage/src/log_store/log_manager.rs +++ b/node/storage/src/log_store/log_manager.rs @@ -1,5 +1,3 @@ -use super::tx_store::BlockHashAndSubmissionIndex; -use super::{FlowSeal, MineLoadChunk, SealAnswer, SealTask}; use crate::config::ShardConfig; use crate::log_store::flow_store::{batch_iter_sharded, FlowConfig, FlowDBStore, FlowStore}; use crate::log_store::tx_store::TransactionStore; @@ -1242,6 +1240,7 @@ pub fn sub_merkle_tree(leaf_data: &[u8]) -> Result { } pub fn data_to_merkle_leaves(leaf_data: &[u8]) -> Result> { + let start_time = Instant::now(); if leaf_data.len() % ENTRY_SIZE != 0 { bail!("merkle_tree: mismatched data size"); } @@ -1257,6 +1256,8 @@ pub fn data_to_merkle_leaves(leaf_data: &[u8]) -> Result> { .map(Sha3Algorithm::leaf) .collect() }; + + metrics::DATA_TO_MERKLE_LEAVES.update_since(start_time); Ok(r) } diff --git a/node/storage/src/log_store/metrics.rs b/node/storage/src/log_store/metrics.rs index 2b9ead4..64c480e 100644 --- a/node/storage/src/log_store/metrics.rs +++ b/node/storage/src/log_store/metrics.rs @@ -11,6 +11,9 @@ lazy_static::lazy_static! { pub static ref APPEND_SUBTREE_LIST: Arc = register_timer("log_store_log_manager_append_subtree_list"); + pub static ref DATA_TO_MERKLE_LEAVES: Arc = + register_timer("log_store_log_manager_data_to_merkle_leaves"); + pub static ref COPY_TX_AND_FINALIZE: Arc = register_timer("log_store_log_manager_copy_tx_and_finalize"); @@ -19,7 +22,12 @@ lazy_static::lazy_static! { pub static ref PUT_BATCH_ROOT_LIST: Arc = register_timer("log_store_flow_store_put_batch_root_list"); pub static ref INSERT_SUBTREE_LIST: Arc = - register_timer("log_store_log_manager_insert_subtree_list"); + register_timer("log_store_flow_store_insert_subtree_list"); - pub static ref PUT_MPT_NODE: Arc = register_timer("log_store_log_manager_put_mpt_node"); + pub static ref PUT_MPT_NODE: Arc = register_timer("log_store_flow_store_put_mpt_node"); + + pub static ref PUT_ENTRY_BATCH_LIST: Arc = + register_timer("log_store_flow_store_put_entry_batch_list"); + + pub static ref APPEND_ENTRIES: Arc = register_timer("log_store_flow_store_append_entries"); }