1  // Copyright (C) 2019-2021 Alpha-Delta Network Inc.
  2  // This file is part of the alphastd library.
  3  
  4  // The alphastd library is free software: you can redistribute it and/or modify
  5  // it under the terms of the GNU General Public License as published by
  6  // the Free Software Foundation, either version 3 of the License, or
  7  // (at your option) any later version.
  8  
  9  // The alphastd library is distributed in the hope that it will be useful,
 10  // but WITHOUT ANY WARRANTY; without even the implied warranty of
 11  // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
 12  // GNU General Public License for more details.
 13  
 14  // You should have received a copy of the GNU General Public License
 15  // along with the alphastd library. If not, see <https://www.gnu.org/licenses/>.
 16  
 17  // With credits to PhilipDaniels/logging_timer.
 18  
 19  //! This crate implements a straightforward timer to conveniently time code blocks.
 20  
 21  #[cfg(test)]
 22  mod tests;
 23  
 24  #[cfg(feature = "timer")]
 25  use core::{fmt, time::Duration};
 26  #[cfg(feature = "timer")]
 27  use std::{
 28      cell::RefCell,
 29      rc::Rc,
 30      sync::atomic::{AtomicBool, AtomicUsize, Ordering},
 31      time::Instant,
 32  };
 33  
 34  #[cfg(feature = "timer")]
 35  use colored::{ColoredString, Colorize};
 36  
 37  #[cfg(feature = "timer")]
 38  pub static NUM_INDENT: AtomicUsize = AtomicUsize::new(0);
 39  #[cfg(feature = "timer")]
 40  pub const PAD_CHAR: &str = " ";
 41  
 42  /// When this struct is dropped, it logs a message stating its name and how long
 43  /// the execution time was. Can be used to time functions or other critical areas.
 44  #[cfg(feature = "timer")]
 45  pub struct Timer<'name> {
 46      /// The instant, in UTC, that the timer was instantiated.
 47      start_time: Instant,
 48      /// The last lap time, in UTC, that the timer was called.
 49      last_lap_time: Rc<RefCell<Instant>>,
 50      /// Set by the module_path!() macro to the module where the timer is instantiated.
 51      #[allow(dead_code)]
 52      module_path: &'static str,
 53      /// Set by the file!() macro to the name of the file where the timer is instantiated.
 54      file: &'static str,
 55      /// Set by the line!() macro to the line number where the timer is instantiated.
 56      line: u32,
 57      /// The name of the timer. Used in messages to identify it.
 58      name: &'name str,
 59      /// The level of indentation for this timer context.
 60      indent: usize,
 61      /// A flag used to suppress printing of the 'Finish' message in the drop() function
 62      /// It is set by the finish method.
 63      finished: AtomicBool,
 64      /// Any extra information to be logged along with the name. Unfortunately, due
 65      /// to the lifetimes associated with a `format_args!` invocation, this currently allocates
 66      /// if you use it.
 67      extra_info: Option<String>,
 68  }
 69  
 70  #[cfg(not(feature = "timer"))]
 71  #[derive(Default)]
 72  pub struct Timer<'name> {
 73      _marker: std::marker::PhantomData<&'name ()>,
 74  }
 75  
 76  impl<'name> Timer<'name> {
 77      /// Constructs a new `Timer` that prints a 'Start' and a 'Finish' message.
 78      /// This method is not usually called directly, use the `timer!` macro instead.
 79      #[cfg(feature = "timer")]
 80      pub fn new(
 81          file: &'static str,
 82          module_path: &'static str,
 83          line: u32,
 84          name: &'name str,
 85          extra_info: Option<String>,
 86      ) -> Option<Self> {
 87          let start_time = Instant::now();
 88          let timer = Timer {
 89              start_time,
 90              last_lap_time: Rc::new(RefCell::new(start_time)),
 91              module_path,
 92              file,
 93              line,
 94              name,
 95              indent: NUM_INDENT.fetch_add(0, Ordering::Relaxed),
 96              finished: AtomicBool::new(false),
 97              extra_info,
 98          };
 99          // Print the start message.
100          timer.print(TimerState::Start, None);
101          // Increment the indentation by 1.
102          NUM_INDENT.fetch_add(1, Ordering::Relaxed);
103          Some(timer)
104      }
105  
106      #[cfg(not(feature = "timer"))]
107      pub fn noop(&self) {}
108  
109      /// Returns how long the timer has been running for.
110      #[cfg(feature = "timer")]
111      pub fn elapsed(&self, elapsed: Duration) -> String {
112          let secs = elapsed.as_secs();
113          let millis = elapsed.subsec_millis();
114          let micros = elapsed.subsec_micros() % 1000;
115          let nanos = elapsed.subsec_nanos() % 1000;
116          if secs != 0 {
117              format!("{}.{:0>3}s", secs, millis)
118          } else if millis > 0 {
119              format!("{}.{:0>3}ms", millis, micros)
120          } else if micros > 0 {
121              format!("{}.{:0>3}µs", micros, nanos)
122          } else {
123              format!("{}ns", elapsed.subsec_nanos())
124          }
125      }
126  
127      /// Returns how long the timer has been running for.
128      #[cfg(feature = "timer")]
129      pub fn elapsed_colored(&self, elapsed: Duration) -> ColoredString {
130          let secs = elapsed.as_secs();
131          let millis = elapsed.subsec_millis();
132          let micros = elapsed.subsec_micros() % 1000;
133          let nanos = elapsed.subsec_nanos() % 1000;
134          if secs != 0 {
135              format!("{}.{:0>3}s", secs, millis).magenta().bold()
136          } else if millis > 0 {
137              format!("{}.{:0>3}ms", millis, micros).yellow().bold()
138          } else if micros > 0 {
139              format!("{}.{:0>3}µs", micros, nanos).cyan().bold()
140          } else {
141              format!("{}ns", elapsed.subsec_nanos()).green().bold()
142          }
143      }
144  
145      /// Outputs a log message with a target of 'Lap' showing the current elapsed time, but does not
146      /// stop the timer. This method can be called multiple times.
147      /// The message can include further information via a `format_args!` approach.
148      /// This method is usually not called directly, it is easier to use the `lap!` macro.
149      #[cfg(feature = "timer")]
150      pub fn lap(&self, args: Option<fmt::Arguments>) {
151          self.print(TimerState::Lap, args);
152      }
153  
154      /// Outputs a log message with a target of 'Finish' and suppresses the normal message
155      /// that is output when the timer is dropped. The message can include further `format_args!`
156      /// information. This method is normally called using the `finish!` macro. Calling
157      /// `finish()` again will have no effect.
158      #[cfg(feature = "timer")]
159      pub fn finish(&self, args: Option<fmt::Arguments>) {
160          if !self.finished.load(Ordering::SeqCst) {
161              // Decrement the indentation by 1.
162              NUM_INDENT.fetch_sub(1, Ordering::Relaxed);
163              self.finished.store(true, Ordering::SeqCst);
164              self.print(TimerState::Finish, args);
165          }
166      }
167  
168      #[cfg(feature = "timer")]
169      fn print(&self, state: TimerState, args: Option<fmt::Arguments>) {
170          println!("{}", self.format(state, args));
171      }
172  
173      #[cfg(feature = "timer")]
174      fn format(&self, status: TimerState, args: Option<fmt::Arguments>) -> String {
175          // Construct the user message.
176          let user_message = match (self.extra_info.as_ref(), args) {
177              (Some(info), Some(args)) => format!("{}, {}, {}", self.name, info, args),
178              (Some(info), None) => format!("{}, {}", self.name, info),
179              (None, Some(args)) => format!("{}, {}", self.name, args),
180              (None, None) => format!("{}", self.name),
181          };
182  
183          // Construct the main message.
184          match status {
185              TimerState::Start => {
186                  // Compute the indentation.
187                  let indentation_amount = self.indent * 4;
188                  let mut indentation = String::new();
189                  for _ in 0..indentation_amount {
190                      indentation.push_str(&PAD_CHAR);
191                  }
192  
193                  let message = format!("{} ({})", Self::status(status, self.indent), user_message);
194                  // let metadata = format!(" [{} {} L{}]", self.module_path, self.file, self.line).bold();
195                  let metadata = format!(" [{} L{}]", self.file, self.line).bold();
196  
197                  format!(" {indentation}{:<30} {:.>55}", message, metadata)
198              }
199              TimerState::Lap => {
200                  // Compute the indentation.
201                  let indentation_amount = (self.indent + 1) * 4;
202                  let mut indentation = String::new();
203                  for _ in 0..indentation_amount {
204                      indentation.push_str(&PAD_CHAR);
205                  }
206  
207                  let message = format!("{} ({})", Self::status(status, self.indent + 1), user_message);
208                  let elapsed = self.elapsed_colored(self.last_lap_time.borrow().elapsed());
209  
210                  // Update the last lap time.
211                  *(*self.last_lap_time).borrow_mut() = Instant::now();
212  
213                  format!(" {indentation}{:<30} {:.>55}", message, elapsed)
214              }
215              TimerState::Finish => {
216                  // Compute the indentation.
217                  let indentation_amount = self.indent * 4;
218                  let mut indentation = String::new();
219                  for _ in 0..indentation_amount {
220                      indentation.push_str(&PAD_CHAR);
221                  }
222  
223                  let message = format!("{} ({})", Self::status(status, self.indent), user_message);
224                  let elapsed = self.elapsed(self.start_time.elapsed());
225  
226                  format!(" {indentation}{:<50} {:.>25}", message, elapsed)
227              }
228          }
229      }
230  
231      /// Returns the state of the timer, with coloring.
232      #[cfg(feature = "timer")]
233      fn status(status: TimerState, indent: usize) -> ColoredString {
234          let status = match status {
235              TimerState::Start => "Start",
236              TimerState::Lap => "Lap",
237              TimerState::Finish => "Finish",
238          };
239  
240          match indent % 5 {
241              0 => Colorize::green(status).bold(),
242              1 => Colorize::cyan(status).bold(),
243              2 => Colorize::yellow(status).bold(),
244              3 => Colorize::magenta(status).bold(),
245              4 => Colorize::red(status).bold(),
246              _ => Colorize::white(status).bold(),
247          }
248      }
249  }
250  
251  #[cfg(feature = "timer")]
252  impl<'a> Drop for Timer<'a> {
253      /// Drops the timer, outputting a log message with a target of `Finish`
254      /// if the `finish` method has not yet been called.
255      fn drop(&mut self) {
256          self.finish(None);
257      }
258  }
259  
260  #[cfg(feature = "timer")]
261  #[derive(Debug, Copy, Clone)]
262  enum TimerState {
263      Start,
264      Lap,
265      Finish,
266  }
267  
268  /// Initializes a timer that logs a start and finish message.
269  ///
270  /// # Examples
271  /// Note that when specifying the log level you must use a semi-colon as a
272  /// separator, this is to ensure disambiguous parsing of the macro arguments.
273  ///
274  /// ```
275  /// use alpha_std_timer::timer;
276  ///
277  /// let _tmr1 = timer!("FIND_FILES");
278  /// let _tmr2 = timer!("FIND_FILES", "Found {} files", 42);
279  /// ```
280  #[cfg(feature = "timer")]
281  #[macro_export]
282  macro_rules! timer {
283      ($name:expr) => {
284          {
285              $crate::Timer::new(
286                  file!(),
287                  module_path!(),
288                  line!(),
289                  $name,
290                  None,
291                  )
292          }
293      };
294  
295      ($name:expr, $format:tt) => {
296          {
297              $crate::Timer::new(
298                  file!(),
299                  module_path!(),
300                  line!(),
301                  $name,
302                  Some(format!($format)),
303                  )
304          }
305      };
306  
307      ($name:expr, $format:tt, $($arg:expr),*) => {
308          {
309              $crate::Timer::new(
310                  file!(),
311                  module_path!(),
312                  line!(),
313                  $name,
314                  Some(format!($format, $($arg), *)),
315                  )
316          }
317      };
318  }
319  
320  /// Makes an existing timer output an 'lap' message.
321  /// Can be called multiple times.
322  #[cfg(feature = "timer")]
323  #[macro_export]
324  macro_rules! lap {
325      ($timer:expr) => ({
326          if let Some(ref timer) = $timer {
327              timer.lap(None);
328          }
329      });
330  
331      ($timer:expr, $format:tt) => ({
332          if let Some(ref timer) = $timer {
333              timer.lap(Some(format_args!($format)))
334          }
335      });
336  
337      ($timer:expr, $format:tt, $($arg:expr),*) => ({
338          if let Some(ref timer) = $timer {
339              timer.lap(Some(format_args!($format, $($arg), *)))
340          }
341      })
342  }
343  
344  /// Makes an existing timer output a 'finished' message and suppresses
345  /// the normal drop message.
346  /// Only the first call has any effect, subsequent calls will be ignored.
347  #[cfg(feature = "timer")]
348  #[macro_export]
349  macro_rules! finish {
350      ($timer:expr) => ({
351          if let Some(ref timer) = $timer {
352              timer.finish(None)
353          }
354      });
355  
356      ($timer:expr, $format:tt) => ({
357          if let Some(ref timer) = $timer {
358              timer.finish(Some(format_args!($format)))
359          }
360      });
361  
362      ($timer:expr, $format:tt, $($arg:expr),*) => ({
363          if let Some(ref timer) = $timer {
364              timer.finish(Some(format_args!($format, $($arg), *)))
365          }
366      })
367  }
368  
369  #[cfg(not(feature = "timer"))]
370  #[macro_export]
371  macro_rules! timer {
372      ($name:expr) => {
373          $crate::Timer::default()
374      };
375  
376      ($name:expr, $format:tt) => {
377          $crate::Timer::default()
378      };
379  
380      ($name:expr, $format:tt, $($arg:expr),*) => {
381          $crate::Timer::default()
382      };
383  }
384  
385  #[cfg(not(feature = "timer"))]
386  #[macro_export]
387  macro_rules! lap {
388      ($timer:expr) => {
389          $timer.noop()
390      };
391  
392      ($timer:expr, $format:tt) => {
393          $timer.noop()
394      };
395  
396      ($timer:expr, $format:tt, $($arg:expr),*) => {
397          $timer.noop()
398      };
399  }
400  
401  #[cfg(not(feature = "timer"))]
402  #[macro_export]
403  macro_rules! finish {
404      ($timer:expr) => {
405          $timer.noop()
406      };
407  
408      ($timer:expr, $format:tt) => {
409          $timer.noop()
410      };
411  
412      ($timer:expr, $format:tt, $($arg:expr),*) => {
413          $timer.noop()
414      };
415  }