/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 | 1.55k | : m_prefix(std::move(prefix)), |
34 | 1.55k | m_title(std::move(end_msg)), |
35 | 1.55k | m_log_category(log_category), |
36 | 1.55k | m_message_on_completion(msg_on_completion) |
37 | 1.55k | { |
38 | 1.55k | 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 | 1.55k | #define strprintf tfm::format |
|
39 | 1.55k | m_start_t = std::chrono::steady_clock::now(); |
40 | 1.55k | } 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 | 1.55k | : m_prefix(std::move(prefix)), | 34 | 1.55k | m_title(std::move(end_msg)), | 35 | 1.55k | m_log_category(log_category), | 36 | 1.55k | m_message_on_completion(msg_on_completion) | 37 | 1.55k | { | 38 | 1.55k | this->Log(strprintf("%s started", m_title)); Line | Count | Source | 1172 | 1.55k | #define strprintf tfm::format |
| 39 | 1.55k | m_start_t = std::chrono::steady_clock::now(); | 40 | 1.55k | } |
|
41 | | |
42 | | ~Timer() |
43 | 1.55k | { |
44 | 1.55k | if (m_message_on_completion) { |
45 | 1.55k | 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 | 1.55k | #define strprintf tfm::format |
|
46 | 1.55k | } else { |
47 | 0 | this->Log("completed"); |
48 | 0 | } |
49 | 1.55k | } Unexecuted instantiation: _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1EEEEEED2Ev _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1000EEEEEED2Ev Line | Count | Source | 43 | 1.55k | { | 44 | 1.55k | if (m_message_on_completion) { | 45 | 1.55k | this->Log(strprintf("%s completed", m_title)); Line | Count | Source | 1172 | 1.55k | #define strprintf tfm::format |
| 46 | 1.55k | } else { | 47 | 0 | this->Log("completed"); | 48 | 0 | } | 49 | 1.55k | } |
|
50 | | |
51 | | void Log(const std::string& msg) |
52 | 3.10k | { |
53 | 3.10k | const std::string full_msg = this->LogMsg(msg); |
54 | | |
55 | 3.10k | if (m_log_category == BCLog::LogFlags::ALL) { |
56 | 0 | LogPrintf("%s\n", full_msg); Line | Count | Source | 266 | 0 | #define LogPrintf(...) LogInfo(__VA_ARGS__) Line | Count | Source | 261 | 0 | #define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, __VA_ARGS__) Line | Count | Source | 255 | 0 | #define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) |
|
|
| LogPrintf("%s\n", full_msg); Line | Count | Source | 266 | 0 | #define LogPrintf(...) LogInfo(__VA_ARGS__) Line | Count | Source | 261 | 0 | #define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, __VA_ARGS__) Line | Count | Source | 255 | 0 | #define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) |
|
|
|
57 | 3.10k | } else { |
58 | 3.10k | LogDebug(m_log_category, "%s\n", full_msg); Line | Count | Source | 280 | 0 | #define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) Line | Count | Source | 273 | 0 | do { \ | 274 | 0 | if (LogAcceptCategory((category), (level))) { \ | 275 | 0 | LogPrintLevel_(category, level, __VA_ARGS__); \ Line | Count | Source | 255 | 0 | #define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) |
| 276 | 0 | } \ | 277 | 0 | } while (0) |
|
| LogDebug(m_log_category, "%s\n", full_msg); Line | Count | Source | 280 | 3.10k | #define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) Line | Count | Source | 273 | 3.10k | do { \ | 274 | 3.10k | if (LogAcceptCategory((category), (level))) { \ | 275 | 0 | LogPrintLevel_(category, level, __VA_ARGS__); \ Line | Count | Source | 255 | 0 | #define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) |
| 276 | 0 | } \ | 277 | 3.10k | } while (0) |
|
|
59 | 3.10k | } |
60 | 3.10k | } Unexecuted instantiation: _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1EEEEEE3LogERKNS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEE _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1000EEEEEE3LogERKNS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEE Line | Count | Source | 52 | 3.10k | { | 53 | 3.10k | const std::string full_msg = this->LogMsg(msg); | 54 | | | 55 | 3.10k | if (m_log_category == BCLog::LogFlags::ALL) { | 56 | 0 | LogPrintf("%s\n", full_msg); Line | Count | Source | 266 | 0 | #define LogPrintf(...) LogInfo(__VA_ARGS__) Line | Count | Source | 261 | 0 | #define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, __VA_ARGS__) Line | Count | Source | 255 | 0 | #define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) |
|
|
| 57 | 3.10k | } else { | 58 | 3.10k | LogDebug(m_log_category, "%s\n", full_msg); Line | Count | Source | 280 | 3.10k | #define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) Line | Count | Source | 273 | 3.10k | do { \ | 274 | 3.10k | if (LogAcceptCategory((category), (level))) { \ | 275 | 0 | LogPrintLevel_(category, level, __VA_ARGS__); \ Line | Count | Source | 255 | 0 | #define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) |
| 276 | 0 | } \ | 277 | 3.10k | } while (0) |
|
| 59 | 3.10k | } | 60 | 3.10k | } |
|
61 | | |
62 | | std::string LogMsg(const std::string& msg) |
63 | 3.10k | { |
64 | 3.10k | const auto end_time{std::chrono::steady_clock::now()}; |
65 | 3.10k | if (!m_start_t) { |
66 | 1.55k | 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 | 1.55k | #define strprintf tfm::format |
|
67 | 1.55k | } |
68 | 1.55k | 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 | 1.55k | } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) { |
73 | 1.55k | return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration)); Line | Count | Source | 1172 | 1.55k | #define strprintf tfm::format |
|
74 | 1.55k | } 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 | 1.55k | } Unexecuted instantiation: _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1EEEEEE6LogMsgERKNS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEE _ZN5BCLog5TimerINSt3__16chrono8durationIxNS1_5ratioILl1ELl1000EEEEEE6LogMsgERKNS1_12basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEE Line | Count | Source | 63 | 3.10k | { | 64 | 3.10k | const auto end_time{std::chrono::steady_clock::now()}; | 65 | 3.10k | if (!m_start_t) { | 66 | 1.55k | return strprintf("%s: %s", m_prefix, msg); Line | Count | Source | 1172 | 1.55k | #define strprintf tfm::format |
| 67 | 1.55k | } | 68 | 1.55k | 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 | 1.55k | } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) { | 73 | 1.55k | return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration)); Line | Count | Source | 1172 | 1.55k | #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 | 1.55k | } |
|
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 | 1.55k | 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 |