Use steady clock for logging timer

pull/27005/head
MarcoFalke 1 year ago
parent 1ff254e45c
commit fad7af700e
No known key found for this signature in database
GPG Key ID: CE2B75697E69A548

@ -12,6 +12,7 @@
#include <util/types.h>
#include <chrono>
#include <optional>
#include <string>
@ -28,14 +29,14 @@ public:
std::string prefix,
std::string end_msg,
BCLog::LogFlags log_category = BCLog::LogFlags::ALL,
bool msg_on_completion = true) :
m_prefix(std::move(prefix)),
m_title(std::move(end_msg)),
m_log_category(log_category),
m_message_on_completion(msg_on_completion)
bool msg_on_completion = true)
: m_prefix(std::move(prefix)),
m_title(std::move(end_msg)),
m_log_category(log_category),
m_message_on_completion(msg_on_completion)
{
this->Log(strprintf("%s started", m_title));
m_start_t = GetTime<std::chrono::microseconds>();
m_start_t = std::chrono::steady_clock::now();
}
~Timer()
@ -60,24 +61,25 @@ public:
std::string LogMsg(const std::string& msg)
{
const auto end_time = GetTime<std::chrono::microseconds>() - m_start_t;
if (m_start_t.count() <= 0) {
const auto end_time{std::chrono::steady_clock::now()};
if (!m_start_t) {
return strprintf("%s: %s", m_prefix, msg);
}
const auto duration{end_time - *m_start_t};
if constexpr (std::is_same<TimeType, std::chrono::microseconds>::value) {
return strprintf("%s: %s (%iμs)", m_prefix, msg, end_time.count());
return strprintf("%s: %s (%iμs)", m_prefix, msg, Ticks<std::chrono::microseconds>(duration));
} else if constexpr (std::is_same<TimeType, std::chrono::milliseconds>::value) {
return strprintf("%s: %s (%.2fms)", m_prefix, msg, end_time.count() * 0.001);
return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));
} else if constexpr (std::is_same<TimeType, std::chrono::seconds>::value) {
return strprintf("%s: %s (%.2fs)", m_prefix, msg, end_time.count() * 0.000001);
return strprintf("%s: %s (%.2fs)", m_prefix, msg, Ticks<SecondsDouble>(duration));
} else {
static_assert(ALWAYS_FALSE<TimeType>, "Error: unexpected time type");
}
}
private:
std::chrono::microseconds m_start_t{};
std::optional<std::chrono::steady_clock::time_point> m_start_t{};
//! Log prefix; usually the name of the function this was created in.
const std::string m_prefix;

@ -75,20 +75,9 @@ struct LogSetup : public BasicTestingSetup {
BOOST_AUTO_TEST_CASE(logging_timer)
{
SetMockTime(1);
auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg");
SetMockTime(2);
BOOST_CHECK_EQUAL(micro_timer.LogMsg("test micros"), "tests: test micros (1000000μs)");
SetMockTime(1);
auto ms_timer = BCLog::Timer<std::chrono::milliseconds>("tests", "end_msg");
SetMockTime(2);
BOOST_CHECK_EQUAL(ms_timer.LogMsg("test ms"), "tests: test ms (1000.00ms)");
SetMockTime(1);
auto sec_timer = BCLog::Timer<std::chrono::seconds>("tests", "end_msg");
SetMockTime(2);
BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)");
const std::string_view result_prefix{"tests: msg ("};
BOOST_CHECK_EQUAL(micro_timer.LogMsg("msg").substr(0, result_prefix.size()), result_prefix);
}
BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup)

Loading…
Cancel
Save