From 96ccb0dcd19afcdf70999d78ec7c746f5577bb09 Mon Sep 17 00:00:00 2001 From: yukang Date: Thu, 14 Mar 2024 21:32:56 +0800 Subject: [PATCH] cleanup perf logs --- tx-pool/src/component/pool_map.rs | 11 ++--------- tx-pool/src/pool.rs | 7 ------- tx-pool/src/process.rs | 26 +------------------------- tx-pool/src/service.rs | 12 ++++-------- 4 files changed, 7 insertions(+), 49 deletions(-) diff --git a/tx-pool/src/component/pool_map.rs b/tx-pool/src/component/pool_map.rs index 79e1046b13..184cc522ba 100644 --- a/tx-pool/src/component/pool_map.rs +++ b/tx-pool/src/component/pool_map.rs @@ -19,8 +19,6 @@ use ckb_types::{ }; use multi_index_map::MultiIndexMap; use std::collections::HashSet; -use std::time::Instant; - type ConflictEntry = (TxEntry, Reject); #[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)] @@ -131,16 +129,11 @@ impl PoolMap { } pub(crate) fn get_max_update_time(&self) -> u64 { - let instant = Instant::now(); - let res = self - .entries + self.entries .iter() .map(|(_, entry)| entry.inner.timestamp) .max() - .unwrap_or(0); - let duration = instant.elapsed(); - debug!("[Perf] get_max_update_time duration: {:?}", duration); - res + .unwrap_or(0) } pub(crate) fn get_by_id(&self, id: &ProposalShortId) -> Option<&PoolEntry> { diff --git a/tx-pool/src/pool.rs b/tx-pool/src/pool.rs index 53fd572e99..ee88211b7d 100644 --- a/tx-pool/src/pool.rs +++ b/tx-pool/src/pool.rs @@ -25,7 +25,6 @@ use ckb_types::{ use lru::LruCache; use std::collections::{HashMap, HashSet}; use std::sync::Arc; -use std::time::Instant; const COMMITTED_HASH_CACHE_SIZE: usize = 100_000; const CONFLICTES_CACHE_SIZE: usize = 10_000; @@ -246,7 +245,6 @@ impl TxPool { // Expire all transaction (and their dependencies) in the pool. pub(crate) fn remove_expired(&mut self, callbacks: &Callbacks) { let now_ms = ckb_systemtime::unix_time_as_millis(); - let instant = Instant::now(); let removed: Vec<_> = self .pool_map @@ -262,13 +260,10 @@ impl TxPool { let reject = Reject::Expiry(entry.timestamp); callbacks.call_reject(self, &entry, reject); } - let duration = instant.elapsed(); - debug!("[Perf] remove_expired duration: {:?}", duration); } // Remove transactions from the pool until total size <= size_limit. pub(crate) fn limit_size(&mut self, callbacks: &Callbacks) { - let instant = Instant::now(); while self.pool_map.total_tx_size > self.config.max_tx_pool_size { let next_evict_entry = || { self.pool_map @@ -294,8 +289,6 @@ impl TxPool { } } self.pool_map.entries.shrink_to_fit(); - let duration = instant.elapsed(); - debug!("[Perf] limit_size duration: {:?}", duration); } // remove transaction with detached proposal from gap and proposed diff --git a/tx-pool/src/process.rs b/tx-pool/src/process.rs index 5831331af5..a669b4881b 100644 --- a/tx-pool/src/process.rs +++ b/tx-pool/src/process.rs @@ -33,7 +33,7 @@ use ckb_verification::{ use std::collections::HashSet; use std::collections::{HashMap, VecDeque}; use std::sync::Arc; -use std::time::{Duration, Instant}; +use std::time::Duration; use tokio::task::block_in_place; const DELAY_LIMIT: usize = 1_500 * 21; // 1_500 per block, 21 blocks @@ -103,7 +103,6 @@ impl TxPoolService { entry: TxEntry, mut status: TxStatus, ) -> (Result<(), Reject>, Arc) { - let instant = Instant::now(); let (ret, snapshot) = self .with_tx_pool_write_lock(move |tx_pool, snapshot| { // check_rbf must be invoked in `write` lock to avoid concurrent issues. @@ -171,8 +170,6 @@ impl TxPoolService { }) .await; - let duration = instant.elapsed(); - debug!("[Perf] submit_entry: {:?}", duration); (ret, snapshot) } @@ -241,7 +238,6 @@ impl TxPoolService { tx: &TransactionView, ) -> (Result, Arc) { // Acquire read lock for cheap check - let instant = Instant::now(); let tx_size = tx.data().serialized_size_in_block(); let (ret, snapshot) = self @@ -283,8 +279,6 @@ impl TxPoolService { } }) .await; - let duration = instant.elapsed(); - debug!("[Perf] pre-check: {:?}", duration); (ret, snapshot) } @@ -1131,7 +1125,6 @@ fn _submit_entry( ) -> Result, Reject> { let tx_hash = entry.transaction().hash(); debug!("submit_entry {:?} {}", status, tx_hash); - let start = Instant::now(); let (succ, evicts) = match status { TxStatus::Fresh => tx_pool.add_pending(entry.clone())?, TxStatus::Gap => tx_pool.add_gap(entry.clone())?, @@ -1144,8 +1137,6 @@ fn _submit_entry( TxStatus::Proposed => callbacks.call_proposed(&entry), } } - let duration = start.elapsed(); - debug!("[Perf] Time elapsed in _submit_entry is: {:?}", duration); Ok(evicts) } @@ -1158,7 +1149,6 @@ fn _update_tx_pool_for_reorg( callbacks: &Callbacks, mine_mode: bool, ) { - let instant = Instant::now(); tx_pool.snapshot = Arc::clone(&snapshot); // NOTE: `remove_by_detached_proposal` will try to re-put the given expired/detached proposals into @@ -1176,7 +1166,6 @@ fn _update_tx_pool_for_reorg( let mut proposals = Vec::new(); let mut gaps = Vec::new(); - let instant = Instant::now(); for entry in tx_pool.pool_map.entries.get_by_status(&Status::Gap) { let short_id = entry.inner.proposal_short_id(); if snapshot.proposals().contains_proposed(&short_id) { @@ -1193,16 +1182,7 @@ fn _update_tx_pool_for_reorg( gaps.push(elem); } } - let duration = instant.elapsed(); - debug!("[Perf] reorg duration: {:?}", duration); - debug!( - "[Perf] reorg size: tx_pool size {:?} snapshot gap: {:?}, proposed: {:?}", - tx_pool.pool_map.entries.len(), - snapshot.proposals().gap().len(), - snapshot.proposals().set().len(), - ); - let instant = Instant::now(); for (id, entry) in proposals { debug!("begin to proposed: {:x}", id); if let Err(e) = tx_pool.proposed_rtx(&id) { @@ -1228,8 +1208,6 @@ fn _update_tx_pool_for_reorg( callbacks.call_reject(tx_pool, &entry, e.clone()); } } - let duration = instant.elapsed(); - debug!("[Perf] reorg setting: {:?}", duration); } // Remove expired transaction from pending @@ -1237,8 +1215,6 @@ fn _update_tx_pool_for_reorg( // Remove transactions from the pool until its size <= size_limit. tx_pool.limit_size(callbacks); - let duration = instant.elapsed(); - debug!("[Perf] reorg _update_tx_pool_for_reorg: {:?}", duration); } pub fn all_inputs_is_unknown(snapshot: &Snapshot, tx: &TransactionView) -> bool { diff --git a/tx-pool/src/service.rs b/tx-pool/src/service.rs index e3381f7403..8ad6300a5b 100644 --- a/tx-pool/src/service.rs +++ b/tx-pool/src/service.rs @@ -14,7 +14,7 @@ use ckb_chain_spec::consensus::Consensus; use ckb_channel::oneshot; use ckb_error::AnyError; use ckb_jsonrpc_types::BlockTemplate; -use ckb_logger::{debug, error, info}; +use ckb_logger::{error, info}; use ckb_network::{NetworkController, PeerIndex}; use ckb_snapshot::Snapshot; use ckb_stop_handler::new_tokio_exit_rx; @@ -33,7 +33,7 @@ use std::sync::{ atomic::{AtomicBool, Ordering}, Arc, }; -use std::time::{Duration, Instant}; +use std::time::Duration; use tokio::sync::watch; use tokio::sync::{mpsc, RwLock}; use tokio::task::block_in_place; @@ -920,8 +920,7 @@ impl TxPoolService { let tx_pool = self.tx_pool.read().await; let orphan = self.orphan.read().await; let tip_header = tx_pool.snapshot.tip_header(); - let instant = Instant::now(); - let res = TxPoolInfo { + TxPoolInfo { tip_hash: tip_header.hash(), tip_number: tip_header.number(), pending_size: tx_pool.pool_map.pending_size(), @@ -934,10 +933,7 @@ impl TxPoolService { last_txs_updated_at: tx_pool.pool_map.get_max_update_time(), tx_size_limit: TRANSACTION_SIZE_LIMIT, max_tx_pool_size: self.tx_pool_config.max_tx_pool_size as u64, - }; - let duration = instant.elapsed(); - debug!("[Perf] tx_pool info: {:?}", duration); - res + } } pub fn should_notify_block_assembler(&self) -> bool {