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
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157

//! The crate provides macros, which measure the time in ms until end of scope
//!
//! This is done by creating an object, which measures the time. The time is printed when the object is dropped.
//! 
//! The logging behaviour is the same as other log macros like info!(..)
//!
//! ### Examples
//!
//! ```rust
//! #[macro_use]
//! extern crate measure_time;
//! fn main() {
//!     info_time!("measure function");
//!     {
//!         debug_time!("{:?}", "measuring block");
//!         let mut sum = 0;
//!         for el in 0..50000 {
//!             sum+=el;
//!         }
//!         println!("{:?}", sum);
//!     }
//!     trace_time!("{:?}", "trace");
//!     print_time!("print");
//!     error_time!(target: "measure_time", "custom target");
//!     // --> prints "yep took ...", "measuring function took 0.0135ms"
//! }
//! ```
//!
#[macro_use]
pub extern crate log;
pub use log::*;

#[macro_export]
macro_rules! log_time {
    (target: $target:expr, $lvl:expr, $lvl2:expr, $($arg:tt)+) => (
        #[allow(unused_variables)] 
        let time = if log_enabled!($lvl) {
            Some($crate::MeasureTime::new($target, module_path!(), file!(), line!(), format!($($arg)+), $lvl2) ) 
        } else{
            None 
        };
    );
}

/// logs the time with the error! macro
#[macro_export]
macro_rules! error_time {
    (target: $target:expr, $($arg:tt)+) => (
        log_time!(target: $target, $crate::Level::Error, $crate::LevelFilter::Error, $($arg)+)
    );
    ($($arg:tt)+) => (log_time!(target: module_path!(), $crate::Level::Error, $crate::LevelFilter::Error, $($arg)+) )
}
/// logs the time with the warn! macro
#[macro_export]
macro_rules! warn_time {
    (target: $target:expr, $($arg:tt)+) => (
        log_time!(target: $target, $crate::Level::Warn, $crate::LevelFilter::Warn, $($arg)+)
    );
    ($($arg:tt)+) => (log_time!(target: module_path!(), $crate::Level::Warn, $crate::LevelFilter::Warn, $($arg)+) )
}
/// logs the time with the info! macro
#[macro_export]
macro_rules! info_time {
    (target: $target:expr, $($arg:tt)+) => (
        log_time!(target: $target, $crate::Level::Info, $crate::LevelFilter::Info, $($arg)+)
    );
    ($($arg:tt)+) => (log_time!(target: module_path!(), $crate::Level::Info, $crate::LevelFilter::Info, $($arg)+) )
}
/// logs the time with the debug! macro
#[macro_export]
macro_rules! debug_time {
    (target: $target:expr, $($arg:tt)+) => (
        log_time!(target: $target, $crate::Level::Debug, $crate::LevelFilter::Debug, $($arg)+)
    );
    ($($arg:tt)+) => (log_time!(target: module_path!(), $crate::Level::Debug, $crate::LevelFilter::Debug, $($arg)+) )
}
/// logs the time with the trace! macro
#[macro_export]
macro_rules! trace_time {
    (target: $target:expr, $($arg:tt)+) => (
        log_time!(target: $target, $crate::Level::Trace, $crate::LevelFilter::Trace, $($arg)+)
    );
    ($($arg:tt)+) => (log_time!(target: module_path!(), $crate::Level::Trace, $crate::LevelFilter::Trace, $($arg)+) )
}
/// logs the time with the print! macro
#[macro_export]
macro_rules! print_time {($($arg:tt)+) => {#[allow(unused_variables)] let time = $crate::MeasureTime::new(module_path!(), module_path!(), file!(), line!(), format!($($arg)+), $crate::LevelFilter::Off); } }

#[cfg(test)]
mod tests {
    #[test]
    fn funcy_func() {
        trace_time!("{:?}", "trace");
        debug_time!("{:?}", "debug");
        info_time!("measure function");
        {
            debug_time!("{:?}", "measuring block");
            let mut sum = 0;
            for el in 0..50000 {
                sum+=el;
            }
            println!("{:?}", sum);
        }

        print_time!("print");
        error_time!("error_time");

        trace_time!(target: "trace_time", "custom target");
        debug_time!(target: "debug_time", "custom target");
        info_time!(target: "info_time", "custom target");
        error_time!(target: "measure_time", "custom target");
    }
}


#[derive(Debug)]
pub struct MeasureTime {
    name: String,
    target: &'static str,
    module_path: &'static str,
    file: &'static str,
    line: u32,
    start: std::time::Instant,
    level: log::LevelFilter
}
impl MeasureTime {
    pub fn new<S: Into<String>>(target: &'static str, module_path: &'static str, file: &'static str, line: u32, name: S, level:log::LevelFilter) -> Self {MeasureTime{target, module_path, file, line, name:name.into(), start: std::time::Instant::now(), level:level} }
}

impl Drop for MeasureTime {
    fn drop(&mut self) {
        let time_in_ms = (self.start.elapsed().as_secs() as f64 * 1_000.0) + (self.start.elapsed().subsec_nanos() as f64 / 1000_000.0);

        let time = match time_in_ms as u64 {
            0..=3000 => format!("{}ms", time_in_ms),
            3000..=60000 => format!("{:.2}s", time_in_ms/1000.0),
            _ => format!("{:.2}m", time_in_ms/1000.0/60.0),
        };

        if let Some(level) = self.level.to_level() {
            log::logger().log(
                &log::Record::builder()
                    .args(format_args!("{} took {}", self.name, time))
                    .level(level)
                    .target(self.target)
                    .module_path(Some(self.module_path))
                    .file(Some(self.file))
                    .line(Some(self.line))
                    .build(),
            );
        }else{
            println!("{} took {}", self.name, time);
        }

    }
}