Crate logging_timer

Provides a couple of simple timers that output messages indicating the elapsed time via the log crate when they are dropped.

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.

Example - "Find Files" is the name of the timer:

use logging_timer::{timer};

fn find_files(dir: PathBuf) -> List<PathBuf> {
    let _tmr = timer!("Find Files");
    let files = vec![];

    // expensive operation here

    return files;
} // _tmr is dropped here and a 'TimerFinished' message is logged

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! style parameters, allowing you to include extra information in the log messages.

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:

use logging_timer::{timer, executing};

fn find_files(dir: PathBuf) -> List<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

Finally, 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.

use logging_timer::{timer, executing, finish};

fn find_files(dir: PathBuf) -> List<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.

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:

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] Elapsed=28.835275ms, Find Files, Dir="/home/phil/mydotnetprojects", NumSolutions=1 NumCsproj=45, NumOtherFiles=12
2019-05-30T21:41:41.955140835Z DEBUG [TimerFinished] [dnlib/src/analysis.rs/93] Elapsed=57.451736ms, Load And Analyze Solution files
2019-05-30T21:41:42.136762196Z DEBUG [TimerFinished] [dnlib/src/analysis.rs/108] Elapsed=181.563223ms, Load And Analyze Project files, Found 43 linked projects and 2 orphaned projects
2019-05-30T21:41:42.136998556Z DEBUG [TimerStarting] [dnscan/src/main.rs/87] Calculate project graphs and redundant projects
2019-05-30T21:41:42.143072972Z DEBUG [TimerExecuting] [dnscan/src/main.rs/87] Elapsed=6.075205ms, Calculate project graphs and redundant projects, Individual graphs done
2019-05-30T21:41:42.149218039Z DEBUG [TimerFinished] [dnscan/src/main.rs/87] Elapsed=12.219438ms, Calculate project graphs and redundant projects, Found 19 redundant project relationships
2019-05-30T21:41:42.165724712Z DEBUG [TimerFinished] [dnscan/src/main.rs/108] Elapsed=16.459312ms, Write output files
2019-05-30T21:41:42.166445Z INFO [TimerFinished] [dnscan/src/main.rs/63] Elapsed=318.48581ms, Directory Analysis

Here the [Timer*] blocks are the target field from log's Record 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. Note how the timer named 'Directory Analysis' is the only one to log both a starting and ending message.

By default messages are output at DEBUG level, you can control this using the level() builder method:

let _tmr = timer!("Directory Analysis").level(Level::Info);

(There is a bug, this does not work for stimer! yet, only timer!)

Macros

executing	Makes an existing timer output an 'executing' mesasge. Can be called multiple times.
finish	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.
stimer	Creates a timer that logs a starting mesage and a finished message.
timer	Creates a timer that does not log a starting message, only a finished one.

Structs

LoggingTimer

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.