1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69

#[cfg(feature = "profiling")]
pub mod profiling {

    use std::sync::atomic::AtomicUsize;
    use std::sync::atomic::Ordering::Relaxed;

    std::thread_local! {
        pub static DEPTH: AtomicUsize = AtomicUsize::new(0);
    }

    /// Measure the time between when this value is allocated
    /// and when it is dropped.
    pub struct Timer {
        name: String,
        start: std::time::Instant,
    }

    impl Timer {
        pub fn new(name: String) -> Self {
            let depth = DEPTH.with(|d| d.fetch_add(1, Relaxed));
            let pad = "   ".repeat(depth);

            tracing::info!("{}⏳ {} - start", pad, name);

            Self {
                name,
                start: std::time::Instant::now(),
            }
        }
    }

    impl Drop for Timer {
        fn drop(&mut self) {
            let elapsed = self.start.elapsed().as_millis();

            let depth = DEPTH.with(|d| d.fetch_sub(1, Relaxed));
            let pad = "   ".repeat(depth - 1);

            tracing::info!("{}⏳ {} - elapsed: {}ms", pad, self.name, elapsed);
        }
    }
}

/// Measure the time until the current scope ends.
///
/// Only enabled when the "profiling" feature is enabled.
///
/// ## Example
///
/// ```rust
/// use ibc_relayer::time;
///
/// time!("full scope");
///
/// let x = {
///   time!("inner {}", "scope");
///
///   42
///   // "inner scope" timer ends here
/// };
/// // "full scope" timer ends here
/// ```
#[macro_export]
macro_rules! time {
    ($($arg:tt)*) => {
        #[cfg(feature = "profiling")]
        let _timer = $crate::macros::profiling::Timer::new(format!($($arg)*));
    };
}