Skip to content

Commit 41edaf2

Browse files
committed
logs: add BCLog::Timer and related macros
Makes logging timing information about a block of code easier.
1 parent 0d86f4d commit 41edaf2

File tree

4 files changed

+142
-0
lines changed

4 files changed

+142
-0
lines changed

src/Makefile.am

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -146,6 +146,7 @@ BITCOIN_CORE_H = \
146146
dbwrapper.h \
147147
limitedmap.h \
148148
logging.h \
149+
logging/timer.h \
149150
memusage.h \
150151
merkleblock.h \
151152
miner.h \

src/Makefile.test.include

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -110,6 +110,7 @@ BITCOIN_TESTS =\
110110
test/key_io_tests.cpp \
111111
test/key_tests.cpp \
112112
test/limitedmap_tests.cpp \
113+
test/logging_tests.cpp \
113114
test/dbwrapper_tests.cpp \
114115
test/validation_tests.cpp \
115116
test/mempool_tests.cpp \

src/logging/timer.h

Lines changed: 104 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,104 @@
1+
// Copyright (c) 2009-2010 Satoshi Nakamoto
2+
// Copyright (c) 2009-2018 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+
13+
#include <chrono>
14+
#include <string>
15+
16+
17+
namespace BCLog {
18+
19+
//! RAII-style object that outputs timing information to logs.
20+
template <typename TimeType>
21+
class Timer
22+
{
23+
public:
24+
//! If log_category is left as the default, end_msg will log unconditionally
25+
//! (instead of being filtered by category).
26+
Timer(
27+
std::string prefix,
28+
std::string end_msg,
29+
BCLog::LogFlags log_category = BCLog::LogFlags::ALL) :
30+
m_prefix(std::move(prefix)),
31+
m_title(std::move(end_msg)),
32+
m_log_category(log_category)
33+
{
34+
this->Log(strprintf("%s started", m_title));
35+
m_start_t = GetTime<std::chrono::microseconds>();
36+
}
37+
38+
~Timer()
39+
{
40+
this->Log(strprintf("%s completed", m_title));
41+
}
42+
43+
void Log(const std::string& msg)
44+
{
45+
const std::string full_msg = this->LogMsg(msg);
46+
47+
if (m_log_category == BCLog::LogFlags::ALL) {
48+
LogPrintf("%s\n", full_msg);
49+
} else {
50+
LogPrint(m_log_category, "%s\n", full_msg);
51+
}
52+
}
53+
54+
std::string LogMsg(const std::string& msg)
55+
{
56+
const auto end_time = GetTime<std::chrono::microseconds>() - m_start_t;
57+
if (m_start_t.count() <= 0) {
58+
return strprintf("%s: %s", m_prefix, msg);
59+
}
60+
61+
std::string units = "";
62+
float divisor = 1;
63+
64+
if (std::is_same<TimeType, std::chrono::microseconds>::value) {
65+
units = "μs";
66+
} else if (std::is_same<TimeType, std::chrono::milliseconds>::value) {
67+
units = "ms";
68+
divisor = 1000.;
69+
} else if (std::is_same<TimeType, std::chrono::seconds>::value) {
70+
units = "s";
71+
divisor = 1000. * 1000.;
72+
}
73+
74+
const float time_ms = end_time.count() / divisor;
75+
return strprintf("%s: %s (%.2f%s)", m_prefix, msg, time_ms, units);
76+
}
77+
78+
private:
79+
std::chrono::microseconds m_start_t{};
80+
81+
//! Log prefix; usually the name of the function this was created in.
82+
const std::string m_prefix{};
83+
84+
//! A descriptive message of what is being timed.
85+
const std::string m_title{};
86+
87+
//! Forwarded on to LogPrint if specified - has the effect of only
88+
//! outputing the timing log when a particular debug= category is specified.
89+
const BCLog::LogFlags m_log_category{};
90+
91+
};
92+
93+
} // namespace BCLog
94+
95+
96+
#define LOG_TIME_MICROS(end_msg, ...) \
97+
BCLog::Timer<std::chrono::microseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__)
98+
#define LOG_TIME_MILLIS(end_msg, ...) \
99+
BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__)
100+
#define LOG_TIME_SECONDS(end_msg, ...) \
101+
BCLog::Timer<std::chrono::seconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__)
102+
103+
104+
#endif // BITCOIN_LOGGING_TIMER_H

src/test/logging_tests.cpp

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,36 @@
1+
// Copyright (c) 2019 The Bitcoin Core developers
2+
// Distributed under the MIT software license, see the accompanying
3+
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
4+
5+
#include <logging.h>
6+
#include <logging/timer.h>
7+
#include <test/setup_common.h>
8+
9+
#include <chrono>
10+
11+
#include <boost/test/unit_test.hpp>
12+
13+
BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
14+
15+
BOOST_AUTO_TEST_CASE(logging_timer)
16+
{
17+
18+
SetMockTime(1);
19+
auto sec_timer = BCLog::Timer<std::chrono::seconds>("tests", "end_msg");
20+
SetMockTime(2);
21+
BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)");
22+
23+
SetMockTime(1);
24+
auto ms_timer = BCLog::Timer<std::chrono::milliseconds>("tests", "end_msg");
25+
SetMockTime(2);
26+
BOOST_CHECK_EQUAL(ms_timer.LogMsg("test ms"), "tests: test ms (1000.00ms)");
27+
28+
SetMockTime(1);
29+
auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg");
30+
SetMockTime(2);
31+
BOOST_CHECK_EQUAL(micro_timer.LogMsg("test micros"), "tests: test micros (1000000.00μs)");
32+
33+
SetMockTime(0);
34+
}
35+
36+
BOOST_AUTO_TEST_SUITE_END()

0 commit comments

Comments
 (0)