From 87f20f0c52b78f805ceabe9aed4225272044a085 Mon Sep 17 00:00:00 2001 From: Tiram <18632023+tiram88@users.noreply.github.com> Date: Tue, 26 Sep 2023 10:43:29 +0300 Subject: [PATCH] Enhance tx throughput stats log line --- mining/src/lib.rs | 34 ++++++++++++++++++++++++++++-- mining/src/monitor.rs | 49 ++++++++++++++++--------------------------- 2 files changed, 50 insertions(+), 33 deletions(-) diff --git a/mining/src/lib.rs b/mining/src/lib.rs index 45b49ab93..d5eb767df 100644 --- a/mining/src/lib.rs +++ b/mining/src/lib.rs @@ -1,4 +1,7 @@ -use std::sync::atomic::{AtomicU64, Ordering}; +use std::{ + sync::atomic::{AtomicU64, Ordering}, + time::{Duration, Instant}, +}; use mempool::tx::Priority; @@ -14,8 +17,8 @@ pub mod monitor; #[cfg(test)] pub mod testutils; -#[derive(Default)] pub struct MiningCounters { + pub creation_time: Instant, pub high_priority_tx_counts: AtomicU64, pub low_priority_tx_counts: AtomicU64, pub block_tx_counts: AtomicU64, @@ -25,9 +28,25 @@ pub struct MiningCounters { pub ready_txs_sample: AtomicU64, } +impl Default for MiningCounters { + fn default() -> Self { + Self { + creation_time: Instant::now(), + high_priority_tx_counts: Default::default(), + low_priority_tx_counts: Default::default(), + block_tx_counts: Default::default(), + tx_accepted_counts: Default::default(), + input_counts: Default::default(), + output_counts: Default::default(), + ready_txs_sample: Default::default(), + } + } +} + impl MiningCounters { pub fn snapshot(&self) -> MempoolCountersSnapshot { MempoolCountersSnapshot { + elapsed_time: (Instant::now() - self.creation_time), high_priority_tx_counts: self.high_priority_tx_counts.load(Ordering::Relaxed), low_priority_tx_counts: self.low_priority_tx_counts.load(Ordering::Relaxed), block_tx_counts: self.block_tx_counts.load(Ordering::Relaxed), @@ -52,6 +71,7 @@ impl MiningCounters { #[derive(Debug, PartialEq, Eq)] pub struct MempoolCountersSnapshot { + pub elapsed_time: Duration, pub high_priority_tx_counts: u64, pub low_priority_tx_counts: u64, pub block_tx_counts: u64, @@ -66,6 +86,15 @@ impl MempoolCountersSnapshot { self.high_priority_tx_counts + self.low_priority_tx_counts } + pub fn u_tps(&self) -> f64 { + let elapsed = self.elapsed_time.as_secs_f64(); + if elapsed != 0f64 { + self.tx_accepted_counts as f64 / elapsed + } else { + 0f64 + } + } + pub fn e_tps(&self) -> f64 { let accepted_txs = u64::min(self.ready_txs_sample, self.tx_accepted_counts); let total_txs = u64::min(self.ready_txs_sample, self.block_tx_counts); @@ -82,6 +111,7 @@ impl core::ops::Sub for &MempoolCountersSnapshot { fn sub(self, rhs: Self) -> Self::Output { Self::Output { + elapsed_time: self.elapsed_time.checked_sub(rhs.elapsed_time).unwrap_or_default(), high_priority_tx_counts: self.high_priority_tx_counts.checked_sub(rhs.high_priority_tx_counts).unwrap_or_default(), low_priority_tx_counts: self.low_priority_tx_counts.checked_sub(rhs.low_priority_tx_counts).unwrap_or_default(), block_tx_counts: self.block_tx_counts.checked_sub(rhs.block_tx_counts).unwrap_or_default(), diff --git a/mining/src/monitor.rs b/mining/src/monitor.rs index 1359286a5..b71bb345c 100644 --- a/mining/src/monitor.rs +++ b/mining/src/monitor.rs @@ -8,10 +8,7 @@ use kaspa_core::{ trace, }; use kaspa_txscript::caches::TxScriptCacheCounters; -use std::{ - sync::Arc, - time::{Duration, Instant}, -}; +use std::{sync::Arc, time::Duration}; const MONITOR: &str = "mempool-monitor"; @@ -37,7 +34,6 @@ impl MiningMonitor { pub async fn worker(self: &Arc) { let mut last_snapshot = self.counters.snapshot(); let mut last_tx_script_cache_snapshot = self.tx_script_cache_counters.snapshot(); - let mut last_log_time = Instant::now(); let snapshot_interval = 10; loop { if let TickReason::Shutdown = self.tick_service.tick(Duration::from_secs(snapshot_interval)).await { @@ -48,11 +44,8 @@ impl MiningMonitor { let snapshot = self.counters.snapshot(); let tx_script_cache_snapshot = self.tx_script_cache_counters.snapshot(); - let now = Instant::now(); - let elapsed = (now - last_log_time).as_secs_f64(); if snapshot == last_snapshot { // No update, avoid printing useless info - last_log_time = Instant::now(); continue; } @@ -60,34 +53,28 @@ impl MiningMonitor { let delta = &snapshot - &last_snapshot; let tx_script_cache_delta = &tx_script_cache_snapshot - &last_tx_script_cache_snapshot; - // Avoid printing useless info if no update - if snapshot != last_snapshot { - info!("Processed {} unique transactions in the last {:.2}s ({:.2} avg txs/s, in: {} via RPC, {} via P2P, out: {} via accepted blocks, {:.2}% e-tps)", - delta.tx_accepted_counts, - elapsed, - delta.tx_accepted_counts as f64 / elapsed, - delta.high_priority_tx_counts, - delta.low_priority_tx_counts, - delta.block_tx_counts, - delta.e_tps() * 100.0, + info!( + "Tx throughput stats: {:.2} u-tps, {:.2}% e-tps (in: {} via RPC, {} via P2P, out: {} via accepted blocks)", + delta.u_tps(), + delta.e_tps() * 100.0, + delta.high_priority_tx_counts, + delta.low_priority_tx_counts, + delta.tx_accepted_counts, + ); + // FIXME: (wip) decide if the log level should be debug and what info should be kept or formulated differently + if tx_script_cache_snapshot != last_tx_script_cache_snapshot { + info!( + "UTXOs stats: {} spent, {} created ({} signatures validated, {} cache hits, {:.2} hit ratio)", + delta.input_counts, + delta.output_counts, + tx_script_cache_delta.insert_counts, + tx_script_cache_delta.get_counts, + tx_script_cache_delta.hit_ratio() ); - // FIXME: (wip) decide if the log level should be debug and what info should be kept or formulated differently - if tx_script_cache_snapshot != last_tx_script_cache_snapshot { - info!( - "Created {} UTXOs, spent {} in the last {:.2}s ({} signatures validated, {} cache hits, {:.2} hit ratio)", - delta.output_counts, - delta.input_counts, - elapsed, - tx_script_cache_delta.insert_counts, - tx_script_cache_delta.get_counts, - tx_script_cache_delta.hit_ratio() - ); - } } last_snapshot = snapshot; last_tx_script_cache_snapshot = tx_script_cache_snapshot; - last_log_time = now; } trace!("mempool monitor thread exiting");