tracing_perf/
lib.rs

1#![doc = include_str!("../README.md")]
2//! ## Feature flags
3#![cfg_attr(
4    feature = "docsrs",
5    cfg_attr(doc, doc = ::document_features::document_features!())
6)]
7#![forbid(unsafe_code)]
8#![warn(clippy::all, clippy::pedantic, clippy::nursery, clippy::cargo)]
9
10use std::fmt;
11
12#[cfg(feature = "start-print-order")]
13use indexmap::IndexMap as HashMap;
14#[cfg(not(feature = "start-print-order"))]
15use std::collections::HashMap;
16
17#[cfg(not(feature = "minstant"))]
18use std::time::{Duration, Instant};
19#[cfg(feature = "minstant")]
20use ::{minstant::Instant, std::time::Duration};
21
22use tracing::Level;
23
24/// Enum containing possible printing orders of total times.
25#[derive(Copy, Clone, Debug, PartialEq, Eq)]
26#[non_exhaustive]
27pub enum PrintOrder {
28    /// Starting order.
29    #[cfg(feature = "start-print-order")]
30    Start,
31    /// Reverse starting order.
32    #[cfg(feature = "start-print-order")]
33    RevStart,
34    /// Key name.
35    Key,
36    /// Reverse key name.
37    RevKey,
38    /// Increasing duration.
39    IncDuration,
40    /// Decreasing duration.
41    DecDuration,
42}
43
44impl Default for PrintOrder {
45    #[cfg(feature = "start-print-order")]
46    fn default() -> Self {
47        Self::Start
48    }
49    #[cfg(not(feature = "start-print-order"))]
50    fn default() -> Self {
51        Self::DecDuration
52    }
53}
54
55/// A configurable builder for a `TimeReporter`
56#[derive(Clone, Debug, PartialEq, Eq)]
57pub struct TimeReporterBuilder {
58    name: String,
59    level: Level,
60    print_order: PrintOrder,
61    width: usize,
62    precision: usize,
63}
64
65impl TimeReporterBuilder {
66    /// Create a new `TimeReporter` builder with the given name
67    pub fn new<S: Into<String>>(name: S) -> Self {
68        Self {
69            name: name.into(),
70            level: Level::INFO,
71            print_order: PrintOrder::default(),
72            width: 11,
73            precision: 9,
74        }
75    }
76
77    #[must_use]
78    pub fn build(&self) -> TimeReporter {
79        TimeReporter {
80            times: HashMap::new(),
81            name: self.name.clone(),
82            cur_state_time: None,
83            level: self.level,
84            print_order: self.print_order,
85            width: self.width,
86            precision: self.precision,
87        }
88    }
89
90    /// Set the logging level.
91    pub fn level(&mut self, level: Level) -> &mut Self {
92        self.level = level;
93        self
94    }
95
96    /// Set the printing order of the total times.
97    pub fn print_order(&mut self, print_order: PrintOrder) -> &mut Self {
98        self.print_order = print_order;
99        self
100    }
101
102    /// Set the minimum formatting width of the total times.
103    ///
104    /// Note: Should be at least `precision + 2`  (i.e at least one leading digit + decimal point + precision)
105    /// or this option will have no effect. Alternatively precision should be at most `width - 2`.
106    ///
107    /// Fill character and alignment are hardcoded to space and left-align.
108    pub fn width(&mut self, width: usize) -> &mut Self {
109        self.width = width;
110        self
111    }
112
113    /// Set the number of digits after the decimal point
114    /// that should be printed for the total times.
115    pub fn precision(&mut self, precision: usize) -> &mut Self {
116        self.precision = precision;
117        self
118    }
119}
120
121/// Collect and report total time spent on set of activities.
122///
123/// `TimeReporter` is useful for generating and reporting
124/// time reports: how much time was spend on a given activity.
125///
126/// On `drop` or on call to `finish` it will report total times
127/// gathered as a `tracing` event.
128#[derive(Clone, Debug, PartialEq, Eq)]
129pub struct TimeReporter {
130    times: HashMap<&'static str, Duration>,
131    cur_state_time: Option<(&'static str, Instant)>,
132    name: String,
133    level: Level,
134    print_order: PrintOrder,
135    width: usize,
136    precision: usize,
137}
138
139impl TimeReporter {
140    /// Create a new `TimeReporter`.
141    pub fn new<S: Into<String>>(name: S) -> Self {
142        TimeReporterBuilder::new(name).build()
143    }
144
145    /// Create a new `TimeReporter` with a specified level.
146    pub fn new_with_level<S: Into<String>>(name: S, level: Level) -> Self {
147        TimeReporterBuilder::new(name).level(level).build()
148    }
149
150    /// Start counting time for a state named "key".
151    ///
152    /// If this `TimeReporter` was already counting time
153    /// for another state, it will end counting time for it
154    /// before starting a new one.
155    pub fn start(&mut self, key: &'static str) {
156        let now = Instant::now();
157        self.save_current(now);
158        self.cur_state_time = Some((key, now));
159    }
160
161    /// Start counting time and execute a function `f`.
162    ///
163    /// This is handy syntax for `if let` or `while let` expressions
164    /// where it would be inconvenient to add a standalone `start` call.
165    pub fn start_with<F, R>(&mut self, key: &'static str, f: F) -> R
166    where
167        F: FnOnce() -> R,
168    {
169        self.start(key);
170
171        f()
172    }
173
174    fn save_current(&mut self, now: Instant) {
175        if let Some((key, prev)) = self.cur_state_time.take() {
176            *self.times.entry(key).or_insert_with(|| Duration::new(0, 0)) += now - prev;
177        }
178    }
179
180    /// Stop counting time.
181    pub fn stop(&mut self) {
182        let now = Instant::now();
183        self.save_current(now);
184    }
185
186    /// Finish counting time and report results.
187    #[allow(clippy::unused_self)]
188    pub fn finish(self) {}
189}
190
191fn get_times(
192    times: &HashMap<&'static str, Duration>,
193    print_order: PrintOrder,
194) -> Vec<(&'static str, Duration)> {
195    cfg_if::cfg_if! {
196        if #[cfg(feature = "start-print-order")] {
197            if print_order == PrintOrder::RevStart {
198                times.iter().rev().map(|(&k, &v)| (k, v)).collect()
199            } else {
200                times.iter().map(|(&k, &v)| (k, v)).collect()
201            }
202        } else {
203            let _ = print_order;
204            times.iter().map(|(&k, &v)| (k, v)).collect()
205        }
206    }
207}
208
209impl<'a> fmt::Display for TimeReporter {
210    #[allow(clippy::cast_precision_loss)]
211    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
212        let mut stats: Vec<(&'static str, Duration)> = get_times(&self.times, self.print_order);
213        match self.print_order {
214            #[cfg(feature = "start-print-order")]
215            PrintOrder::Start | PrintOrder::RevStart => {}
216            PrintOrder::Key => stats.sort_by_key(|s| s.0),
217            PrintOrder::RevKey => stats.sort_by(|a, b| b.0.cmp(a.0)),
218            PrintOrder::IncDuration => stats.sort_by_key(|s| s.1),
219            PrintOrder::DecDuration => stats.sort_by(|a, b| b.1.cmp(&a.1)),
220        }
221
222        write!(f, "name: {}", self.name)?;
223        let precision = self.precision;
224        let width = self.width;
225        for &(state, dur) in &stats {
226            let dur = dur.as_secs() as f64 + f64::from(dur.subsec_nanos()) / 1_000_000_000_f64;
227            write!(f, ", {}: {:<width$.precision$}", state, dur)?;
228        }
229
230        Ok(())
231    }
232}
233
234macro_rules! _span {
235    ($lvl:expr, $($args:tt)*) => {{
236        match $lvl {
237            Level::ERROR => ::tracing::span!(Level::ERROR, $($args)*),
238            Level::WARN  => ::tracing::span!(Level::WARN,  $($args)*),
239            Level::INFO  => ::tracing::span!(Level::INFO,  $($args)*),
240            Level::DEBUG => ::tracing::span!(Level::DEBUG, $($args)*),
241            Level::TRACE => ::tracing::span!(Level::TRACE, $($args)*),
242        }
243    }};
244}
245
246macro_rules! _event {
247    (target: $target:expr, $lvl:expr, $($args:tt)*) => {{
248        match $lvl {
249            Level::ERROR => ::tracing::event!(target: $target, Level::ERROR, $($args)*),
250            Level::WARN  => ::tracing::event!(target: $target, Level::WARN,  $($args)*),
251            Level::INFO  => ::tracing::event!(target: $target, Level::INFO,  $($args)*),
252            Level::DEBUG => ::tracing::event!(target: $target, Level::DEBUG, $($args)*),
253            Level::TRACE => ::tracing::event!(target: $target, Level::TRACE, $($args)*),
254        }
255    }};
256}
257
258impl Drop for TimeReporter {
259    fn drop(&mut self) {
260        let _span = _span!(self.level, "time-report").entered();
261        _event!(target: "tracing-perf", self.level, "{}", self);
262    }
263}
tracing_perf/lib.rs

tracing_perf/
lib.rs
