From a5a7d5a9dacabf16b33891735227ed0d2e4fd587 Mon Sep 17 00:00:00 2001 From: danda Date: Mon, 8 Apr 2024 17:05:08 -0700 Subject: [PATCH] feat: make duration macros more flexible Changes: * Moves the duration macros into new module crate::macros * adds macros duration_info!, duration_debug!, duration_async_info!, and duration_async_debug! * duration! and duration_async! now use log-level TRACE by default. * adds an optional message string to each macro. * adds tests to ensure that each usage variant will compile. In total, the caller can now: * log duration to trace, debug, info log-levels * include an optional descriptive message. --- src/lib.rs | 31 +----- src/macros.rs | 210 ++++++++++++++++++++++++++++++++++++++++ src/models/state/mod.rs | 2 +- 3 files changed, 212 insertions(+), 31 deletions(-) create mode 100644 src/macros.rs diff --git a/src/lib.rs b/src/lib.rs index 85313fbf..92065fe9 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -8,6 +8,7 @@ pub mod config_models; pub mod connect_to_peers; pub mod database; pub mod locks; +pub mod macros; pub mod main_loop; pub mod mine_loop; pub mod models; @@ -289,36 +290,6 @@ where (output, total_time) } -#[macro_export] -macro_rules! log_duration { - ($args: expr) => {{ - let (output, duration) = $crate::time_fn_call(|| $args); - tracing::debug!( - "at {}:{}\n-- executed expression --\n{}\n -- duration: {} secs --", - file!(), - line!(), - stringify!($args), - duration - ); - output - }}; -} - -#[macro_export] -macro_rules! log_duration_async { - ($args: expr) => {{ - let (output, duration) = $crate::time_fn_call_async({ $args }).await; - tracing::debug!( - "at {}:{}\n-- executed async expression --\n{}\n -- duration: {} secs --", - file!(), - line!(), - stringify!($args), - duration - ); - output - }}; -} - /// Converts a UTC millisecond timestamp (millis since 1970 UTC) into /// a `DateTime`, ie local-time. pub fn utc_timestamp_to_localtime(timestamp: T) -> DateTime diff --git a/src/macros.rs b/src/macros.rs new file mode 100644 index 00000000..d6e69d2d --- /dev/null +++ b/src/macros.rs @@ -0,0 +1,210 @@ +/// 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), + } + output + }}; + ($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 + }}; + ($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 +// use crate::macros::xxxxx; +// +// 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; +#[allow(unused_imports)] +pub(crate) use duration_debug; +#[allow(unused_imports)] +pub(crate) use duration_info; + +#[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()); + } + + #[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()); + } +} diff --git a/src/models/state/mod.rs b/src/models/state/mod.rs index 151b3498..6ab67bce 100644 --- a/src/models/state/mod.rs +++ b/src/models/state/mod.rs @@ -1186,7 +1186,7 @@ impl GlobalState { Ok(()) } - crate::log_duration_async!(store_block_internal_worker( + crate::macros::duration_async_info!(store_block_internal_worker( self, new_block, coinbase_utxo_info