Rust性能分析插件logging_timer_proc_macros使用指南

logging_timer_proc_macros是一个基于过程宏的Rust性能分析工具，它可以方便地测量代码块的执行时间并将结果记录到日志中。

安装

在Cargo.toml中添加依赖：

[dependencies]
logging_timer_proc_macros = "1.0"
log = "0.4"  # 需要配合log crate使用

基本用法

1. 测量函数执行时间

使用#[time("message")]属性宏来测量整个函数的执行时间：

use logging_timer_proc_macros::time;
use log::info;

#[time("Function execution")]
fn my_function() {
    // 这里是一些耗时操作
    std::thread::sleep(std::time::Duration::from_millis(100));
}

fn main() {
    env_logger::init();
    my_function();
}

输出示例：

INFO [logging_timer] Starting 'Function execution'
INFO [logging_timer] Finished 'Function execution' in 100.23ms

2. 测量代码块执行时间

使用time!宏来测量特定代码块的执行时间：

use logging_timer_proc_macros::time;
use log::info;

fn main() {
    env_logger::init();
    
    time!("Block execution", {
        // 这里是一些耗时操作
        std::thread::sleep(std::time::Duration::from_millis(50));
    });
    
    // 也可以这样写
    let result = time!("Block with return value", {
        std::thread::sleep(std::time::Duration::from_millis(20));
        42
    });
    info!("Result: {}", result);
}

3. 嵌套计时

宏支持嵌套使用，可以测量复杂代码结构中的各个部分：

#[time("Outer function")]
fn outer_function() {
    std::thread::sleep(std::time::Duration::from_millis(50));
    
    #[time("Inner function")]
    fn inner_function() {
        std::thread::sleep(std::time::Duration::from_millis(20));
    }
    
    inner_function();
}

高级用法

1. 自定义日志级别

默认使用info!级别，可以指定其他日志级别：

#[time("Function execution", level = "debug")]
fn my_function() {
    // ...
}

time!("Block execution", level = "warn", {
    // ...
});

2. 条件性计时

只在特定条件下启用计时：

#[time("Function execution", enabled = cfg!(debug_assertions))]
fn debug_only_function() {
    // 这段代码只在debug模式下计时
}

3. 多线程支持

宏会自动处理多线程环境，每个线程会有独立的计时：

use std::thread;

#[time("Thread work")]
fn do_work() {
    std::thread::sleep(std::time::Duration::from_millis(100));
}

fn main() {
    env_logger::init();
    
    let handles: Vec<_> = (0..3).map(|_| {
        thread::spawn(|| {
            do_work();
        })
    }).collect();
    
    for handle in handles {
        handle.join().unwrap();
    }
}

最佳实践

1. 在开发环境中广泛使用性能分析，生产环境中选择性使用
2. 为计时器使用有意义的描述信息
3. 避免在高频调用的函数中使用（除非必要）
4. 结合log crate的过滤功能控制输出

注意事项

1. 需要配合log crate使用（如env_logger、simple_logger等）
2. 会引入少量性能开销（主要是日志记录部分）
3. 不适合测量极短时间（纳秒级）的操作

这个工具特别适合在开发阶段识别性能瓶颈，或者在复杂系统中监控关键路径的执行时间。

完整示例代码

下面是一个综合使用logging_timer_proc_macros的完整示例：

use logging_timer_proc_macros::{time, time_};
use log::{info, warn};

// 测量函数执行时间
#[time("Database query")]
fn query_database() -> Vec<String> {
    // 模拟数据库查询
    std::thread::sleep(std::time::Duration::from_millis(80));
    vec!["data1".to_string(), "data2".to_string()]
}

// 条件性计时 - 只在debug模式启用
#[time("Expensive calculation", enabled = cfg!(debug_assertions))]
fn expensive_calculation() -> i32 {
    std::thread::sleep(std::time::Duration::from_millis(30));
    42
}

fn main() {
    // 初始化日志
    env_logger::init();
    
    // 示例1: 测量函数执行时间
    let data = query_database();
    info!("Got {} items", data.len());
    
    // 示例2: 测量代码块执行时间
    let result = time!("Complex processing", {
        let mut total = 0;
        for i in 0..5 {
            // 嵌套计时
            time!("Inner loop iteration", {
                std::thread::sleep(std::time::Duration::from_millis(10));
                total += i;
            });
        }
        total
    });
    info!("Processing result: {}", result);
    
    // 示例3: 自定义日志级别
    time_!("Warning level timer", level = "warn", {
        std::thread::sleep(std::time::Duration::from_millis(15));
    });
    
    // 示例4: 条件性计时函数
    let calc_result = expensive_calculation();
    warn!("Calculation result: {}", calc_result);
    
    // 示例5: 多线程计时
    let handles: Vec<_> = (0..2).map(|i| {
        std::thread::spawn(move || {
            #[time("Thread worker")]
            fn worker_task(id: usize) {
                std::thread::sleep(std::time::Duration::from_millis(50 + (id as u64) * 20));
            }
            worker_task(i);
        })
    }).collect();
    
    for handle in handles {
        handle.join().unwrap();
    }
}

输出示例：

INFO [logging_timer] Starting 'Database query'
INFO [logging_timer] Finished 'Database query' in 80.12ms
INFO Got 2 items
INFO [logging_timer] Starting 'Complex processing'
INFO [logging_timer] Starting 'Inner loop iteration'
INFO [logging_timer] Finished 'Inner loop iteration' in 10.05ms
INFO [logging_timer] Starting 'Inner loop iteration'
INFO [logging_timer] Finished 'Inner loop iteration' in 10.03ms
INFO [logging_timer] Starting 'Inner loop iteration'
INFO [logging_timer] Finished 'Inner loop iteration' in 10.02ms
INFO [logging_timer] Starting 'Inner loop iteration'
INFO [logging_timer] Finished 'Inner loop iteration' in 10.04ms
INFO [logging_timer] Starting 'Inner loop iteration'
INFO [logging_timer] Finished 'Inner loop iteration' in 10.01ms
INFO [logging_timer] Finished 'Complex processing' in 50.23ms
INFO Processing result: 10
WARN [logging_timer] Starting 'Warning level timer'
WARN [logging_timer] Finished 'Warning level timer' in 15.08ms
WARN [logging_timer] Starting 'Expensive calculation'
WARN [logging_timer] Finished 'Expensive calculation' in 30.15ms
WARN Calculation result: 42
INFO [logging_timer] Starting 'Thread worker'
INFO [logging_timer] Starting 'Thread worker'
INFO [logging_timer] Finished 'Thread worker' in 50.11ms
INFO [logging_timer] Finished 'Thread worker' in 70.18ms