From 6650541b2dd7b9884ad7fc39f372dffbef773699 Mon Sep 17 00:00:00 2001 From: junderw Date: Mon, 26 Jun 2023 19:29:32 -0700 Subject: [PATCH] Added Logging and refactored a bit --- Cargo.lock | 150 ++++++++++++++++++++- backend/rust-gbt/Cargo.toml | 3 + backend/rust-gbt/src/audit_transaction.rs | 24 +++- backend/rust-gbt/src/gbt.rs | 53 ++++++-- backend/rust-gbt/src/lib.rs | 50 ++++++- backend/rust-gbt/src/thread_transaction.rs | 1 + backend/rust-gbt/src/u32_hasher_types.rs | 7 + 7 files changed, 265 insertions(+), 23 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d7e7ef21a..e03ab2531 100644 --- a/Cargo.lock +++ b/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" diff --git a/backend/rust-gbt/Cargo.toml b/backend/rust-gbt/Cargo.toml index d529be207..09fde52e2 100644 --- a/backend/rust-gbt/Cargo.toml +++ b/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" diff --git a/backend/rust-gbt/src/audit_transaction.rs b/backend/rust-gbt/src/audit_transaction.rs index e9f2655f0..d4e9cf1c3 100644 --- a/backend/rust-gbt/src/audit_transaction.rs +++ b/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) { diff --git a/backend/rust-gbt/src/gbt.rs b/backend/rust-gbt/src/gbt.rs index 896b1681b..797f7f981 100644 --- a/backend/rust-gbt/src/gbt.rs +++ b/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; type ModifiedQueue = PriorityQueue; +#[derive(Debug)] struct TxPriority { uid: u32, score: f64, @@ -60,7 +62,7 @@ pub fn gbt(mempool: &mut ThreadTransactionsMap) -> GbtResult { let mut mempool_stack: Vec = Vec::with_capacity(STARTING_CAPACITY); let mut clusters: Vec> = 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 - // (i.e. the package rooted in the transaction with the best ancestor score) + info!("Building blocks by greedily choosing the highest feerate package"); + info!("(i.e. the package rooted in the transaction with the best ancestor score)"); let mut blocks: Vec> = 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 = 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 - .dependency_rate - .min(next_tx.ancestor_fee() as f64 / (f64::from(next_tx.ancestor_weight()) / 4.0)); + let cluster_rate = next_tx.cluster_rate(); 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.effective_fee_per_vsize = cluster_rate; - tx.dirty = true; - } + tx.set_dirty_if_different(cluster_rate); 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::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, audit_pool: &'a AuditPool) -> Option<&'a AuditTransaction> { +fn next_valid_from_stack<'a>( + mempool_stack: &mut Vec, + 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, 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 { diff --git a/backend/rust-gbt/src/lib.rs b/backend/rust-gbt/src/lib.rs index f70ea989f..754763946 100644 --- a/backend/rust-gbt/src/lib.rs +++ b/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>, } +#[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 { + 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 { + 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( 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 diff --git a/backend/rust-gbt/src/thread_transaction.rs b/backend/rust-gbt/src/thread_transaction.rs index a16020165..2bb3a959d 100644 --- a/backend/rust-gbt/src/thread_transaction.rs +++ b/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, diff --git a/backend/rust-gbt/src/u32_hasher_types.rs b/backend/rust-gbt/src/u32_hasher_types.rs index 1995bcad2..6f9f99a85 100644 --- a/backend/rust-gbt/src/u32_hasher_types.rs +++ b/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 { #[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;