util: Use steady clock for logging timer

maflcko commented at 11:14 am on January 31, 2023: member

The logging timer has many issues:

The underlying clock is mockable, meaning that benchmarks are useless when mocktime was set at the beginning or end of the benchmark.
The underlying clock is not monotonic, meaning that benchmarks are useless when the system time was changed during the benchmark.

Fix all issues in this patch.

DrahtBot commented at 11:14 am on January 31, 2023: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	john-moffett
Approach ACK	stickies-v

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

DrahtBot added the label Utils/log/libs on Jan 31, 2023

john-moffett approved

john-moffett commented at 2:08 pm on January 31, 2023: contributor

ACK fa3fc86202e59c2afb579323072ad213e6e6449c

fanquake requested review from stickies-v on Jan 31, 2023

in src/logging/timer.h:63 in fa3fc86202 outdated

59@@ -60,8 +60,8 @@ class Timer
60 
61     std::string LogMsg(const std::string& msg)
62     {
63-        const auto end_time = GetTime<std::chrono::microseconds>() - m_start_t;
64-        if (m_start_t.count() <= 0) {
65+        const auto end_time{std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now() - m_start_t)};

stickies-v commented at 3:27 pm on January 31, 2023:

Suggest renaming to duration while you’re touching this, end_time is incorrect. Does increase the LoC change further down, though.

0        const auto duration{std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now() - m_start_t)};

maflcko commented at 5:50 pm on January 31, 2023:

Thanks, done

in src/logging/timer.h:64 in fa3fc86202 outdated

59@@ -60,8 +60,8 @@ class Timer
60 
61     std::string LogMsg(const std::string& msg)
62     {
63-        const auto end_time = GetTime<std::chrono::microseconds>() - m_start_t;
64-        if (m_start_t.count() <= 0) {
65+        const auto end_time{std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now() - m_start_t)};
66+        if (m_start_t == decltype(m_start_t){}) {

stickies-v commented at 3:32 pm on January 31, 2023:

Have you considered making m_start_t a std::optional?

maflcko commented at 5:50 pm on January 31, 2023:

Thanks, done

stickies-v commented at 3:33 pm on January 31, 2023: contributor

Concept ACK - using steady_clock seems strictly better.

Use steady clock for logging timer fad7af700e

maflcko force-pushed on Jan 31, 2023

in src/test/logging_tests.cpp:80 in fad7af700e

88-    SetMockTime(1);
89-    auto sec_timer = BCLog::Timer<std::chrono::seconds>("tests", "end_msg");
90-    SetMockTime(2);
91-    BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)");
92+    const std::string_view result_prefix{"tests: msg ("};
93+    BOOST_CHECK_EQUAL(micro_timer.LogMsg("msg").substr(0, result_prefix.size()), result_prefix);

stickies-v commented at 7:54 pm on January 31, 2023:

We don’t need to cut all this test coverage, e.g. we can still cut the mocktime but:

capture auto test_start{std::chrono::steady_clock::now()} at the beginning and and ensure that LogMsg contains a duration that’s longer than now() - test_start
ensure that the different timers accurately represent s/ms/μs

Do you think the current timer test coverage is unnecessary?

maflcko commented at 8:56 am on February 1, 2023:

Not sure if the goal of a unit test is to re-implement the whole function on top of fuzzy parsing? Happy to push any patch if someone writes something, though.

stickies-v commented at 7:56 pm on January 31, 2023: contributor

Approach ACK fad7af700e3f57d16631e27fbe2fd7aaa6c9a950

New logic in timer.h LGTM, just not sure about the test coverage cuts - but I’m not overly concerned either.

fanquake requested review from john-moffett on Feb 1, 2023

john-moffett approved

john-moffett commented at 8:02 pm on February 1, 2023: contributor

ACK fad7af700e3f57d16631e27fbe2fd7aaa6c9a950

I’m fine with the unit test the way it is, but if you want to do a simple additional check to make sure there’s a digit following the parenthesis, here’s a diff:

0diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
1index beb9398c74d..64a9129aa16 100644
2--- a/src/test/logging_tests.cpp
3+++ b/src/test/logging_tests.cpp
4@@ -8,0 +9 @@
5+#include <util/strencodings.h>
6@@ -80,0 +82,2 @@ BOOST_AUTO_TEST_CASE(logging_timer)
7+    uint8_t digit;
8+    BOOST_CHECK(ParseUInt8(micro_timer.LogMsg("msg").substr(result_prefix.size(), 1), &digit));

fanquake merged this on Feb 2, 2023

fanquake closed this on Feb 2, 2023

maflcko deleted the branch on Feb 2, 2023

sidhujag referenced this in commit ffe5039a58 on Feb 3, 2023

bitcoin locked this on Feb 2, 2024

util: Use steady clock for logging timer #27005

Reviews