From 537993a13d434f7a8b0cc6bbb1fa784bcc7b2f72 Mon Sep 17 00:00:00 2001 From: Nikolay Volf Date: Wed, 27 May 2020 18:11:36 +0300 Subject: [PATCH] Improve logging for transaction pool (#6152) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * improve logging * Update client/transaction-pool/graph/src/validated_pool.rs Co-authored-by: Tomasz Drwięga * address review and make uniform Co-authored-by: Tomasz Drwięga --- .../transaction-pool/graph/src/listener.rs | 15 ++++++++------- .../graph/src/validated_pool.rs | 18 ++++++++++-------- .../transaction-pool/src/revalidation.rs | 14 ++++++++++++-- 3 files changed, 30 insertions(+), 17 deletions(-) diff --git a/substrate/client/transaction-pool/graph/src/listener.rs b/substrate/client/transaction-pool/graph/src/listener.rs index cccf542199..2923f2b34a 100644 --- a/substrate/client/transaction-pool/graph/src/listener.rs +++ b/substrate/client/transaction-pool/graph/src/listener.rs @@ -18,7 +18,7 @@ // along with this program. If not, see . use std::{ - collections::HashMap, hash, + collections::HashMap, hash, fmt::Debug, }; use linked_hash_map::LinkedHashMap; use serde::Serialize; @@ -27,7 +27,7 @@ use log::{debug, trace, warn}; use sp_runtime::traits; /// Extrinsic pool default listener. -pub struct Listener { +pub struct Listener { watchers: HashMap>>, finality_watchers: LinkedHashMap, Vec>, } @@ -35,7 +35,7 @@ pub struct Listener { /// Maximum number of blocks awaiting finality at any time. const MAX_FINALITY_WATCHERS: usize = 512; -impl Default for Listener { +impl Default for Listener { fn default() -> Self { Listener { watchers: Default::default(), @@ -74,7 +74,7 @@ impl Listener { /// New transaction was added to the ready pool or promoted from the future pool. pub fn ready(&mut self, tx: &H, old: Option<&H>) { - trace!(target: "txpool", "[{:?}] Ready (replaced: {:?})", tx, old); + trace!(target: "txpool", "[{:?}] Ready (replaced with {:?})", tx, old); self.fire(tx, |watcher| watcher.ready()); if let Some(old) = old { self.fire(old, |watcher| watcher.usurped(tx.clone())); @@ -89,7 +89,7 @@ impl Listener { /// Transaction was dropped from the pool because of the limit. pub fn dropped(&mut self, tx: &H, by: Option<&H>) { - trace!(target: "txpool", "[{:?}] Dropped (replaced by {:?})", tx, by); + trace!(target: "txpool", "[{:?}] Dropped (replaced with {:?})", tx, by); self.fire(tx, |watcher| match by { Some(t) => watcher.usurped(t.clone()), None => watcher.dropped(), @@ -99,9 +99,9 @@ impl Listener { /// Transaction was removed as invalid. pub fn invalid(&mut self, tx: &H, warn: bool) { if warn { - warn!(target: "txpool", "Extrinsic invalid: {:?}", tx); + warn!(target: "txpool", "[{:?}] Extrinsic invalid", tx); } else { - debug!(target: "txpool", "Extrinsic invalid: {:?}", tx); + debug!(target: "txpool", "[{:?}] Extrinsic invalid", tx); } self.fire(tx, |watcher| watcher.invalid()); } @@ -134,6 +134,7 @@ impl Listener { pub fn finalized(&mut self, block_hash: BlockHash) { if let Some(hashes) = self.finality_watchers.remove(&block_hash) { for hash in hashes { + log::debug!(target: "txpool", "[{:?}] Sent finalization event (block {:?})", hash, block_hash); self.fire(&hash, |s| s.finalized(block_hash)) } } diff --git a/substrate/client/transaction-pool/graph/src/validated_pool.rs b/substrate/client/transaction-pool/graph/src/validated_pool.rs index 7e8e91efe8..9ab45e3b26 100644 --- a/substrate/client/transaction-pool/graph/src/validated_pool.rs +++ b/substrate/client/transaction-pool/graph/src/validated_pool.rs @@ -27,7 +27,6 @@ use crate::listener::Listener; use crate::rotator::PoolRotator; use crate::watcher::Watcher; use serde::Serialize; -use log::{debug, warn}; use parking_lot::{Mutex, RwLock}; use sp_runtime::{ @@ -189,11 +188,11 @@ impl ValidatedPool { let ready_limit = &self.options.ready; let future_limit = &self.options.future; - debug!(target: "txpool", "Pool Status: {:?}", status); + log::debug!(target: "txpool", "Pool Status: {:?}", status); if ready_limit.is_exceeded(status.ready, status.ready_bytes) || future_limit.is_exceeded(status.future, status.future_bytes) { - debug!( + log::debug!( target: "txpool", "Enforcing limits ({}/{}kB ready, {}/{}kB future", ready_limit.count, ready_limit.total_bytes / 1024, @@ -209,8 +208,11 @@ impl ValidatedPool { self.rotator.ban(&Instant::now(), removed.iter().map(|x| x.clone())); removed }; + if !removed.is_empty() { + log::debug!(target: "txpool", "Enforcing limits: {} dropped", removed.len()); + } + // run notifications - debug!(target: "txpool", "Enforcing limits: {} dropped", removed.len()); let mut listener = self.listener.write(); for h in &removed { listener.dropped(h, None); @@ -324,7 +326,7 @@ impl ValidatedPool { // we do not want to fail if single transaction import has failed // nor we do want to propagate this error, because it could tx unknown to caller // => let's just notify listeners (and issue debug message) - warn!( + log::warn!( target: "txpool", "[{:?}] Removing invalid transaction from update: {}", hash, @@ -531,14 +533,14 @@ impl ValidatedPool { return vec![]; } - debug!(target: "txpool", "Removing invalid transactions: {:?}", hashes); + log::debug!(target: "txpool", "Removing invalid transactions: {:?}", hashes); // temporarily ban invalid transactions self.rotator.ban(&Instant::now(), hashes.iter().cloned()); let invalid = self.pool.write().remove_subtree(hashes); - debug!(target: "txpool", "Removed invalid transactions: {:?}", invalid); + log::debug!(target: "txpool", "Removed invalid transactions: {:?}", invalid); let mut listener = self.listener.write(); for tx in &invalid { @@ -560,7 +562,7 @@ impl ValidatedPool { /// Notify all watchers that transactions in the block with hash have been finalized pub async fn on_block_finalized(&self, block_hash: BlockHash) -> Result<(), B::Error> { - debug!(target: "txpool", "Attempting to notify watchers of finalization for {}", block_hash); + log::trace!(target: "txpool", "Attempting to notify watchers of finalization for {}", block_hash); self.listener.write().finalized(block_hash); Ok(()) } diff --git a/substrate/client/transaction-pool/src/revalidation.rs b/substrate/client/transaction-pool/src/revalidation.rs index 33f3a3da47..423ff92ba4 100644 --- a/substrate/client/transaction-pool/src/revalidation.rs +++ b/substrate/client/transaction-pool/src/revalidation.rs @@ -178,7 +178,7 @@ impl RevalidationWorker { for ext_hash in transactions { // we don't add something that already scheduled for revalidation if self.members.contains_key(&ext_hash) { - log::debug!( + log::trace!( target: "txpool", "[{:?}] Skipped adding for revalidation: Already there.", ext_hash, @@ -245,6 +245,16 @@ impl RevalidationWorker { Some(worker_payload) => { this.best_block = worker_payload.at; this.push(worker_payload); + + if this.members.len() > 0 { + log::debug!( + target: "txpool", + "Updated revalidation queue at {}. Transactions: {:?}", + this.best_block, + this.members, + ); + } + continue; }, // R.I.P. worker! @@ -326,7 +336,7 @@ where /// revalidation is actually done. pub async fn revalidate_later(&self, at: NumberFor, transactions: Vec>) { if transactions.len() > 0 { - log::debug!(target: "txpool", "Added {} transactions to revalidation queue", transactions.len()); + log::debug!(target: "txpool", "Sent {} transactions to revalidation queue", transactions.len()); } if let Some(ref to_worker) = self.background {