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.
Neptune-Crypto · Apr 9, 2024 · e61ef78 · e61ef78
1 parent 0869f4c
commit e61ef78
Show file tree

Hide file tree

Showing 3 changed files with 212 additions and 31 deletions.
diff --git 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<Local>`, ie local-time.
 pub fn utc_timestamp_to_localtime<T>(timestamp: T) -> DateTime<Local>

diff --git a/src/macros.rs 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
@@ -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