logging_timer 0.4.0

//! This crate provides a couple of simple timers that log messages indicating the elapsed
//! time between their creation and dropping. Messages are output via the
//! [log](https://crates.io/crates/log) crate.
//!
//! Timers have names, and the log messages are constructed in such a way that they contain
//! the module, filename and line number of the place where the timer was constructed.
//!
//! Timers are usually created using the `timer!` or `stimer!` macros. The difference is
//! that `timer!` returns a timer that logs a message only when it is dropped, while `stimer!`
//! returns a timer that logs a started message as soon as it is created, and a finished
//! message when it is dropped.
//!
//! In this example "FIND_FILES" is the name of the timer (using all UPPERCASE for the timer
//! name is optional but helps make the name stand out in the log)
//!
//! ```norun
//! use logging_timer::{timer};
//!
//! fn find_files(dir: PathBuf) -> Vec<PathBuf> {
//!     let _tmr = timer!("FIND_FILES");
//!     let files = vec![];
//!
//!     // expensive operation here
//!
//!     return files;
//! } // _tmr is dropped here and a 'TimerFinished' message is logged
//!```
//!
//! Note that you have to assign the result of the macro to a variable, otherwise Rust will
//! drop the returned timer object *immediately*, which is not what you want (you want it to
//! be dropped at the end of scope).
//!
//! You can replace `timer!` with `stimer!` to get a timer that logs a starting message as
//! well, giving you a pair of 'bracketing' log messages.
//!
//! In addition, both timer macros accept [format_args!](https://doc.rust-lang.org/std/macro.format_args.html)
//! style parameters, allowing you to include extra information in the log messages.
//!
//! ```norun
//! let _tmr = timer!("FIND_FILES", "Directory = {}", dir);
//! ```
//!
//! # Outputting Intermediate Messages
//!
//! The `executing!` macro allows you to make the timer produce a message before it is dropped.
//! You can call it as many times as you want. A pseudocode example:
//!
//! ```norun
//! use logging_timer::{timer, executing};
//!
//! fn find_files(dir: PathBuf) -> Vec<PathBuf> {
//!     let tmr = timer!("FIND_FILES");
//!     let files = vec![];
//!
//!     for dir in sub_dirs(dir) {
//!         // expensive operation
//!         executing!(tmr, "Processed {}", dir);
//!     }
//!
//!     return files;
//! } // tmr is dropped here and a 'TimerFinished' message is logged
//!```
//!
//! # Controlling the Final Message
//!
//! The `finish!` macro also makes the timer log a message, but it also has the side
//! effect of suppressing the normal drop message.  `finish!` is useful when you want the final
//! message to include some information that you did not have access to until the calculation had
//! finished.
//!
//! ```norun
//! use logging_timer::{timer, executing, finish};
//!
//! fn find_files(dir: PathBuf) -> Vec<PathBuf> {
//!     let tmr = timer!("FIND_FILES");
//!     let files = vec![];
//!
//!     finish!(tmr, "Found {} files", files.len());
//!     return files;
//! } // tmr is dropped here but no message is produced.
//!```
//!
//! # Setting the log level
//!
//! By default both `timer` and `stimer` log at `Debug` level. An optional first parameter to
//! these macros allows you to set the log level. **To aid parsing of the macro arguments this
//! first parameter is terminated by a semi-colon.** For example:
//!
//! ```norun
//! let tmr1 = timer!(Level::Warn; "TIMER_AT_WARN");
//! let tmr2 = stimer!(Level::Info; "TIMER_AT_INFO");
//! ```
//! # Example of Timer Output
//!
//! The overall format will depend on how you customize the output format of the log crate, but as an illustrative example:
//!
//! ```text
//! 2019-05-30T21:41:41.847982550Z DEBUG [TimerStarting] [dnscan/src/main.rs/63] DIRECTORY_ANALYSIS
//! 2019-05-30T21:41:41.868690703Z INFO [dnlib::configuration] [dnlib/src/configuration.rs/116] Loaded configuration from "/home/phil/.dnscan/.dnscan.json"
//! 2019-05-30T21:41:41.897609281Z DEBUG [TimerFinished] [dnlib/src/io.rs/67] FIND_FILES, Elapsed=28.835275ms, Dir="/home/phil/mydotnetprojects", NumSolutions=1 NumCsproj=45, NumOtherFiles=12
//! 2019-05-30T21:41:41.955140835Z DEBUG [TimerFinished] [dnlib/src/analysis.rs/93] LOAD_SOLUTIONS, Elapsed=57.451736ms
//! 2019-05-30T21:41:42.136762196Z DEBUG [TimerFinished] [dnlib/src/analysis.rs/108] LOAD_PROJECTS, Elapsed=181.563223ms, Found 43 linked projects and 2 orphaned projects
//! 2019-05-30T21:41:42.136998556Z DEBUG [TimerStarting] [dnscan/src/main.rs/87] CALCULATE_PROJECT_GRAPH
//! 2019-05-30T21:41:42.143072972Z DEBUG [TimerExecuting] [dnscan/src/main.rs/87] CALCULATE_PROJECT_GRAPH, Elapsed=6.075205ms, Individual graphs done
//! 2019-05-30T21:41:42.149218039Z DEBUG [TimerFinished] [dnscan/src/main.rs/87] CALCULATE_PROJECT_GRAPH, Elapsed=12.219438ms, Found 19 redundant project relationships
//! 2019-05-30T21:41:42.165724712Z DEBUG [TimerFinished] [dnscan/src/main.rs/108] WRITE_OUTPUT_FILES, Elapsed=16.459312ms
//! 2019-05-30T21:41:42.166445Z INFO [TimerFinished] [dnscan/src/main.rs/63] DIRECTORY_ANALYSIS, Elapsed=318.48581ms
//! ```
//!
//! Here the `[Timer*]` blocks are the `target` field from log's [Record](https://docs.rs/log/0.4.6/log/struct.Record.html)
//! struct and `[dnscan/src/main.rs/63]` is the filename and number from `Record` - this captures the place where the timer was
//! instantiated. The module is also set, but is not shown in these examples.

