1  use std::borrow::Cow;
  2  use std::time;
  3  
  4  use fedimint_logging::LOG_TIMING;
  5  use tracing::{debug, info, trace, warn, Level};
  6  
  7  /// Data inside `TimeReporter`, in another struct to be able to move it out of
  8  /// without violating `drop` consistency
  9  struct TimeReporterInner {
 10      name: Cow<'static, str>,
 11      level: Level,
 12      start: time::SystemTime,
 13      threshold: Option<time::Duration>,
 14  }
 15  
 16  impl TimeReporterInner {
 17      fn report(&mut self) {
 18          let duration = crate::time::now()
 19              .duration_since(self.start)
 20              .map_err(|error| {
 21                  warn!(
 22                      target: LOG_TIMING,
 23                      %error,
 24                      "Timer reporter duration overflow. This should not happen."
 25                  );
 26                  error
 27              })
 28              .unwrap_or_default();
 29  
 30          // even `event!` doesn't support non-constant values, so we have to do a match
 31          // here
 32          let duration_ms = duration.as_millis();
 33          match self.level {
 34              Level::TRACE => {
 35                  trace!(
 36                      target: LOG_TIMING,
 37                      name = %self.name,
 38                      duration_ms,
 39                      "Operation timing"
 40                  );
 41              }
 42              Level::DEBUG => {
 43                  debug!(
 44                      target: LOG_TIMING,
 45                      name = %self.name,
 46                      duration_ms,
 47                      "Operation timing"
 48                  );
 49              }
 50              Level::INFO => {
 51                  info!(
 52                      target: LOG_TIMING,
 53                      name = %self.name,
 54                      duration_ms,
 55                      "Operation timing"
 56                  );
 57              }
 58              // anything else is just a warn, whatever; it's long enough
 59              _ => {
 60                  warn!(
 61                      target: LOG_TIMING,
 62                      name = %self.name,
 63                      duration_ms,
 64                      "Operation timing"
 65                  );
 66              }
 67          }
 68          if let Some(threshold) = self.threshold {
 69              if duration < threshold {
 70                  warn!(
 71                      target: LOG_TIMING,
 72                      name = %self.name,
 73                      duration_ms = duration.as_millis(),
 74                      threshold_ms = threshold.as_millis(),
 75                      "Operation time exceeded threshold"
 76                  );
 77              }
 78          }
 79      }
 80  }
 81  
 82  pub struct TimeReporter {
 83      /// Inner data
 84      ///
 85      /// If `None`, time reported has been moved out from and is now a no-op
 86      inner: Option<TimeReporterInner>,
 87  }
 88  
 89  impl TimeReporter {
 90      pub fn new(name: impl Into<Cow<'static, str>>) -> Self {
 91          Self {
 92              inner: Some(TimeReporterInner {
 93                  name: name.into(),
 94                  level: Level::DEBUG,
 95                  start: crate::time::now(),
 96                  threshold: None,
 97              }),
 98          }
 99      }
100  
101      pub fn level(mut self, level: tracing::Level) -> Self {
102          Self {
103              inner: self
104                  .inner
105                  .take()
106                  .map(|inner| TimeReporterInner { level, ..inner }),
107          }
108      }
109  
110      /// Add a threshold, which will log a warning if exceeded
111      pub fn threshold(mut self, threshold: time::Duration) -> Self {
112          Self {
113              inner: self.inner.take().map(|inner| TimeReporterInner {
114                  threshold: Some(threshold),
115                  ..inner
116              }),
117          }
118      }
119  
120      /// Handy alias for [`Self::threshold`]
121      pub fn threshold_millis(self, millis: u64) -> Self {
122          self.threshold(time::Duration::from_millis(millis))
123      }
124  
125      pub fn info(self) -> Self {
126          self.level(Level::INFO)
127      }
128  
129      pub fn cancel(&mut self) {
130          self.inner.take();
131      }
132  
133      pub fn finish(self) {
134          /* drop */
135      }
136  }
137  
138  impl Drop for TimeReporter {
139      fn drop(&mut self) {
140          if let Some(mut inner) = self.inner.take() {
141              inner.report()
142          }
143      }
144  }