Merge bitcoin#27005: util: Use steady clock for logging timer

fad7af7 Use steady clock for logging timer (MarcoFalke)

Pull request description:

  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.

ACKs for top commit:
  stickies-v:
    Approach ACK fad7af7
  john-moffett:
    ACK fad7af7

Tree-SHA512: bec8da0f338ed4611e1807937575e1b2afda25139d88015b1c29fa7d13946fbfbc4ee589b576c0508d505df5e5fafafcbc07d63ce4bab4b01475260d9d5d2107

Author: fanquake

src/logging/timer.h

@@ -12,6 +12,7 @@
 #include <util/types.h>
 
 #include <chrono>
+#include <optional>
 #include <string>
 
 
@@ -28,14 +29,14 @@ class Timer
         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 @@ class Timer
 
     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;

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<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)

src/util/time.h

@@ -93,6 +93,7 @@ constexpr int64_t count_microseconds(std::chrono::microseconds t) { return t.cou
 
 using HoursDouble = std::chrono::duration<double, std::chrono::hours::period>;
 using SecondsDouble = std::chrono::duration<double, std::chrono::seconds::period>;
+using MillisecondsDouble = std::chrono::duration<double, std::chrono::milliseconds::period>;
 
 /**
  * DEPRECATED