From fad7af700e3f57d16631e27fbe2fd7aaa6c9a950 Mon Sep 17 00:00:00 2001 From: MarcoFalke <*~=`'#}+{/-|&$^_@721217.xyz> Date: Tue, 3 Jan 2023 12:28:52 +0100 Subject: [PATCH] Use steady clock for logging timer --- src/logging/timer.h | 26 ++++++++++++++------------ src/test/logging_tests.cpp | 15 ++------------- 2 files changed, 16 insertions(+), 25 deletions(-) diff --git a/src/logging/timer.h b/src/logging/timer.h index ea0821dede9..993ba99c25f 100644 --- a/src/logging/timer.h +++ b/src/logging/timer.h @@ -12,6 +12,7 @@ #include #include +#include #include @@ -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(); + 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() - 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::value) { - return strprintf("%s: %s (%iμs)", m_prefix, msg, end_time.count()); + return strprintf("%s: %s (%iμs)", m_prefix, msg, Ticks(duration)); } else if constexpr (std::is_same::value) { - return strprintf("%s: %s (%.2fms)", m_prefix, msg, end_time.count() * 0.001); + return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks(duration)); } else if constexpr (std::is_same::value) { - return strprintf("%s: %s (%.2fs)", m_prefix, msg, end_time.count() * 0.000001); + return strprintf("%s: %s (%.2fs)", m_prefix, msg, Ticks(duration)); } else { static_assert(ALWAYS_FALSE, "Error: unexpected time type"); } } private: - std::chrono::microseconds m_start_t{}; + std::optional m_start_t{}; //! Log prefix; usually the name of the function this was created in. const std::string m_prefix; diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 022e33f99de..beb9398c74d 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -75,20 +75,9 @@ struct LogSetup : public BasicTestingSetup { BOOST_AUTO_TEST_CASE(logging_timer) { - SetMockTime(1); auto micro_timer = BCLog::Timer("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("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("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)