crude_profiler/
lib.rs

1//! A library for some simple manual profiling.
2//!
3//! This is a slightly silly profiling library, which requires you to
4//! manually annotate your code to obtain profiling information.  On
5//! the plus side, this means you aren't overwhelmed with detail, and
6//! that you can profile portions of functions, or just the functions
7//! you care about.  On the down side, you end up having to insert a
8//! bunch of annotations just to get information.  You also need to
9//! write the profiling information to a file or stdout on your own.
10//!
11//! One possible use is to print out a simple table of where time was
12//! spent, e.g. 5% initializing, 95% computing.  Another would be if
13//! you want to profile while ensuring that all time spent sleeping
14//! (or waiting for another process) is accounted for.
15//!
16//! # Example
17//!
18//! ```
19//! let _g = crude_profiler::push("test one");
20//! // ... do some work here
21//! _g.replace("test two");
22//! println!("{}", crude_profiler::report());
23//! ```
24
25#[macro_use]
26extern crate lazy_static;
27
28use std::sync::Mutex;
29use std::collections::HashMap;
30use std::collections::hash_map::{Entry};
31
32struct Profile {
33    times: HashMap<Vec<&'static str>, std::time::Duration>,
34    counts: HashMap<Vec<&'static str>, usize>,
35    stack: Vec<&'static str>,
36    started: std::time::Instant,
37}
38
39fn add_to_map<K: std::hash::Hash + std::cmp::Eq>(m: &mut HashMap<K, std::time::Duration>,
40                                                 k: K, d: std::time::Duration) {
41    match m.entry(k) {
42        Entry::Occupied(mut o) => {
43            *o.get_mut() += d;
44        },
45        Entry::Vacant(v) => {
46            v.insert(d);
47        },
48    }
49}
50fn increment_map<K: std::hash::Hash + std::cmp::Eq>(m: &mut HashMap<K, usize>,
51                                                    k: K, n: usize) {
52    match m.entry(k) {
53        Entry::Occupied(mut o) => {
54            *o.get_mut() += n;
55        },
56        Entry::Vacant(v) => {
57            v.insert(n);
58        },
59    }
60}
61
62impl Profile {
63    fn new() -> Profile {
64        Profile {
65            times: HashMap::new(),
66            counts: HashMap::new(),
67            started: std::time::Instant::now(),
68            stack: Vec::new(),
69        }
70    }
71    fn add_time(&mut self, now: std::time::Instant) {
72        if now > self.started {
73            let d = now.duration_since(self.started);
74            add_to_map(&mut self.times, self.stack.clone(), d);
75        }
76    }
77}
78
79lazy_static! {
80    static ref PROFILE: Mutex<Profile> = Mutex::new(Profile::new());
81}
82
83/// A `Guard` causes a task to end when it is dropped.
84pub struct Guard {
85}
86
87impl Drop for Guard {
88    fn drop(&mut self) {
89        let now = std::time::Instant::now();
90        let mut m = PROFILE.lock().unwrap();
91        m.add_time(now);
92        m.stack.pop();
93        m.started = std::time::Instant::now();
94    }
95}
96
97impl Guard {
98    /// Replace the last task pushed (or replaced) with a new one.
99    ///
100    /// # Example
101    ///
102    /// ```
103    /// let _g = crude_profiler::push("test one");
104    /// std::thread::sleep(std::time::Duration::from_secs(2));
105    /// _g.replace("test two");
106    /// std::thread::sleep(std::time::Duration::from_secs(2));
107    /// println!("{}", crude_profiler::report());
108    /// ```
109    pub fn replace(&self, task: &'static str) {
110        let now = std::time::Instant::now();
111        let mut m = PROFILE.lock().unwrap();
112        m.add_time(now);
113        m.stack.pop();
114        m.stack.push(task);
115        let st = m.stack.clone();
116        increment_map(&mut m.counts, st, 1);
117        m.started = std::time::Instant::now();
118    }
119}
120
121/// Push a task to the stack of tasks.  The task will continue until
122/// the `Guard` is dropped.
123///
124/// # Example
125///
126/// ```
127/// let _g = crude_profiler::push("test one");
128/// println!("{}", crude_profiler::report());
129/// ```
130pub fn push(task: &'static str) -> Guard {
131    let now = std::time::Instant::now();
132    let mut m = PROFILE.lock().unwrap();
133    m.add_time(now);
134    m.stack.push(task);
135    let st = m.stack.clone();
136    increment_map(&mut m.counts, st, 1);
137    m.started = std::time::Instant::now();
138    Guard {}
139}
140
141/// Forget any prior timings.
142pub fn clear() {
143    let mut m = PROFILE.lock().unwrap();
144    m.times = HashMap::new();
145    m.counts = HashMap::new();
146    m.stack = Vec::new();
147    m.started = std::time::Instant::now();
148}
149
150fn pretty_stack(v: &Vec<&'static str>) -> String {
151    let mut out = String::new();
152    for s in v {
153        out.push_str(s);
154        out.push_str(":");
155    }
156    out
157}
158
159fn duration_to_f64(t: std::time::Duration) -> f64 {
160    t.as_secs() as f64 + (t.subsec_nanos() as f64)*1e-9
161}
162
163fn pretty_time(t: f64) -> String {
164    if t < 1e-7 {
165        format!("{:.2} ns", t*1e9)
166    } else if t < 1e-4 {
167        format!("{:.2} us", t*1e6)
168    } else if t < 1e-2 {
169        format!("{:.2} ms", t*1e3)
170    } else if t >= 1e2 {
171        format!("{:.2e} s", t)
172    } else {
173        format!("{:.2} s", t)
174    }
175}
176
177/// Create a string that holds a report of time used.  This is
178/// currently the *only* way to extract timings data, so obviously it
179/// isn't very automation-friendly.
180pub fn report() -> String {
181    let now = std::time::Instant::now();
182    let mut m = PROFILE.lock().unwrap();
183    m.add_time(now);
184    let mut out = String::new();
185    let mut total_time = std::time::Duration::from_secs(0);
186    for &v in m.times.values() {
187        total_time += v;
188    }
189    let mut keys: Vec<_> = m.times.keys().collect();
190    keys.sort();
191    let mut cum: HashMap<&'static str, std::time::Duration> = HashMap::new();
192    let mut cumcount: HashMap<&'static str, usize> = HashMap::new();
193    for &k in keys.iter() {
194        for &s in k.iter() {
195            add_to_map(&mut cum, s, m.times[k]);
196            increment_map(&mut cumcount, s, m.counts[k]);
197        }
198    }
199    let mut shortkeys: Vec<_> = cum.keys().collect();
200    shortkeys.sort_by_key(|&s| cum[s]);
201    shortkeys.reverse();
202    let total_f64 = duration_to_f64(total_time);
203    for s in shortkeys {
204        let mut ways: HashMap<Vec<&'static str>, std::time::Duration> = HashMap::new();
205        let mut wayscount: HashMap<Vec<&'static str>, usize> = HashMap::new();
206        for &k in keys.iter().filter(|&k| k.contains(s)) {
207            let mut vv = Vec::from(k.split(|&ss| ss == *s).next().unwrap());
208            vv.push(s);
209            add_to_map(&mut ways, vv.clone(), m.times[k]);
210            increment_map(&mut wayscount, vv, m.counts[k]);
211        }
212        let mut waykeys: Vec<_> = ways.keys().collect();
213        waykeys.sort_by_key(|&k| ways[k]);
214        waykeys.reverse();
215        let percent = 100.0*duration_to_f64(cum[s])/total_f64;
216        if waykeys.len() > 1 {
217            out.push_str(&format!("{:4.1}% {} {} ({}, {})\n",
218                                  percent, &s,
219                                  pretty_time(duration_to_f64(cum[s])), cumcount[s],
220                                  pretty_time(duration_to_f64(cum[s])/cumcount[s] as f64)));
221            for &k in waykeys.iter().filter(|&k| k.contains(s)) {
222                let percent = 100.0*duration_to_f64(ways[k])/total_f64;
223                out.push_str(&format!("      {:4.1}% {} {} ({}, {})\n",
224                                      percent, &pretty_stack(k),
225                                      pretty_time(duration_to_f64(ways[k])),
226                                      wayscount[k],
227                                      pretty_time(duration_to_f64(ways[k])/wayscount[k] as f64)));
228            }
229        } else {
230            out.push_str(&format!("{:4.1}% {} {} ({}, {})\n", percent,
231                                  &pretty_stack(waykeys[0]),
232                                  pretty_time(duration_to_f64(cum[s])),
233                                  cumcount[s],
234                                  pretty_time(duration_to_f64(cum[s])/cumcount[s] as f64)));
235        }
236    }
237    // out.push_str(&format!("{:?}", m.times));
238    out
239}
240
241#[cfg(test)]
242mod tests {
243    use super::*;
244
245    lazy_static! {
246        static ref TEST_LOCK: Mutex<()> = Mutex::new(());
247    }
248
249    #[test]
250    fn it_works() {
251        let mut _m = TEST_LOCK.lock().unwrap();
252        clear();
253        push("hello world");
254        let rep = report();
255        println!("\n{}", rep);
256        assert!(rep.contains("hello world"));
257    }
258    #[test]
259    fn nesting() {
260        let mut _m = TEST_LOCK.lock().unwrap();
261        clear();
262        {
263            let _a = push("hello");
264            let _b = push("world");
265        }
266        let rep = report();
267        println!("\n{}", rep);
268        assert!(rep.contains("hello:world"));
269    }
270    #[test]
271    fn replace_works() {
272        let mut _m = TEST_LOCK.lock().unwrap();
273        clear();
274        {
275            let _a = push("first");
276            let _b = push("greet");
277            _b.replace("world");
278        }
279        {
280            let _a = push("second");
281            let _b = push("greet");
282            _b.replace("world");
283        }
284        let rep = report();
285        println!("\n{}", rep);
286        assert!(!rep.contains("hello:world"));
287        assert!(rep.contains("first:world"));
288        assert!(rep.contains("first:greet"));
289        assert!(rep.contains("second:world"));
290        assert!(rep.contains("second:greet"));
291    }
292    #[test]
293    fn replace_timings() {
294        let mut _m = TEST_LOCK.lock().unwrap();
295        clear();
296        {
297            let _a = push("first");
298            std::thread::sleep(std::time::Duration::from_secs(2));
299            let _b = push("hello");
300            std::thread::sleep(std::time::Duration::from_secs(3));
301            _b.replace("world");
302            std::thread::sleep(std::time::Duration::from_secs(1));
303        }
304        {
305            let _a = push("second");
306            std::thread::sleep(std::time::Duration::from_secs(1));
307            let _b = push("greet");
308            std::thread::sleep(std::time::Duration::from_secs(4));
309            _b.replace("world");
310            std::thread::sleep(std::time::Duration::from_secs(3));
311        }
312        let rep = report();
313        println!("\n{}", rep);
314        assert!(!rep.contains("hello:world"));
315        assert!(rep.contains("first:world"));
316        assert!(rep.contains("first:hello"));
317        assert!(rep.contains("second:world"));
318        assert!(rep.contains("second:greet"));
319        assert!(rep.contains("first: 6"));
320        assert!(rep.contains("first:hello: 3"));
321        assert!(rep.contains("first:world: 1"));
322        assert!(rep.contains("second: 8"));
323        assert!(rep.contains("second:greet: 4"));
324        assert!(rep.contains("second:world: 3"));
325        assert!(rep.contains("world 4"));
326    }
327}
crude_profiler/lib.rs

crude_profiler/
lib.rs
