Enhance tx throughput stats log line

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(),

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<MiningMonitor>) {
         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,46 +44,37 @@ 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;
             }
 
             // Subtract the snapshots
             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");