Line data    Source code

       1             : // Copyright (c) 2009-2010 Satoshi Nakamoto
       2             : // Copyright (c) 2009-2022 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 <logging.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           0 :     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           0 :         : m_prefix(std::move(prefix)),
      34           0 :           m_title(std::move(end_msg)),
      35           0 :           m_log_category(log_category),
      36           0 :           m_message_on_completion(msg_on_completion)
      37             :     {
      38           0 :         this->Log(strprintf("%s started", m_title));
      39           0 :         m_start_t = std::chrono::steady_clock::now();
      40           0 :     }
      41             : 
      42           0 :     ~Timer()
      43             :     {
      44           0 :         if (m_message_on_completion) {
      45           0 :             this->Log(strprintf("%s completed", m_title));
      46           0 :         } else {
      47           0 :             this->Log("completed");
      48             :         }
      49           0 :     }
      50             : 
      51           0 :     void Log(const std::string& msg)
      52             :     {
      53           0 :         const std::string full_msg = this->LogMsg(msg);
      54             : 
      55           0 :         if (m_log_category == BCLog::LogFlags::ALL) {
      56           0 :             LogPrintf("%s\n", full_msg);
      57           0 :         } else {
      58           0 :             LogPrint(m_log_category, "%s\n", full_msg);
      59             :         }
      60           0 :     }
      61             : 
      62           0 :     std::string LogMsg(const std::string& msg)
      63             :     {
      64           0 :         const auto end_time{std::chrono::steady_clock::now()};
      65           0 :         if (!m_start_t) {
      66           0 :             return strprintf("%s: %s", m_prefix, msg);
      67             :         }
      68           0 :         const auto duration{end_time - *m_start_t};
      69             : 
      70             :         if constexpr (std::is_same<TimeType, std::chrono::microseconds>::value) {
      71             :             return strprintf("%s: %s (%iμs)", m_prefix, msg, Ticks<std::chrono::microseconds>(duration));
      72             :         } else if constexpr (std::is_same<TimeType, std::chrono::milliseconds>::value) {
      73           0 :             return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));
      74             :         } else if constexpr (std::is_same<TimeType, std::chrono::seconds>::value) {
      75           0 :             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           0 :     }
      80             : 
      81             : private:
      82           0 :     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 LogPrint 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> 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> 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> 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> UNIQUE_NAME(logging_timer)(__func__, end_msg)
     109             : 
     110             : 
     111             : #endif // BITCOIN_LOGGING_TIMER_H