/Users/eugenesiegel/btc/bitcoin/src/logging/timer.h
| Line | Count | Source (jump to first uncovered line) | 
| 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 |  |     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 | 13.7k |         : m_prefix(std::move(prefix)), | 
| 34 | 13.7k |           m_title(std::move(end_msg)), | 
| 35 | 13.7k |           m_log_category(log_category), | 
| 36 | 13.7k |           m_message_on_completion(msg_on_completion) | 
| 37 | 13.7k |     { | 
| 38 | 13.7k |         this->Log(strprintf("%s started", m_title));| Line | Count | Source |  | 1172 | 0 | #define strprintf tfm::format | 
 |         this->Log(strprintf("%s started", m_title));| Line | Count | Source |  | 1172 | 13.7k | #define strprintf tfm::format | 
 | 
| 39 | 13.7k |         m_start_t = std::chrono::steady_clock::now(); | 
| 40 | 13.7k |     } Unexecuted instantiation: _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1EEEEEEC2ENS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEESD_NS_8LogFlagsEb_ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1000EEEEEEC2ENS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEESD_NS_8LogFlagsEb| Line | Count | Source |  | 33 | 13.7k |         : m_prefix(std::move(prefix)), |  | 34 | 13.7k |           m_title(std::move(end_msg)), |  | 35 | 13.7k |           m_log_category(log_category), |  | 36 | 13.7k |           m_message_on_completion(msg_on_completion) |  | 37 | 13.7k |     { |  | 38 | 13.7k |         this->Log(strprintf("%s started", m_title));| Line | Count | Source |  | 1172 | 13.7k | #define strprintf tfm::format | 
 |  | 39 | 13.7k |         m_start_t = std::chrono::steady_clock::now(); |  | 40 | 13.7k |     } | 
 | 
| 41 |  |  | 
| 42 |  |     ~Timer() | 
| 43 | 13.7k |     { | 
| 44 | 13.7k |         if (m_message_on_completion) { | 
| 45 | 13.7k |             this->Log(strprintf("%s completed", m_title));| Line | Count | Source |  | 1172 | 0 | #define strprintf tfm::format | 
 |             this->Log(strprintf("%s completed", m_title));| Line | Count | Source |  | 1172 | 13.7k | #define strprintf tfm::format | 
 | 
| 46 | 13.7k |         } else { | 
| 47 | 0 |             this->Log("completed"); | 
| 48 | 0 |         } | 
| 49 | 13.7k |     } Unexecuted instantiation: _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1EEEEEED2Ev_ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1000EEEEEED2Ev| Line | Count | Source |  | 43 | 13.7k |     { |  | 44 | 13.7k |         if (m_message_on_completion) { |  | 45 | 13.7k |             this->Log(strprintf("%s completed", m_title));| Line | Count | Source |  | 1172 | 13.7k | #define strprintf tfm::format | 
 |  | 46 | 13.7k |         } else { |  | 47 | 0 |             this->Log("completed"); |  | 48 | 0 |         } |  | 49 | 13.7k |     } | 
 | 
| 50 |  |  | 
| 51 |  |     void Log(const std::string& msg) | 
| 52 | 27.5k |     { | 
| 53 | 27.5k |         const std::string full_msg = this->LogMsg(msg); | 
| 54 |  |  | 
| 55 | 27.5k |         if (m_log_category == BCLog::LogFlags::ALL) { | 
| 56 | 0 |             LogPrintf("%s\n", full_msg);| Line | Count | Source |  | 361 | 0 | #define LogPrintf(...) LogInfo(__VA_ARGS__) | Line | Count | Source |  | 356 | 0 | #define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/true, __VA_ARGS__) | Line | Count | Source |  | 350 | 0 | #define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) | 
 | 
 | 
 |             LogPrintf("%s\n", full_msg);| Line | Count | Source |  | 361 | 0 | #define LogPrintf(...) LogInfo(__VA_ARGS__) | Line | Count | Source |  | 356 | 0 | #define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/true, __VA_ARGS__) | Line | Count | Source |  | 350 | 0 | #define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) | 
 | 
 | 
 | 
| 57 | 27.5k |         } else { | 
| 58 | 27.5k |             LogDebug(m_log_category, "%s\n", full_msg); | Line | Count | Source |  | 381 | 0 | #define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) | Line | Count | Source |  | 373 | 0 |     do {                                                              \ |  | 374 | 0 |         if (LogAcceptCategory((category), (level))) {                 \ |  | 375 | 0 |             bool rate_limit{level >= BCLog::Level::Info};             \ |  | 376 | 0 |             LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \ | Line | Count | Source |  | 350 | 0 | #define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) | 
 |  | 377 | 0 |         }                                                             \ |  | 378 | 0 |     } while (0) | 
 | 
 |             LogDebug(m_log_category, "%s\n", full_msg); | Line | Count | Source |  | 381 | 27.5k | #define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) | Line | Count | Source |  | 373 | 27.5k |     do {                                                              \ |  | 374 | 27.5k |         if (LogAcceptCategory((category), (level))) {                 \ |  | 375 | 0 |             bool rate_limit{level >= BCLog::Level::Info};             \ |  | 376 | 0 |             LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \ | Line | Count | Source |  | 350 | 0 | #define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) | 
 |  | 377 | 0 |         }                                                             \ |  | 378 | 27.5k |     } while (0) | 
 | 
 | 
