Added Logging and refactored a bit

Cargo.lock

@@ -70,6 +70,9 @@ dependencies = [
  "napi-build",
  "napi-derive",
  "priority-queue",
+ "tracing",
+ "tracing-log",
+ "tracing-subscriber",
 ]
 
 [[package]]
@@ -97,6 +100,12 @@ dependencies = [
  "hashbrown",
 ]
 
+[[package]]
+name = "lazy_static"
+version = "1.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e2abad23fbc42b3700f2f279844dc832adb2b2eb069b2df918f455c4e18cc646"
+
 [[package]]
 name = "libc"
 version = "0.2.146"
@@ -113,6 +122,21 @@ dependencies = [
  "winapi",
 ]
 
+[[package]]
+name = "log"
+version = "0.4.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b06a4cde4c0f271a446782e3eff8de789548ce57dbc8eca9292c27f4a42004b4"
+
+[[package]]
+name = "matchers"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558"
+dependencies = [
+ "regex-automata",
+]
+
 [[package]]
 name = "memchr"
 version = "2.5.0"
@@ -177,6 +201,16 @@ dependencies = [
  "libloading",
 ]
 
+[[package]]
+name = "nu-ansi-term"
+version = "0.46.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
+dependencies = [
+ "overload",
+ "winapi",
+]
+
 [[package]]
 name = "num_cpus"
 version = "1.15.0"
@@ -193,6 +227,12 @@ version = "1.18.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "dd8b5dd2ae5ed71462c540258bedcb51965123ad7e7ccf4b9a8cafaa4a63576d"
 
