Branch data     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                 :       10476 :     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                 :       10476 :         : m_prefix(std::move(prefix)),
      34                 :       10476 :           m_title(std::move(end_msg)),
      35                 :       10476 :           m_log_category(log_category),
      36                 :       10476 :           m_message_on_completion(msg_on_completion)
      37                 :             :     {
      38   [ +  -  +  - ]:       10476 :         this->Log(strprintf("%s started", m_title));
      39         [ -  + ]:       10476 :         m_start_t = std::chrono::steady_clock::now();
      40                 :       10476 :     }
      41                 :             : 
      42                 :       10476 :     ~Timer()
      43                 :             :     {
      44         [ +  + ]:       10476 :         if (m_message_on_completion) {
      45                 :        9640 :             this->Log(strprintf("%s completed", m_title));
      46                 :             :         } else {
      47                 :         836 :             this->Log("completed");
      48                 :             :         }
      49                 :       10476 :     }
      50                 :             : 
      51                 :       20952 :     void Log(const std::string& msg)
      52                 :             :     {
      53                 :       20952 :         const std::string full_msg = this->LogMsg(msg);
      54                 :             : 
      55         [ +  + ]:       20952 :         if (m_log_category == BCLog::LogFlags::ALL) {
      56         [ +  - ]:         172 :             LogPrintf("%s\n", full_msg);
      57                 :             :         } else {
      58   [ +  -  +  -  :       20952 :             LogDebug(m_log_category, "%s\n", full_msg);
                   +  - ]
      59                 :             :         }
      60                 :       20952 :     }
      61                 :             : 
      62                 :       20953 :     std::string LogMsg(const std::string& msg)
      63                 :             :     {
      64                 :       20953 :         const auto end_time{std::chrono::steady_clock::now()};
      65         [ +  + ]:       20953 :         if (!m_start_t) {
      66                 :       10476 :             return strprintf("%s: %s", m_prefix, msg);
      67                 :             :         }
      68                 :       10477 :         const auto duration{end_time - *m_start_t};
      69                 :             : 
      70                 :             :         if constexpr (std::is_same<TimeType, std::chrono::microseconds>::value) {
      71                 :           2 :             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                 :       10410 :             return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));
      74                 :             :         } else if constexpr (std::is_same<TimeType, std::chrono::seconds>::value) {
      75                 :          65 :             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> 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