use log;
use std::fmt;
use std::sync::atomic::{AtomicBool, Ordering};
use std::time::Instant;

/*
 * Sizes in bytes on 64bit Linux:
 *   level       =  8
 *   file        = 16
 *   module_path = 16
 *   line        =  4
 *   finished    =  1
 *   start_time  = 16
 *   name        = 16
 *   extra_info  = 24
 *
 *   TOTAL       = 104
 *
 * Wrapping in an Option<T> so that we can avoid most computation if log_enabled!(level)
 * returns false does not increase the size of the value at all. Rust is cool :-)
 */

 /// When this struct is dropped, it logs a message stating its name and how long
/// the execution time was. Can be used to time functions or other critical areas.
pub struct LoggingTimer<'name> {
    /// The log level. Defaults to Debug.
    level: log::Level,
    /// Set by the file!() macro to the name of the file where the timer is instantiated.
    file: &'static str,
    /// Set by the module_path!() macro to the module where the timer is instantiated.
    module_path: &'static str,
    /// Set by the line!() macro to the line number where the timer is instantiated.
    line: u32,
    /// A flag used to suppress printing of the 'Finished' message in the drop() function
    /// It is set by the finish method.
    finished: AtomicBool,
    /// The instant, in UTC, that the timer was instantiated.
    start_time: Instant,
    /// The name of the timer. Used in messages to identify it.
    name: &'name str,
    /// Any extra information to be logged along with the name. Unfortunately, due
    /// to the lifetimes associated with a `format_args!` invocation, this currently allocates
    /// if you use it.
    extra_info: Option<String>,
}

impl<'name> LoggingTimer<'name> {
    /// Constructs a new `LoggingTimer` that prints only a 'TimerFinished' message.
    /// This method is not usually called directly, use the `timer!` macro instead.
    pub fn new(
        file: &'static str,
        module_path: &'static str,
        line: u32,
        name: &'name str,
        extra_info: Option<String>,
        level: log::Level,
    ) -> Option<Self> {
        if log::log_enabled!(level) {
            Some(LoggingTimer {
                level: level,
                start_time: Instant::now(),
                file: file,
                module_path: module_path,
                line: line,
                name: name,
                finished: AtomicBool::new(false),
                extra_info: extra_info
            })
        } else {
            None
        }
    }

    /// Constructs a new `LoggingTimer` that prints a 'TimerStarting' and a 'TimerFinished' message.
    /// This method is not usually called directly, use the `stimer!` macro instead.
    pub fn with_start_message(
        file: &'static str,
        module_path: &'static str,
        line: u32,
        name: &'name str,
        extra_info: Option<String>,
        level: log::Level,
    ) -> Option<Self> {
        if log::log_enabled!(level) {
            let tmr = Self::new(file, module_path, line, name, extra_info, level).unwrap();
            tmr.log_impl(TimerTarget::Starting, None);
            Some(tmr)
        } else {
            None
        }
    }

