Merge bitcoin/bitcoin#22872: log: improve checkaddrman logging with duration in milliseconds

22b44fc696dc1078c40d17e2d497c74c7b4ae750 p2p: improve checkaddrman logging with duration in milliseconds (Jon Atack)
ec65bed00ee2e403e39b3c5977caf4abd31ccc87 log, timer: add LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE macro (Jon Atack)
325da75a5396f3161a6eade74b349105ed5722ab log, timer: allow not repeating log message on completion (Jon Atack)

Pull request description:

  This patch:
  - updates the `logging/timer.h::Timer` class to allow not repeating the log message on completion
  - adds a `LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE` macro that prints the descriptive message when logging the start but not when logging the completion
  - updates the checkaddrman logging to log the duration, and renames the function like the `-checkaddrman` configuration option in order to prefix every log message with `CheckAddrman` instead of the longer, less pleasant, and different-from-checkaddrman `ForceCheckAddrman` (the Doxygen documentation on the function already makes clear that it is unaffected by `m_consistency_check_ratio`).

  before
  ```
  2021-09-21T18:42:50Z [opencon] Addrman checks started: new 64864, tried 1690, total 66554
  2021-09-21T18:42:50Z [opencon] Addrman checks completed successfully
  ```

  after
  ```
  2021-09-21T18:42:50Z [opencon] CheckAddrman: new 64864, tried 1690, total 66554 started
  2021-09-21T18:42:50Z [opencon] CheckAddrman: completed (76.21ms)
  ```

  To test, build and run bitcoind with `-debug=addrman -checkaddrman=<n>` for a value of `n` in the range of, say, 10 to 40.

ACKs for top commit:
  laanwj:
    Code review ACK 22b44fc696dc1078c40d17e2d497c74c7b4ae750

Tree-SHA512: 658c0dfaaa9d07092e2418f2d05007c58cc35be6593f22b3c592ce793334a885dd92dacc46bdeddc9d37939cf11174660a094c07c0fa117fbb282953aa45a94d

1 files changed, 17 insertions, 6 deletions

diff --git a/src/logging/timer.h b/src/logging/timer.h
index 79627b1fe3..b77a0e17c7 100644
--- a/src/logging/timer.h
+++ b/src/logging/timer.h
@@ -27,10 +27,12 @@ public:
     Timer(
         std::string prefix,
         std::string end_msg,
-        BCLog::LogFlags log_category = BCLog::LogFlags::ALL) :
+        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_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>();
@@ -38,7 +40,11 @@ public:
 
     ~Timer()
     {
-        this->Log(strprintf("%s completed", m_title));
+        if (m_message_on_completion) {
+            this->Log(strprintf("%s completed", m_title));
+        } else {
+            this->Log("completed");
+        }
     }
 
     void Log(const std::string& msg)
@@ -74,14 +80,17 @@ private:
     std::chrono::microseconds m_start_t{};
 
     //! Log prefix; usually the name of the function this was created in.
-    const std::string m_prefix{};
+    const std::string m_prefix;
 
     //! A descriptive message of what is being timed.
-    const std::string m_title{};
+    const std::string m_title;
 
     //! Forwarded on to LogPrint if specified - has the effect of only
     //! outputting the timing log when a particular debug= category is specified.
-    const BCLog::LogFlags m_log_category{};
+    const BCLog::LogFlags m_log_category;
+
+    //! Whether to output the message again on completion.
+    const bool m_message_on_completion;
 };
 
 } // namespace BCLog
@@ -91,6 +100,8 @@ private:
     BCLog::Timer<std::chrono::microseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category)
 #define LOG_TIME_MILLIS_WITH_CATEGORY(end_msg, log_category) \
     BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category)
+#define LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE(end_msg, log_category) \
+    BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category, /* msg_on_completion=*/false)
 #define LOG_TIME_SECONDS(end_msg) \
     BCLog::Timer<std::chrono::seconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg)