rprofile 0.1.3

A simple crate to measure processor timings in selected samples of execution
Documentation 
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

pub use std::{sync::Mutex, time::Duration};

pub use cpu_time::ProcessTime;
pub use dashmap::DashMap;
pub use lazy_static::lazy_static;

lazy_static! {
    pub static ref cpu_times: dashmap::DashMap<String, (usize, Duration)> = DashMap::new();
    pub static ref enabled: Mutex<bool> = Mutex::new(false);
    pub static ref overhead_time: Mutex<Vec<Duration>> = Mutex::new(Vec::new());
}

pub fn start() {
    let mut e = enabled.try_lock().unwrap();
    *e = true;
}

pub fn stop() {
    let mut e = enabled.try_lock().unwrap();
    *e = false;
    *overhead_time.lock().unwrap() = Vec::new();
}

pub fn show() {
    cpu_times.clone().into_iter().for_each(|(s, (count, dur))| {
        println!(
            "{: <24}: {: <10} calls | {: <10} total ms",
            s,
            count,
            dur.as_micros() as f64 / 1000.0,
        )
    })
}

/// Example usage
///
///```rust
/// use rprofile::*;
///
/// fn k() {
///     trace_cpu!("k", for _i in 0..1000 {});
/// }
///
/// fn f() {
///     for i in 0..100 {
///         trace_cpu!("g", g());
///     }
///     for j in 0..10000 {}
/// }
///
/// fn g() {
///     for i in 0..100 {
///         k()
///     }
/// }
/// fn main() {
///     start();
///     trace_cpu!("f1", f());
///     trace_cpu!("f2", f());
///     stop();
///     f();
///     show();
///     assert!(false)
/// }
/// ```
#[macro_export]
macro_rules! trace_cpu {
    ( $name: literal, $x:expr ) => {{
        let now = ProcessTime::now();
        if !*enabled.lock().unwrap() {
            return $x;
        }
        if !cpu_times.contains_key($name) {
            cpu_times.insert($name.to_string(), (0, Duration::from_millis(0)));
        }
        overhead_time
            .lock()
            .unwrap()
            .push(now.try_elapsed().unwrap());
        let ret = $x;
        let elapsed = now.try_elapsed().unwrap();
        let mut vec = overhead_time.lock().unwrap();
        let top = vec.pop().unwrap();
        let mut tpl = cpu_times.get_mut($name).unwrap();
        (*tpl).0 += 1;
        (*tpl).1 += elapsed - top;
        let new_vec = vec.clone();
        let total_time = now.try_elapsed().unwrap();
        *vec = new_vec
            .into_iter()
            .map(|t| t + total_time - elapsed + Duration::from_nanos(800))
            .collect::<Vec<_>>();
        ret
    }};
}