Skip to content

Commit

Permalink
perf: split lengthy fn(s) to improve concurrency
Browse files Browse the repository at this point in the history 
Primary changes are:
 1. splits lengthy &mut self methods into read-only &self
    method(s) and faster &mut self method(s).  This makes
    these methods more concurrency friendly.

 2. provides original functionality with methods that have
    _atomic() suffix.  These take &mut self and call both
    the &self and &mut self methods.

 3. Adds ScopeDurationLogger to easily enable logging of
    slow methods.  by default "slow" means > 0.1 seconds.

Details:
 * log genesis block digest
 * rename GlobalState::set_new_tip() -> set_new_tip_atomic()
 * impl ScopeDurationLogger and use it to log method durations
 * split WalletState::update_wallet_state_with_new_block()
 * split ArchivalState::update_mutator_set()
 * add experimental GlobalStateLock::set_new_tip_concurrent()
    (not used)
 * split GlobalState::resync_membership_proofs()
 * remove duration_* macros
 * add fn_name, fn_name_bare macros
  • Loading branch information
@dan-da
dan-da committed Sep 22, 2024
1 parent a59bae6 commit b24390c
Show file tree
Hide file tree
Showing 14 changed files with 1,100 additions and 572 deletions.
41 changes: 41 additions & 0 deletions src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -284,6 +284,47 @@ pub async fn initialize(cli_args: cli_args::Args) -> Result<()> {
.await
}

pub struct ScopeDurationLogger<'a> {
start: Instant,
description: &'a str,
log_slow_fn_threshold: f64,
}
impl<'a> ScopeDurationLogger<'a> {
pub fn new_with_threshold(description: &'a str, log_slow_fn_threshold: f64) -> Self {
Self {
start: Instant::now(),
description,
log_slow_fn_threshold,
}
}

pub fn new(description: &'a str) -> Self {
Self::new_with_threshold(
description,
match env::var("LOG_SLOW_FN_THRESHOLD") {
Ok(t) => t.parse().unwrap(),
Err(_) => 0.1,
},
)
}
}

impl Drop for ScopeDurationLogger<'_> {
fn drop(&mut self) {
let elapsed = self.start.elapsed();
let duration = elapsed.as_secs() as f64 + elapsed.subsec_nanos() as f64 / 1e9;

if duration >= self.log_slow_fn_threshold {
let msg = format!(
"\n-- slow fn threshold of {} secs exceeded --\n executed {} in {} secs",
self.log_slow_fn_threshold, self.description, duration,
);

tracing::warn!("{}", msg);
}
}
}