| 59 | 27.5k |         } | 
| 60 | 27.5k |     } Unexecuted instantiation: _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1EEEEEE3LogERKNS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEE_ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1000EEEEEE3LogERKNS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEE| Line | Count | Source |  | 52 | 27.5k |     { |  | 53 | 27.5k |         const std::string full_msg = this->LogMsg(msg); |  | 54 |  |  |  | 55 | 27.5k |         if (m_log_category == BCLog::LogFlags::ALL) { |  | 56 | 0 |             LogPrintf("%s\n", full_msg);| Line | Count | Source |  | 361 | 0 | #define LogPrintf(...) LogInfo(__VA_ARGS__) | Line | Count | Source |  | 356 | 0 | #define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/true, __VA_ARGS__) | Line | Count | Source |  | 350 | 0 | #define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) | 
 | 
 | 
 |  | 57 | 27.5k |         } else { |  | 58 | 27.5k |             LogDebug(m_log_category, "%s\n", full_msg); | Line | Count | Source |  | 381 | 27.5k | #define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) | Line | Count | Source |  | 373 | 27.5k |     do {                                                              \ |  | 374 | 27.5k |         if (LogAcceptCategory((category), (level))) {                 \ |  | 375 | 0 |             bool rate_limit{level >= BCLog::Level::Info};             \ |  | 376 | 0 |             LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \ | Line | Count | Source |  | 350 | 0 | #define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) | 
 |  | 377 | 0 |         }                                                             \ |  | 378 | 27.5k |     } while (0) | 
 | 
 |  | 59 | 27.5k |         } |  | 60 | 27.5k |     } | 
 | 
| 61 |  |  | 
| 62 |  |     std::string LogMsg(const std::string& msg) | 
| 63 | 27.5k |     { | 
| 64 | 27.5k |         const auto end_time{std::chrono::steady_clock::now()}; | 
| 65 | 27.5k |         if (!m_start_t) { | 
| 66 | 13.7k |             return strprintf("%s: %s", m_prefix, msg);| Line | Count | Source |  | 1172 | 0 | #define strprintf tfm::format | 
 |             return strprintf("%s: %s", m_prefix, msg);| Line | Count | Source |  | 1172 | 13.7k | #define strprintf tfm::format | 
 | 
| 67 | 13.7k |         } | 
| 68 | 13.7k |         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 | 13.7k |         } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) { | 
| 73 | 13.7k |             return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));| Line | Count | Source |  | 1172 | 13.7k | #define strprintf tfm::format | 
 | 
| 74 | 13.7k |         } else if constexpr (std::is_same_v<TimeType, std::chrono::seconds>) { | 
| 75 | 0 |             return strprintf("%s: %s (%.2fs)", m_prefix, msg, Ticks<SecondsDouble>(duration));| Line | Count | Source |  | 1172 | 0 | #define strprintf tfm::format | 
 | 
| 76 |  |         } else { | 
| 77 |  |             static_assert(ALWAYS_FALSE<TimeType>, "Error: unexpected time type"); | 
| 78 |  |         } | 
| 79 | 13.7k |     } Unexecuted instantiation: _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1EEEEEE6LogMsgERKNS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEE_ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1000EEEEEE6LogMsgERKNS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEE| Line | Count | Source |  | 63 | 27.5k |     { |  | 64 | 27.5k |         const auto end_time{std::chrono::steady_clock::now()}; |  | 65 | 27.5k |         if (!m_start_t) { |  | 66 | 13.7k |             return strprintf("%s: %s", m_prefix, msg);| Line | Count | Source |  | 1172 | 13.7k | #define strprintf tfm::format | 
 |  | 67 | 13.7k |         } |  | 68 | 13.7k |         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 | 13.7k |         } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) { |  | 73 | 13.7k |             return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));| Line | Count | Source |  | 1172 | 13.7k | #define strprintf tfm::format | 
 |  | 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 | 13.7k |     } | 
 | 
| 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 | 13.7k |     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 | 0 |     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 | 0 |     BCLog::Timer<std::chrono::seconds> UNIQUE_NAME(logging_timer)(__func__, end_msg) | 
| 109 |  |  | 
| 110 |  |  | 
| 111 |  | #endif // BITCOIN_LOGGING_TIMER_H |