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