    /// Returns how long the timer has been running for.
    pub fn elapsed(&self) -> std::time::Duration {
        self.start_time.elapsed()
    }

    /// Sets the logging level.
    /// Note that this consumes self, so that it can be called in a one-liner like this:
    ///
    /// ```norun
    /// let tmr = timer!("foo").level(Level::Trace);
    /// ```
    #[deprecated(since = "0.3", note = "Please use the first parameter to the `timer` or `stimer` macro instead")]
    pub fn level(mut self, level: log::Level) -> Self {
        self.level = level;
        self
    }

    /// Outputs a log message with a target of 'TimerExecuting' showing the current elapsed time, but does not
    /// stop the timer. This method can be called multiple times.
    /// The message can include further information via a `format_args!` approach.
    /// This method is usually not called directly, it is easier to use the `executing!` macro.
    pub fn executing(&self, args: Option<fmt::Arguments>) {
        self.log_impl(TimerTarget::Executing, args);
    }

    /// Outputs a log message with a target of 'TimerFinished' and suppresses the normal message
    /// that is output when the timer is dropped. The message can include further `format_args!`
    /// information. This method is normally called using the `finish!` macro. Calling
    /// `finish()` again will have no effect.
    pub fn finish(&self, args: Option<fmt::Arguments>) {
        if !self.finished.load(Ordering::SeqCst) {
            self.finished.store(true, Ordering::SeqCst);
            self.log_impl(TimerTarget::Finished, args);
        }
    }

    fn log_impl(&self, target: TimerTarget, args: Option<fmt::Arguments>) {
        if !log::log_enabled!(self.level) {
            return;
        }

        match (target, self.extra_info.as_ref(), args) {
            (TimerTarget::Starting, Some(info), Some(args)) => {
                self.log_record(target, format_args!("{}, {}, {}", self.name, info, args))
            }
            (TimerTarget::Starting, Some(info), None) => {
                self.log_record(target, format_args!("{}, {}", self.name, info))
            }
            (TimerTarget::Starting, None, Some(args)) => {
                self.log_record(target, format_args!("{}, {}", self.name, args))
            }
            (TimerTarget::Starting, None, None) => self.log_record(target, format_args!("{}", self.name)),

            (_, Some(info), Some(args)) => {
                self.log_record(target, format_args!("{}, Elapsed={:?}, {}, {}", self.name, self.elapsed(), info, args))
            }
            (_, Some(info), None) => {
                self.log_record(target, format_args!("{}, Elapsed={:?}, {}", self.name, self.elapsed(), info))
            }
            (_, None, Some(args)) => {
                self.log_record(target, format_args!("{}, Elapsed={:?}, {}", self.name, self.elapsed(), args))
            }
            (_, None, None) => self.log_record(target, format_args!("{}, Elapsed={:?}", self.name, self.elapsed())),
        };
    }

    fn log_record(&self, target: TimerTarget, args: fmt::Arguments) {
        log::logger().log(
            &log::RecordBuilder::new()
                .level(self.level)
                .target(match target {
                    TimerTarget::Starting => "TimerStarting",
                    TimerTarget::Executing => "TimerExecuting",
                    TimerTarget::Finished => "TimerFinished",
                })
                .file(Some(self.file))
                .module_path(Some(self.module_path))
                .line(Some(self.line))
                .args(args)
                .build(),
        );
    }
}

impl<'a> Drop for LoggingTimer<'a> {
    /// Drops the timer, outputting a log message with a target of `TimerFinished`
    /// if the `finish` method has not yet been called.
    fn drop(&mut self) {
        self.finish(None);
    }
}

#[derive(Debug, Copy, Clone)]
enum TimerTarget {
    Starting,
    Executing,
    Finished,
}

/* TODO: These macro definitions are very verbose, especially the duplication to get
 * 'level' to work, but after much hacking this was the only combination I could
 * get to work. There is probably a way to reduce the duplication, especially
 * by making the 'level' bit optional.
 */

/* TODO: Write proc-macro versions of timer and stimer which can be used to
 * decorate a function.
 */

/* TODO: Can we improve performance by doing less work depending on the enabled
 * log level? We have taken first steps towards that in `log_impl`, but we might
 * be able to avoid a lot more work, such as getting the time. Maybe introduce
 * an enum that has two variants, one the current LoggingTimer, and one 'NoOp',
 * then determine which to use in the constructors.
 */