+[[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
 [[package]]
 name = "pin-project-lite"
 version = "0.2.9"
@@ -235,9 +275,24 @@ checksum = "81ca098a9821bd52d6b24fd8b10bd081f47d39c22778cafaa75a2857a62c6390"
 dependencies = [
  "aho-corasick",
  "memchr",
- "regex-syntax",
+ "regex-syntax 0.7.2",
 ]
 
+[[package]]
+name = "regex-automata"
+version = "0.1.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132"
+dependencies = [
+ "regex-syntax 0.6.29",
+]
+
+[[package]]
+name = "regex-syntax"
+version = "0.6.29"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1"
+
 [[package]]
 name = "regex-syntax"
 version = "0.7.2"
@@ -250,6 +305,21 @@ version = "1.0.17"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "bebd363326d05ec3e2f532ab7660680f3b02130d780c299bca73469d521bc0ed"
 
+[[package]]
+name = "sharded-slab"
+version = "0.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31"
+dependencies = [
+ "lazy_static",
+]
+
+[[package]]
+name = "smallvec"
+version = "1.10.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a507befe795404456341dfab10cef66ead4c041f62b8b11bbb92bffe5d0953e0"
+
 [[package]]
 name = "syn"
 version = "1.0.109"
@@ -272,6 +342,16 @@ dependencies = [
  "unicode-ident",
 ]
 
+[[package]]
+name = "thread_local"
+version = "1.1.7"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152"
+dependencies = [
+ "cfg-if",
+ "once_cell",
+]
+
 [[package]]
 name = "tokio"
 version = "1.28.2"
@@ -284,6 +364,68 @@ dependencies = [
  "windows-sys",
 ]
 
+[[package]]
+name = "tracing"
+version = "0.1.37"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8"
+dependencies = [
+ "cfg-if",
+ "pin-project-lite",
+ "tracing-attributes",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-attributes"
+version = "0.1.26"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5f4f31f56159e98206da9efd823404b79b6ef3143b4a7ab76e67b1751b25a4ab"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn 2.0.20",
+]
+
+[[package]]
+name = "tracing-core"
+version = "0.1.31"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0955b8137a1df6f1a2e9a37d8a6656291ff0297c1a97c24e0d8425fe2312f79a"
+dependencies = [
+ "once_cell",
+ "valuable",
+]
+
+[[package]]
+name = "tracing-log"
+version = "0.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922"
+dependencies = [
+ "lazy_static",
+ "log",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.17"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77"
+dependencies = [
+ "matchers",
+ "nu-ansi-term",
+ "once_cell",
+ "regex",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing",
+ "tracing-core",
+ "tracing-log",
+]
+
 [[package]]
 name = "unicode-ident"
 version = "1.0.9"
@@ -296,6 +438,12 @@ version = "1.10.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "1dd624098567895118886609431a7c3b8f516e41d30e0643f03d94592a147e36"
 
+[[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
 [[package]]
 name = "winapi"
 version = "0.3.9"

backend/rust-gbt/Cargo.toml

@@ -17,6 +17,9 @@ bytes = "1.4.0"
 napi = { version = "2.13.2", features = ["napi8", "tokio_rt"] }
 napi-derive = "2.13.0"
 bytemuck = "1.13.1"
+tracing = "0.1.36"
+tracing-log = "0.1.3"
+tracing-subscriber = { version = "0.3.15", features = ["env-filter"]}
 
 [build-dependencies]
 napi-build = "2.0.1"

backend/rust-gbt/src/audit_transaction.rs

@@ -9,7 +9,7 @@ use std::{
 };
 
 #[allow(clippy::struct_excessive_bools)]
-#[derive(Clone)]
+#[derive(Clone, Debug)]
 pub struct AuditTransaction {
     pub uid: u32,
     pub fee: u64,
@@ -97,11 +97,6 @@ impl AuditTransaction {
         self.score
     }
 
-    #[inline]
-    pub const fn ancestor_fee(&self) -> u64 {
-        self.ancestor_fee
-    }
-
     #[inline]
     pub const fn ancestor_weight(&self) -> u32 {
         self.ancestor_weight
@@ -112,6 +107,23 @@ impl AuditTransaction {
         self.ancestor_sigops
     }
 
+    #[inline]
+    pub fn cluster_rate(&self) -> f64 {
+        // Safety: self.ancestor_weight can never be 0.
+        // Even if it could, as it approaches 0, the value inside the min() call
+        // grows, so if we think of 0 as "grew infinitely" then dependency_rate would be
+        // the smaller of the two. If either side is NaN, the other side is returned.
+        self.dependency_rate
+            .min(self.ancestor_fee as f64 / (f64::from(self.ancestor_weight) / 4.0))
+    }
+
+    pub fn set_dirty_if_different(&mut self, cluster_rate: f64) {
+        if self.effective_fee_per_vsize != cluster_rate {
+            self.effective_fee_per_vsize = cluster_rate;
+            self.dirty = true;
+        }
+    }
+
     /// Safety: This function must NEVER set score to NaN.
     #[inline]
     fn calc_new_score(&mut self) {

backend/rust-gbt/src/gbt.rs

@@ -3,6 +3,7 @@ use std::{
     cmp::Ordering,
     collections::{HashMap, HashSet},
 };
+use tracing::{info, trace};
 
 use crate::{
     audit_transaction::AuditTransaction,
@@ -20,6 +21,7 @@ const MAX_BLOCKS: usize = 8;
 type AuditPool = HashMap<u32, AuditTransaction, U32HasherState>;
 type ModifiedQueue = PriorityQueue<u32, TxPriority, U32HasherState>;
 
+#[derive(Debug)]
 struct TxPriority {
     uid: u32,
     score: f64,
@@ -60,7 +62,7 @@ pub fn gbt(mempool: &mut ThreadTransactionsMap) -> GbtResult {
     let mut mempool_stack: Vec<u32> = Vec::with_capacity(STARTING_CAPACITY);
     let mut clusters: Vec<Vec<u32>> = Vec::new();
 
-    // Initialize working structs
+    info!("Initializing working structs");
     for (uid, tx) in mempool {
         let audit_tx = AuditTransaction::from_thread_transaction(tx);
         // Safety: audit_pool and mempool_stack must always contain the same transactions
@@ -68,12 +70,13 @@ pub fn gbt(mempool: &mut ThreadTransactionsMap) -> GbtResult {
         mempool_stack.push(*uid);
     }
 
-    // Build relatives graph & calculate ancestor scores
+    info!("Building relatives graph & calculate ancestor scores");
     for txid in &mempool_stack {
         set_relatives(*txid, &mut audit_pool);
     }
+    trace!("Post relative graph Audit Pool: {:#?}", audit_pool);
 
-    // Sort by descending ancestor score
+    info!("Sorting by descending ancestor score");
     mempool_stack.sort_unstable_by(|a, b| {
         let a_tx = audit_pool
             .get(a)
@@ -84,8 +87,8 @@ pub fn gbt(mempool: &mut ThreadTransactionsMap) -> GbtResult {
         a_tx.cmp(b_tx)
     });
 
-    // Build blocks by greedily choosing the highest feerate package
+    info!("Building blocks by greedily choosing the highest feerate package");
-    // (i.e. the package rooted in the transaction with the best ancestor score)
+    info!("(i.e. the package rooted in the transaction with the best ancestor score)");
     let mut blocks: Vec<Vec<u32>> = Vec::new();
     let mut block_weight: u32 = BLOCK_RESERVED_WEIGHT;
     let mut block_sigops: u32 = 0;
@@ -94,6 +97,22 @@ pub fn gbt(mempool: &mut ThreadTransactionsMap) -> GbtResult {
     let mut overflow: Vec<u32> = Vec::new();
     let mut failures = 0;
     while !mempool_stack.is_empty() || !modified.is_empty() {
+        // This trace log storm is big, so to make scrolling through
+        // Each iteration easier, leaving a bunch of empty rows
+        // And a header of ======
+        trace!("\n\n\n\n\n\n\n\n\n\n==================================");
+        trace!("mempool_array: {:#?}", mempool_stack);
+        trace!("clusters: {:#?}", clusters);
+        trace!("modified: {:#?}", modified);
+        trace!("audit_pool: {:#?}", audit_pool);
+        trace!("blocks: {:#?}", blocks);
+        trace!("block_weight: {:#?}", block_weight);
+        trace!("block_sigops: {:#?}", block_sigops);
+        trace!("transactions: {:#?}", transactions);
+        trace!("overflow: {:#?}", overflow);
+        trace!("failures: {:#?}", failures);
+        trace!("\n==================================");
+
         let next_from_stack = next_valid_from_stack(&mut mempool_stack, &audit_pool);
         let next_from_queue = next_valid_from_queue(&mut modified, &audit_pool);
         if next_from_stack.is_none() && next_from_queue.is_none() {
@@ -134,18 +153,13 @@ pub fn gbt(mempool: &mut ThreadTransactionsMap) -> GbtResult {
             package.sort_unstable_by_key(|a| a.1);
             package.push((next_tx.uid, next_tx.ancestors.len()));
 
-            let cluster_rate = next_tx
+            let cluster_rate = next_tx.cluster_rate();
-                .dependency_rate
-                .min(next_tx.ancestor_fee() as f64 / (f64::from(next_tx.ancestor_weight()) / 4.0));
 
             for (txid, _) in &package {
                 cluster.push(*txid);
                 if let Some(tx) = audit_pool.get_mut(txid) {
                     tx.used = true;
-                    if tx.effective_fee_per_vsize != cluster_rate {
+                    tx.set_dirty_if_different(cluster_rate);
-                        tx.effective_fee_per_vsize = cluster_rate;
-                        tx.dirty = true;
-                    }
                     transactions.push(tx.uid);
                     block_weight += tx.weight;
                     block_sigops += tx.sigops;
@@ -202,10 +216,15 @@ pub fn gbt(mempool: &mut ThreadTransactionsMap) -> GbtResult {
     // make a list of dirty transactions and their new rates
     let mut rates: Vec<Vec<f64>> = Vec::new();
     for (txid, tx) in audit_pool {
+        trace!("txid: {}, is_dirty: {}", txid, tx.dirty);
         if tx.dirty {
             rates.push(vec![f64::from(txid), tx.effective_fee_per_vsize]);
         }
     }
+    trace!("\n\n\n\n\n====================");
+    trace!("blocks: {:#?}", blocks);
+    trace!("clusters: {:#?}", clusters);
+    trace!("rates: {:#?}\n====================\n\n\n\n\n", rates);
 
     GbtResult {
         blocks,
@@ -214,7 +233,10 @@ pub fn gbt(mempool: &mut ThreadTransactionsMap) -> GbtResult {
     }
 }
 
-fn next_valid_from_stack<'a>(mempool_stack: &mut Vec<u32>, audit_pool: &'a AuditPool) -> Option<&'a AuditTransaction> {
+fn next_valid_from_stack<'a>(
+    mempool_stack: &mut Vec<u32>,
+    audit_pool: &'a AuditPool,
+) -> Option<&'a AuditTransaction> {
     let mut next_txid = mempool_stack.last()?;
     let mut tx: &AuditTransaction = audit_pool.get(next_txid)?;
     while tx.used || tx.modified {
@@ -225,7 +247,10 @@ fn next_valid_from_stack<'a>(mempool_stack: &mut Vec<u32>, audit_pool: &'a Audit
     Some(tx)
 }
 
-fn next_valid_from_queue<'a>(queue: &mut ModifiedQueue, audit_pool: &'a AuditPool) -> Option<&'a AuditTransaction> {
+fn next_valid_from_queue<'a>(
+    queue: &mut ModifiedQueue,
+    audit_pool: &'a AuditPool,
+) -> Option<&'a AuditTransaction> {
     let mut next_txid = queue.peek()?.0;
     let mut tx: &AuditTransaction = audit_pool.get(next_txid)?;
     while tx.used {

backend/rust-gbt/src/lib.rs

@@ -8,17 +8,21 @@
 
 use napi::bindgen_prelude::{Result, Uint8Array};
 use napi_derive::napi;
+use tracing::{debug, info, trace};
+use tracing_log::LogTracer;
+use tracing_subscriber::{EnvFilter, FmtSubscriber};
 
 use std::collections::HashMap;
 use std::sync::{Arc, Mutex};
-use u32_hasher_types::{u32hashmap_with_capacity, U32HasherState};
 
 mod audit_transaction;
 mod gbt;
 mod thread_transaction;
 mod u32_hasher_types;
 mod utils;
+
 use thread_transaction::ThreadTransaction;
+use u32_hasher_types::{u32hashmap_with_capacity, U32HasherState};
 
 /// This is the starting capacity for HashMap/Vec/etc. that deal with transactions.
 /// `HashMap` doubles capacity when it hits it, so 2048 is a decent tradeoff between
@@ -35,12 +39,36 @@ pub struct GbtGenerator {
     thread_transactions: Arc<Mutex<ThreadTransactionsMap>>,
 }
 
+#[napi::module_init]
+fn init() {
+    // Set all `tracing` logs to print to STDOUT
+    // Note: Passing RUST_LOG env variable to the node process
+    //       will change the log level for the rust module.
+    tracing::subscriber::set_global_default(
+        FmtSubscriber::builder()
+            .with_env_filter(EnvFilter::from_default_env())
+            .with_ansi(
+                // Default to no-color logs.
+                // Setting RUST_LOG_COLOR to 1 or true|TRUE|True etc.
+                // will enable color
+                std::env::var("RUST_LOG_COLOR")
+                    .map(|s| ["1", "true"].contains(&&*s.to_lowercase()))
+                    .unwrap_or(false),
+            )
+            .finish(),
+    )
+    .expect("Logging subscriber failed");
+    // Convert all `log` logs into `tracing` events
+    LogTracer::init().expect("Legacy log subscriber failed");
+}
+
 #[napi]
 impl GbtGenerator {
     #[napi(constructor)]
     #[allow(clippy::new_without_default)]
     #[must_use]
     pub fn new() -> Self {
+        debug!("Created new GbtGenerator");
         Self {
             thread_transactions: Arc::new(Mutex::new(u32hashmap_with_capacity(STARTING_CAPACITY))),
         }
@@ -51,6 +79,7 @@ impl GbtGenerator {
     /// Rejects if the thread panics or if the Mutex is poisoned.
     #[napi]
     pub async fn make(&self, mempool_buffer: Uint8Array) -> Result<GbtResult> {
+        trace!("make: Current State {:#?}", self.thread_transactions);
         run_task(Arc::clone(&self.thread_transactions), move |map| {
             for tx in ThreadTransaction::batch_from_buffer(&mempool_buffer) {
                 map.insert(tx.uid, tx);
@@ -64,6 +93,7 @@ impl GbtGenerator {
     /// Rejects if the thread panics or if the Mutex is poisoned.
     #[napi]
     pub async fn update(&self, new_txs: Uint8Array, remove_txs: Uint8Array) -> Result<GbtResult> {
+        trace!("update: Current State {:#?}", self.thread_transactions);
         run_task(Arc::clone(&self.thread_transactions), move |map| {
             for tx in ThreadTransaction::batch_from_buffer(&new_txs) {
                 map.insert(tx.uid, tx);
@@ -105,12 +135,28 @@ async fn run_task<F>(
 where
     F: FnOnce(&mut ThreadTransactionsMap) + Send + 'static,
 {
+    debug!("Spawning thread...");
     let handle = napi::tokio::task::spawn_blocking(move || {
+        debug!(
+            "Getting lock for thread_transactions from thread {:?}...",
+            std::thread::current().id()
+        );
         let mut map = thread_transactions
             .lock()
             .map_err(|_| napi::Error::from_reason("THREAD_TRANSACTIONS Mutex poisoned"))?;
         callback(&mut map);
-        Ok(gbt::gbt(&mut map))
+
+        info!("Starting gbt algorithm for {} elements...", map.len());
+        let result = gbt::gbt(&mut map);
+        info!("Finished gbt algorithm for {} elements...", map.len());
+
+        debug!(
+            "Releasing lock for thread_transactions from thread {:?}...",
+            std::thread::current().id()
+        );
+        drop(map);
+
+        Ok(result)
     });
 
     handle

backend/rust-gbt/src/thread_transaction.rs

@@ -1,6 +1,7 @@
 use bytes::buf::Buf;
 use std::io::Cursor;
 
+#[derive(Debug)]
 pub struct ThreadTransaction {
     pub uid: u32,
     pub fee: u64,

backend/rust-gbt/src/u32_hasher_types.rs

@@ -1,6 +1,7 @@
 use priority_queue::PriorityQueue;
 use std::{
     collections::{HashMap, HashSet},
+    fmt::Debug,
     hash::{BuildHasher, Hasher},
 };
 
@@ -25,6 +26,12 @@ pub fn u32hashset_new() -> HashSet<u32, U32HasherState> {
 #[derive(Clone)]
 pub struct U32HasherState(());
 
+impl Debug for U32HasherState {
+    fn fmt(&self, _: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        Ok(())
+    }
+}
+
 impl BuildHasher for U32HasherState {
     type Hasher = U32Hasher;