slog_perf/
lib.rs

1//! This crate provides very useful tools for reporting performance metrics
2//! through `slog`.
3#[macro_use]
4extern crate slog;
5
6use slog::Logger;
7use std::time;
8use std::collections::HashMap;
9
10/// Collect and report total time spent on set of activities
11///
12/// `TimeReporter` is useful for generating and reporting
13/// time reports: how much time was spend on a given activity.
14///
15/// On `drop` or on call to `finish` it will report total times
16/// gathered to `slog::Logger`.
17pub struct TimeReporter {
18    times: HashMap<&'static str, time::Duration>,
19    cur_state_time: Option<(&'static str, time::Instant)>,
20    log: Logger,
21    level: slog::Level,
22}
23
24impl TimeReporter {
25    /// Create new `TimeReporter`
26    pub fn new<S : Into<String>>(name: S, log: Logger) -> TimeReporter {
27        let name = name.into();
28
29        let log = log.new(o!("name" => name));
30
31        TimeReporter {
32            times: HashMap::new(),
33            log: log,
34            cur_state_time: None,
35            level: slog::Level::Info,
36        }
37    }
38
39    /// Create new `TimeReporter`
40    pub fn new_with_level<S : Into<String>>(name: S, log: Logger, level: slog::Level) -> TimeReporter {
41        let name = name.into();
42
43        let log = log.new(o!("name" => name));
44
45        TimeReporter {
46            times: HashMap::new(),
47            log: log,
48            cur_state_time: None,
49            level: level,
50        }
51    }
52    /// Start counting time for a state named "key"
53    ///
54    /// If this the `TimeReporter` was already counting time
55    /// for another state, it will end counting time for it
56    /// before starting new one.
57    pub fn start(&mut self, key: &'static str) {
58
59        let now = time::Instant::now();
60
61        self.save_current(now);
62        trace!(self.log, "start"; "phase" => key);
63
64        self.cur_state_time = Some((key, now))
65    }
66
67    /// Start counting time and execute a function `f`
68    ///
69    /// This is handy syntax for `if let` or `while let` expressions
70    /// where it would be inconvenient to add standalone `start` call.
71    pub fn start_with<F, R>(&mut self, key :&'static str, f: F) -> R
72        where F: FnOnce() -> R
73    {
74        self.start(key);
75
76        f()
77    }
78
79    fn save_current(&mut self, now: time::Instant) {
80        if let Some((key, prev)) = self.cur_state_time.take() {
81
82            *self.times
83                 .entry(key)
84                 .or_insert(time::Duration::new(0, 0)) += now - prev;
85            trace!(self.log, "end"; "phase" => key);
86        }
87    }
88
89    pub fn stop(&mut self) {
90        let now = time::Instant::now();
91        self.save_current(now);
92    }
93
94    /// Finish counting time and report results
95    pub fn finish(self) {}
96}
97
98// Private struct implementing `slog::KV`
99struct TimeReporterDroper<'a> {
100    reporter: &'a TimeReporter,
101}
102
103impl<'a> slog::KV for TimeReporterDroper<'a> {
104    fn serialize(&self,
105                 _record: &slog::Record,
106                 ser: &mut slog::Serializer)
107                 -> slog::Result {
108
109        let mut stats: Vec<(&'static str, time::Duration)> = self.reporter
110            .times
111            .iter()
112            .map(|(&k, &v)| (k, v))
113            .collect();
114
115        // TODO: or by duration?
116        stats.sort_by_key(|s| s.1);
117
118        for &(state, dur) in stats.iter().rev() {
119            ser.emit_arguments(
120                state,
121                &format_args!("{}",
122                            dur.as_secs() as f64
123                            + dur.subsec_nanos() as f64 / 1000000000f64)
124                )?;
125        }
126
127        Ok(())
128    }
129}
130impl Drop for TimeReporter {
131    fn drop(&mut self) {
132        self.stop();
133
134        debug_assert!(self.cur_state_time.is_none());
135
136        let lrd = TimeReporterDroper { reporter: &self };
137
138        static LOC : slog::RecordLocation = slog::RecordLocation {
139            file: file!(),
140            line: line!(),
141            column: column!(),
142            function: "",
143            module: module_path!(),
144        };
145        let record_static = slog::RecordStatic {
146            location : &LOC,
147            level: self.level,
148            tag: "slog_perf",
149        };
150        let args = format_args!("time report");
151
152        self.log.log(&slog::Record::new(
153            &record_static,
154            &args,
155            slog_b!(lrd),
156        ));
157    }
158}
slog_perf/lib.rs

slog_perf/
lib.rs
