From d5541abdd88895fc1f43cea890dce8218cd9d1ec Mon Sep 17 00:00:00 2001 From: Peter Zhang Date: Fri, 25 Oct 2024 11:59:26 +0800 Subject: [PATCH] add detailed metrics in slow operations --- node/storage/src/log_store/flow_store.rs | 24 +++++++++++++++++------ node/storage/src/log_store/log_manager.rs | 3 +++ node/storage/src/log_store/metrics.rs | 11 +++++++++++ node/storage/src/log_store/tx_store.rs | 8 ++++++-- 4 files changed, 38 insertions(+), 8 deletions(-) diff --git a/node/storage/src/log_store/flow_store.rs b/node/storage/src/log_store/flow_store.rs index 37ee1e2..687386c 100644 --- a/node/storage/src/log_store/flow_store.rs +++ b/node/storage/src/log_store/flow_store.rs @@ -1,13 +1,14 @@ -use super::load_chunk::EntryBatch; -use super::seal_task_manager::SealTaskManager; -use super::{MineLoadChunk, SealAnswer, SealTask}; use crate::config::ShardConfig; use crate::error::Error; +use crate::log_store::load_chunk::EntryBatch; use crate::log_store::log_manager::{ bytes_to_entries, data_to_merkle_leaves, COL_ENTRY_BATCH, COL_ENTRY_BATCH_ROOT, COL_FLOW_MPT_NODES, ENTRY_SIZE, PORA_CHUNK_SIZE, }; -use crate::log_store::{FlowRead, FlowSeal, FlowWrite}; +use crate::log_store::seal_task_manager::SealTaskManager; +use crate::log_store::{ + metrics, FlowRead, FlowSeal, FlowWrite, MineLoadChunk, SealAnswer, SealTask, +}; use crate::{try_option, ZgsKeyValueDB}; use anyhow::{anyhow, bail, Result}; use append_merkle::{MerkleTreeInitialData, MerkleTreeRead}; @@ -20,6 +21,7 @@ use std::cmp::Ordering; use std::collections::BTreeMap; use std::fmt::Debug; use std::sync::Arc; +use std::time::Instant; use std::{cmp, mem}; use tracing::{debug, error, trace}; use zgs_spec::{BYTES_PER_SECTOR, SEALS_PER_LOAD, SECTORS_PER_LOAD, SECTORS_PER_SEAL}; @@ -40,7 +42,11 @@ impl FlowStore { } pub fn put_batch_root_list(&self, root_map: BTreeMap) -> Result<()> { - self.db.put_batch_root_list(root_map) + let start_time = Instant::now(); + let res = self.db.put_batch_root_list(root_map); + + metrics::PUT_BATCH_ROOT_LIST.update_since(start_time); + res } pub fn insert_subtree_list_for_batch( @@ -48,6 +54,7 @@ impl FlowStore { batch_index: usize, subtree_list: Vec<(usize, usize, DataRoot)>, ) -> Result<()> { + let start_time = Instant::now(); let mut batch = self .db .get_entry_batch(batch_index as u64)? @@ -55,6 +62,8 @@ impl FlowStore { batch.set_subtree_list(subtree_list); self.db.put_entry_raw(vec![(batch_index as u64, batch)])?; + metrics::INSERT_SUBTREE_LIST.update_since(start_time); + Ok(()) } @@ -73,7 +82,10 @@ impl FlowStore { } pub fn put_mpt_node_list(&self, node_list: Vec<(usize, usize, DataRoot)>) -> Result<()> { - self.db.put_mpt_node_list(node_list) + let start_time = Instant::now(); + let res = self.db.put_mpt_node_list(node_list); + metrics::PUT_MPT_NODE.update_since(start_time); + res } pub fn delete_batch_list(&self, batch_list: &[u64]) -> Result<()> { diff --git a/node/storage/src/log_store/log_manager.rs b/node/storage/src/log_store/log_manager.rs index 2b55863..b9cdcc0 100644 --- a/node/storage/src/log_store/log_manager.rs +++ b/node/storage/src/log_store/log_manager.rs @@ -936,6 +936,7 @@ impl LogManager { #[instrument(skip(self, merkle))] fn pad_tx(&self, tx_start_index: u64, merkle: &mut MerkleManager) -> Result<()> { // Check if we need to pad the flow. + let start_time = Instant::now(); let mut tx_start_flow_index = merkle.last_chunk_start_index() + merkle.last_chunk_merkle.leaves() as u64; let pad_size = tx_start_index - tx_start_flow_index; @@ -1025,6 +1026,8 @@ impl LogManager { merkle.pora_chunks_merkle.leaves(), merkle.last_chunk_merkle.leaves() ); + + metrics::PAD_TX.update_since(start_time); Ok(()) } diff --git a/node/storage/src/log_store/metrics.rs b/node/storage/src/log_store/metrics.rs index 9757615..2b9ead4 100644 --- a/node/storage/src/log_store/metrics.rs +++ b/node/storage/src/log_store/metrics.rs @@ -5,10 +5,21 @@ use metrics::{register_timer, Timer}; lazy_static::lazy_static! { pub static ref TX_STORE_PUT: Arc = register_timer("log_store_tx_store_put_tx"); + pub static ref CHECK_TX_COMPLETED: Arc = + register_timer("log_store_log_manager_check_tx_completed"); pub static ref APPEND_SUBTREE_LIST: Arc = register_timer("log_store_log_manager_append_subtree_list"); pub static ref COPY_TX_AND_FINALIZE: Arc = register_timer("log_store_log_manager_copy_tx_and_finalize"); + + pub static ref PAD_TX: Arc = register_timer("log_store_log_manager_pad_tx"); + + 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"); + + pub static ref PUT_MPT_NODE: Arc = register_timer("log_store_log_manager_put_mpt_node"); } diff --git a/node/storage/src/log_store/tx_store.rs b/node/storage/src/log_store/tx_store.rs index 50895fc..00dbe8b 100644 --- a/node/storage/src/log_store/tx_store.rs +++ b/node/storage/src/log_store/tx_store.rs @@ -180,8 +180,12 @@ impl TransactionStore { } pub fn check_tx_completed(&self, tx_seq: u64) -> Result { - Ok(self.kvdb.get(COL_TX_COMPLETED, &tx_seq.to_be_bytes())? - == Some(vec![TX_STATUS_FINALIZED])) + let start_time = Instant::now(); + let res = self.kvdb.get(COL_TX_COMPLETED, &tx_seq.to_be_bytes())? + == Some(vec![TX_STATUS_FINALIZED]); + + metrics::CHECK_TX_COMPLETED.update_since(start_time); + Ok(res) } pub fn check_tx_pruned(&self, tx_seq: u64) -> Result {