Rust 的日志计时器

此 crate 提供了一些简单的计时器，当它们被丢弃时会记录创建和丢弃之间的经过时间。消息通过 log crate 输出。

计时器有名称，日志消息的构造方式使得它们包含计时器被构造的位置的模块、文件名和行号。

使用计时器属性

开始使用最简单的方法是使用两个属性之一 time 或 stime 来监测一个函数，函数的名称用作计时器的名称

use logging_timer::{time, stime};

#[time]
fn find_files(dir: PathBuf) -> Vec<PathBuf> {
    let files = vec![];

    // expensive operation here

    return files;
} // 'TimerFinished' message is logged here

这两个属性接受两个可选参数，用于指定日志级别和一个模式，其中将替换函数的名称。模式有助于区分具有相同名称的多个函数：例如，在同一个模块中有多个具有相同名称的函数时，“new”可能出现在不同的结构体中。

#[time]                                 // Use default log level of Debug
#[time("info")]                         // Set custom log level
#[time("info", "FirstStruct::{}")]      // Logs "FirstStruct::new()" at Info
#[time("info", "SecondStruct::{}")]     // Logs "SecondStruct::new()" at Info
#[time("ThirdStruct::{}")]              // Logs "ThirdStruct::new()" at Debug
#[time("never")]                        // Turn off instrumentation at compile time

有效的日志级别值为 error、warn、info、debug 和 trace。默认为 debug。你也可以指定 'never' 来在编译时完全禁用监测。日志级别应首先出现，但如上所示可以省略。宏通过查找 "{}" 来区分日志级别和模式。

使用内联计时器

通过两种类似于函数的宏形式提供了更多的灵活性，包括记录额外信息，分别是 timer! 和 stimer!。二者的区别在于 timer! 返回的计时器仅在它被丢弃时记录消息，而 stimer! 返回的计时器在创建时立即记录一个开始消息，在丢弃时记录一个完成消息。还有两个相应的 proc-macros，即 time 和 stimer，可用于使用计时器对函数进行跟踪。

在这个例子中，“FIND_FILES” 是计时器的名称（使用全部大写字母作为计时器名称是可选的，但有助于使名称在日志中更加突出）

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

您可以将 timer! 替换为 stimer! 以获得一个记录开始消息的计时器，从而提供一对“括号”日志消息。

此外，这两个计时器宏都接受类似于 format_args! 的样式参数，允许您在日志消息中包含额外信息。

let _tmr = timer!("FIND_FILES", "Directory = {}", dir);

输出中间消息

executing! 宏允许计时器在它被丢弃之前生成消息。您可以多次调用它。伪代码示例

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

控制最终消息

finish! 宏也允许计时器记录消息，但它还有一个副作用，即抑制正常的丢弃消息。当您希望最终消息包含一些在计算完成后才可获得的信息时，finish! 是有用的。

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.

设置日志级别

默认情况下，timer 和 stimer 都记录在 Debug 级别。这些宏的可选第一个参数允许您设置日志级别。为了帮助解析宏参数，这个第一个参数以分号结束。例如

let tmr1 = timer!(Level::Warn; "TIMER_AT_WARN");
let tmr2 = stimer!(Level::Info; "TIMER_AT_INFO");

计时器输出示例

整体格式将取决于您如何自定义日志crate的输出格式，但作为一个示例

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

在这里，[Timer*] 块是 log 的 Record 结构中的 target 字段，而 [dnscan/src/main.rs/63] 是来自 Record 的文件名和数字 - 这捕捉了计时器被实例化的位置。模块也被设置，但在此示例中没有显示。

测量的是什么？

记录的时间是 wall-clock time - 函数执行开始与函数末尾计时器丢弃之间的时间差。

wall clock time 不一定是函数在 CPU 上执行的时间长度。这对于普通函数来说是因为线程抢占，但对于可能在其生命周期中花费大量时间挂起的 async 函数来说更是如此。

对于更复杂的用法，您可能需要查看 Tokio Tracing crate。

代码示例

在 examples 文件夹中还有一个示例程序，演示了所有不同的用法。要运行，请克隆仓库，然后在 Linux 中执行

RUST_LOG=debug cargo run --example logging_demo

如果您在 Windows 上，在 PowerShell 中可以这样做

$env:RUST_LOG="debug"
cargo run --example logging_demo

历史

请参阅 CHANGELOG。

性能

timer 和 stimer 宏返回一个 Option<LoggingTimer>。方法 log_enabled 用于检查是否在请求的级别启用了日志记录。如果未启用日志记录，则返回 None。这避免了在定时器为空操作的情况下进行大多数计算，因此以下循环在我的2012年款Intel i7上大约需要4毫秒创建和销毁100万个定时器。

for _ in 0..1_000_000 {
    let _tmr = stimer!("TEMP");
}

相比之下，库的v0.3版本始终返回一个 LoggingTimer，循环耗时是十倍。

在64位Linux上，Option<LoggingTimer> 的大小为104字节。