/// Time a fn call. Duration is returned as a float in seconds.
pub fn time_fn_call<O>(f: impl FnOnce() -> O) -> (O, f64) {
let start = Instant::now();
Expand Down
202 changes: 18 additions & 184 deletions src/macros.rs
View file
Original file line number Diff line number Diff line change
@@ -1,141 +1,20 @@
/// executes an expression, times duration, and emits trace! message
///
/// The trace level is `tracing::Level::TRACE` by default.
///
/// Accepts arguments in 3 forms:
/// duration!(myfunc())
/// duration!(myfunc(), message)
/// duration!(myfunc(), message, trace_level)
#[allow(unused_macros)]
macro_rules! duration {
($target: expr, $message: expr, $lvl: expr) => {{
let (output, duration) = $crate::time_fn_call(|| $target);
let msg = format!(
"at {}:{}{}\n-- executed expression --\n{}\n -- duration: {} secs --",
file!(),
line!(),
if $message.len() > 0 {
format! {"\n{}", $message}
} else {
"".to_string()
},
stringify!($target),
duration
);
match $lvl {
tracing::Level::INFO => tracing::info!("{}", msg),
tracing::Level::TRACE => tracing::trace!("{}", msg),
tracing::Level::DEBUG => tracing::trace!("{}", msg),
tracing::Level::WARN => tracing::warn!("{}", msg),
tracing::Level::ERROR => tracing::error!("{}", msg),
macro_rules! fn_name_bare {
() => {{
fn f() {}
fn type_name_of<T>(_: T) -> &'static str {
std::any::type_name::<T>()
}
output
type_name_of(f)
.rsplit("::")
.find(|&part| part != "f" && part != "{{closure}}")
.expect("Short function name")
}};
($target: expr, $message: expr) => {
$crate::macros::duration!($target, $message, tracing::Level::TRACE)
};
($target: expr) => {
$crate::macros::duration!($target, "", tracing::Level::TRACE)
};
}

/// executes an expression, times duration, and emits info! message
///
/// Accepts arguments in 2 forms:
/// duration!(myfunc())
/// duration!(myfunc(), message)
#[allow(unused_macros)]
macro_rules! duration_info {
($target: expr) => {
$crate::macros::duration!($target, "", tracing::Level::INFO)
};
($target: expr, $message: expr) => {
$crate::macros::duration!($target, $message, tracing::Level::INFO)
};
}

/// executes an expression, times duration, and emits debug! message
///
/// Accepts arguments in 2 forms:
/// duration!(myfunc())
/// duration!(myfunc(), message)
#[allow(unused_macros)]
macro_rules! duration_debug {
($target: expr) => {
$crate::macros::duration!($target, "", tracing::Level::DEBUG)
};
($target: expr, $message: expr) => {
$crate::macros::duration!($target, $message, tracing::Level::DEBUG)
};
}

/// executes an async expression, times duration, and emits trace! message
///
/// Accepts arguments in 3 forms:
/// duration!(myfunc())
/// duration!(myfunc(), message)
/// duration!(myfunc(), message, trace_level)
#[allow(unused_macros)]
macro_rules! duration_async {
($target: expr, $message: expr, $lvl: expr) => {{
let (output, duration) = $crate::time_fn_call_async({ $target }).await;
let msg = format!(
"at {}:{}{}\n-- executed expression --\n{}\n -- duration: {} secs --",
file!(),
line!(),
if $message.len() > 0 {
format! {"\n{}", $message}
} else {
"".to_string()
},
stringify!($target),
duration
);
match $lvl {
tracing::Level::INFO => tracing::info!("{}", msg),
tracing::Level::TRACE => tracing::trace!("{}", msg),
tracing::Level::DEBUG => tracing::trace!("{}", msg),
tracing::Level::WARN => tracing::warn!("{}", msg),
tracing::Level::ERROR => tracing::error!("{}", msg),
}
output
macro_rules! fn_name {
() => {{
format!("{}()", crate::macros::fn_name_bare!())
}};
($target: expr, $message: expr) => {
$crate::macros::duration_async!($target, $message, tracing::Level::TRACE)
};
($target: expr) => {
$crate::macros::duration_async!($target, "", tracing::Level::TRACE)
};
}

/// executes an async expression, times duration, and emits info! message
///
/// Accepts arguments in 2 forms:
/// duration!(myfunc())
/// duration!(myfunc(), message)
#[allow(unused_macros)]
macro_rules! duration_async_info {
($target: expr) => {
$crate::macros::duration_async!($target, "", tracing::Level::INFO)
};
($target: expr, $message: expr) => {
$crate::macros::duration_async!($target, $message, tracing::Level::INFO)
};
}

/// executes an async expression, times duration, and emits debug! message
///
/// Accepts arguments in 2 forms:
/// duration!(myfunc())
/// duration!(myfunc(), message)
#[allow(unused_macros)]
macro_rules! duration_async_debug {
($target: expr) => {
$crate::macros::duration_async!($target, "", tracing::Level::DEBUG)
};
($target: expr, $message: expr) => {
$crate::macros::duration_async!($target, $message, tracing::Level::DEBUG)
};
}

// These allow the macros to be used as
Expand All @@ -144,67 +23,22 @@ macro_rules! duration_async_debug {
// see: https://stackoverflow.com/a/67140319/10087197

#[allow(unused_imports)]
pub(crate) use duration;
#[allow(unused_imports)]
pub(crate) use duration_async;
#[allow(unused_imports)]
pub(crate) use duration_async_debug;
#[allow(unused_imports)]
pub(crate) use duration_async_info;
pub(crate) use fn_name;
#[allow(unused_imports)]
pub(crate) use duration_debug;
#[allow(unused_imports)]
pub(crate) use duration_info;
pub(crate) use fn_name_bare;

#[cfg(test)]
mod test {

use super::*;
use tracing::Level;

fn fibonacci(n: u32) -> u32 {
match n {
0 => 1,
1 => 1,
_ => fibonacci(n - 1) + fibonacci(n - 2),
}
}

async fn fibonacci_async(n: u32) -> u32 {
match n {
0 => 1,
1 => 1,
_ => fibonacci(n - 1) + fibonacci(n - 2),
}
}

#[test]
fn duration_tests() {
duration!(fibonacci(1));
duration!(fibonacci(2), "fibonacci - 2".to_string());
duration!(fibonacci(3), "fibonacci - 3", Level::INFO);

duration_info!(fibonacci(4));
duration_info!(fibonacci(5), "fibonacci - 5");
duration_info!(fibonacci(6), "fibonacci - 6".to_string());

duration_debug!(fibonacci(7));
duration_debug!(fibonacci(8), "fibonacci - 8");
duration_debug!(fibonacci(9), "fibonacci - 9".to_string());
fn fn_name_test() {
assert_eq!(fn_name!(), "fn_name_test()");
}

#[tokio::test]
async fn duration_async_tests() {
duration_async!(fibonacci_async(1));
duration_async!(fibonacci_async(2), "fibonacci_async - 2".to_string());
duration_async!(fibonacci_async(3), "fibonacci_async - 3", Level::INFO);

duration_async_info!(fibonacci_async(4));
duration_async_info!(fibonacci_async(5), "fibonacci_async - 5");
duration_async_info!(fibonacci_async(6), "fibonacci_async - 6".to_string());

duration_async_debug!(fibonacci_async(7));
duration_async_debug!(fibonacci_async(8), "fibonacci_async - 8");
duration_async_debug!(fibonacci_async(9), "fibonacci_async - 9".to_string());
async fn async_fn_name_test() {
assert_eq!(fn_name!(), "async_fn_name_test()");
}
}
4 changes: 2 additions & 2 deletions src/main_loop.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -345,7 +345,7 @@ impl MainLoopHandler {
}

global_state_mut
.set_new_self_mined_tip(
.set_new_self_mined_tip_atomic(
new_block.as_ref().clone(),
new_block_info.coinbase_utxo_info.as_ref().clone(),
)
Expand Down Expand Up @@ -429,7 +429,7 @@ impl MainLoopHandler {
new_block.kernel.header.timestamp.standard_format()
);

global_state_mut.set_new_tip(new_block).await?;
global_state_mut.set_new_tip_atomic(new_block).await?;
}
}

Expand Down
9 changes: 8 additions & 1 deletion src/models/blockchain/block/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -327,7 +327,14 @@ impl Block {
difficulty: MINIMUM_DIFFICULTY.into(),
};

Self::new(header, body, BlockType::Genesis)
let block = Self::new(header, body, BlockType::Genesis);

debug!(
"Instantiated genesis block with digest\n str: {}\n hex: {}",
block.hash(),
block.hash().to_hex()
);
block
}

fn premine_distribution(_network: Network) -> Vec<(ReceivingAddress, NeptuneCoins)> {
Expand Down
Loading

0 comments on commit b24390c

Please sign in to comment.