/// Creates a timer that does not log a starting message, only a finished one.
#[macro_export]
macro_rules! timer {
    ($name:expr) => {
        {
            $crate::LoggingTimer::new(
                file!(),
                module_path!(),
                line!(),
                $name,
                None,
                Level::Debug,
                )
        }
    };

    ($level:expr; $name:expr) => {
        {
            $crate::LoggingTimer::new(
                file!(),
                module_path!(),
                line!(),
                $name,
                None,
                $level,
                )
        }
    };

    ($name:expr, $format:tt) => {
        {
            $crate::LoggingTimer::new(
                file!(),
                module_path!(),
                line!(),
                $name,
                Some(format!($format)),
                Level::Debug,
                )
        }
    };

    ($level:expr; $name:expr, $format:tt) => {
        {
            $crate::LoggingTimer::new(
                file!(),
                module_path!(),
                line!(),
                $name,
                Some(format!($format)),
                $level,
                )
        }
    };

    ($name:expr, $format:tt, $($arg:expr),*) => {
        {
            $crate::LoggingTimer::new(
                file!(),
                module_path!(),
                line!(),
                $name,
                Some(format!($format, $($arg), *)),
                Level::Debug,
                )
        }
    };

    ($level:expr; $name:expr, $format:tt, $($arg:expr),*) => {
        {
            $crate::LoggingTimer::new(
                file!(),
                module_path!(),
                line!(),
                $name,
                Some(format!($format, $($arg), *)),
                $level,
                )
        }
    };
}

/// Creates a timer that logs a starting mesage and a finished message.
#[macro_export]
macro_rules! stimer {
    ($name:expr) => {
        {
            $crate::LoggingTimer::with_start_message(
                file!(),
                module_path!(),
                line!(),
                $name,
                None,
                Level::Debug,
                )
        }
    };

    ($level:expr; $name:expr) => {
        {
            $crate::LoggingTimer::with_start_message(
                file!(),
                module_path!(),
                line!(),
                $name,
                None,
                $level,
                )
        }
    };

    ($level:expr; $name:expr, $format:tt) => {
        {
            $crate::LoggingTimer::with_start_message(
                file!(),
                module_path!(),
                line!(),
                $name,
                Some(format!($format)),
                $level,
                )
        }
    };

    ($name:expr, $format:tt) => {
        {
            $crate::LoggingTimer::with_start_message(
                file!(),
                module_path!(),
                line!(),
                $name,
                Some(format!($format)),
                Level::Debug,
                )
        }
    };

    ($name:expr, $format:tt, $($arg:expr),*) => {
        {
            $crate::LoggingTimer::with_start_message(
                file!(),
                module_path!(),
                line!(),
                $name,
                Some(format!($format, $($arg), *)),
                Level::Debug,
                )
        }
    };

    ($level:expr; $name:expr, $format:tt, $($arg:expr),*) => {
        {
            $crate::LoggingTimer::with_start_message(
                file!(),
                module_path!(),
                line!(),
                $name,
                Some(format!($format, $($arg), *)),
                $level,
                )
        }
    };
}

/// Makes an existing timer output an 'executing' mesasge.
/// Can be called multiple times.
#[macro_export]
macro_rules! executing {
    ($timer:expr) => ({
        if let Some(ref tmr) = $timer {
            tmr.executing(None);
        }
    });

    ($timer:expr, $format:tt) => ({
        if let Some(ref tmr) = $timer {
            tmr.executing(Some(format_args!($format)))
        }
    });

    ($timer:expr, $format:tt, $($arg:expr),*) => ({
        if let Some(ref tmr) = $timer {
            tmr.executing(Some(format_args!($format, $($arg), *)))
        }
    })
}

/// Makes an existing timer output a 'finished' mesasge and suppresses
/// the normal drop message.
/// Only the first call has any effect, subsequent calls will be ignored.
#[macro_export]
macro_rules! finish {
    ($timer:expr) => ({
        if let Some(ref tmr) = $timer {
            tmr.finish(None)
        }
    });

    ($timer:expr, $format:tt) => ({
        if let Some(ref tmr) = $timer {
            tmr.finish(Some(format_args!($format)))
        }
    });

    ($timer:expr, $format:tt, $($arg:expr),*) => ({
        if let Some(ref tmr) = $timer {
            tmr.finish(Some(format_args!($format, $($arg), *)))
        }
    })
}