timer.h raw

   1  // Copyright (c) 2009-2010 Satoshi Nakamoto
   2  // Copyright (c) 2009-present The Bitcoin Core developers
   3  // Distributed under the MIT software license, see the accompanying
   4  // file COPYING or http://www.opensource.org/licenses/mit-license.php.
   5  
   6  #ifndef BITCOIN_LOGGING_TIMER_H
   7  #define BITCOIN_LOGGING_TIMER_H
   8  
   9  #include <util/log.h>
  10  #include <util/macros.h>
  11  #include <util/time.h>
  12  #include <util/types.h>
  13  
  14  #include <chrono>
  15  #include <optional>
  16  #include <string>
  17  
  18  
  19  namespace BCLog {
  20  
  21  //! RAII-style object that outputs timing information to logs.
  22  template <typename TimeType>
  23  class Timer
  24  {
  25  public:
  26      //! If log_category is left as the default, end_msg will log unconditionally
  27      //! (instead of being filtered by category).
  28      Timer(
  29          std::string prefix,
  30          std::string end_msg,
  31          BCLog::LogFlags log_category = BCLog::LogFlags::ALL,
  32          bool msg_on_completion = true)
  33          : m_prefix(std::move(prefix)),
  34            m_title(std::move(end_msg)),
  35            m_log_category(log_category),
  36            m_message_on_completion(msg_on_completion)
  37      {
  38          this->Log(strprintf("%s started", m_title));
  39          m_start_t = std::chrono::steady_clock::now();
  40      }
  41  
  42      ~Timer()
  43      {
  44          if (m_message_on_completion) {
  45              this->Log(strprintf("%s completed", m_title));
  46          } else {
  47              this->Log("completed");
  48          }
  49      }
  50  
  51      void Log(const std::string& msg)
  52      {
  53          const std::string full_msg = this->LogMsg(msg);
  54  
  55          if (m_log_category == BCLog::LogFlags::ALL) {
  56              LogInfo("%s\n", full_msg);
  57          } else {
  58              LogDebug(m_log_category, "%s\n", full_msg);
  59          }
  60      }
  61  
  62      std::string LogMsg(const std::string& msg)
  63      {
  64          const auto end_time{std::chrono::steady_clock::now()};
  65          if (!m_start_t) {
  66              return strprintf("%s: %s", m_prefix, msg);
  67          }
  68          const auto duration{end_time - *m_start_t};
  69  
  70          if constexpr (std::is_same_v<TimeType, std::chrono::microseconds>) {
  71              return strprintf("%s: %s (%iμs)", m_prefix, msg, Ticks<std::chrono::microseconds>(duration));
  72          } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) {
  73              return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));
  74          } else if constexpr (std::is_same_v<TimeType, std::chrono::seconds>) {
  75              return strprintf("%s: %s (%.2fs)", m_prefix, msg, Ticks<SecondsDouble>(duration));
  76          } else {
  77              static_assert(ALWAYS_FALSE<TimeType>, "Error: unexpected time type");
  78          }
  79      }
  80  
  81  private:
  82      std::optional<std::chrono::steady_clock::time_point> m_start_t{};
  83  
  84      //! Log prefix; usually the name of the function this was created in.
  85      const std::string m_prefix;
  86  
  87      //! A descriptive message of what is being timed.
  88      const std::string m_title;
  89  
  90      //! Forwarded on to LogDebug if specified - has the effect of only
  91      //! outputting the timing log when a particular debug= category is specified.
  92      const BCLog::LogFlags m_log_category;
  93  
  94      //! Whether to output the message again on completion.
  95      const bool m_message_on_completion;
  96  };
  97  
  98  } // namespace BCLog
  99  
 100  
 101  #define LOG_TIME_MICROS_WITH_CATEGORY(end_msg, log_category) \
 102      BCLog::Timer<std::chrono::microseconds> BITCOIN_UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category)
 103  #define LOG_TIME_MILLIS_WITH_CATEGORY(end_msg, log_category) \
 104      BCLog::Timer<std::chrono::milliseconds> BITCOIN_UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category)
 105  #define LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE(end_msg, log_category) \
 106      BCLog::Timer<std::chrono::milliseconds> BITCOIN_UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category, /* msg_on_completion=*/false)
 107  #define LOG_TIME_SECONDS(end_msg) \
 108      BCLog::Timer<std::chrono::seconds> BITCOIN_UNIQUE_NAME(logging_timer)(__func__, end_msg)
 109  
 110  
 111  #endif // BITCOIN_LOGGING_TIMER_H
 112