merge bitcoin#22872: improve checkaddrman logging with duration in milliseconds

src/addrman.cpp

@@ -7,6 +7,8 @@
 #include <addrman_impl.h>
 
 #include <hash.h>
+#include <logging.h>
+#include <logging/timer.h>
 #include <netaddress.h>
 #include <protocol.h>
 #include <random.h>
@@ -389,7 +391,7 @@ void AddrManImpl::Unserialize(Stream& s_)
         LogPrint(BCLog::ADDRMAN, "addrman lost %i new and %i tried addresses due to collisions or invalid addresses\n", nLostUnk, nLost);
     }
 
-    const int check_code{ForceCheckAddrman()};
+    const int check_code{CheckAddrman()};
     if (check_code != 0) {
         throw DbInconsistentError(strprintf(
             "Corrupt data. Consistency check failed with code %s",
@@ -956,18 +958,19 @@ void AddrManImpl::Check() const
     if (m_consistency_check_ratio == 0) return;
     if (insecure_rand.randrange(m_consistency_check_ratio) >= 1) return;
 
-    const int err{ForceCheckAddrman()};
+    const int err{CheckAddrman()};
     if (err) {
         LogPrintf("ADDRMAN CONSISTENCY CHECK FAILED!!! err=%i\n", err);
         assert(false);
     }
 }
 
-int AddrManImpl::ForceCheckAddrman() const
+int AddrManImpl::CheckAddrman() const
 {
     AssertLockHeld(cs);
 
-    LogPrint(BCLog::ADDRMAN, "Addrman checks started: new %i, tried %i, total %u\n", nNew, nTried, vRandom.size());
+    LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE(
+        strprintf("new %i, tried %i, total %u", nNew, nTried, vRandom.size()), BCLog::ADDRMAN);
 
     std::unordered_set<int> setTried;
     std::unordered_map<int, int> mapNew;
@@ -1047,7 +1050,6 @@ int AddrManImpl::ForceCheckAddrman() const
     if (nKey.IsNull())
         return -16;
 
-    LogPrint(BCLog::ADDRMAN, "Addrman checks completed successfully\n");
     return 0;
 }
 

src/addrman_impl.h

@@ -6,6 +6,7 @@
 #define BITCOIN_ADDRMAN_IMPL_H
 
 #include <logging.h>
+#include <logging/timer.h>
 #include <netaddress.h>
 #include <protocol.h>
 #include <serialize.h>
@@ -269,12 +270,13 @@ private:
 
     std::pair<CAddress, int64_t> SelectTriedCollision_() EXCLUSIVE_LOCKS_REQUIRED(cs);
 
-    //! Consistency check, taking into account m_consistency_check_ratio. Will std::abort if an inconsistency is detected.
+    //! Consistency check, taking into account m_consistency_check_ratio.
+    //! Will std::abort if an inconsistency is detected.
     void Check() const EXCLUSIVE_LOCKS_REQUIRED(cs);
 
     //! Perform consistency check, regardless of m_consistency_check_ratio.
     //! @returns an error code or zero.
-    int ForceCheckAddrman() const EXCLUSIVE_LOCKS_REQUIRED(cs);
+    int CheckAddrman() const EXCLUSIVE_LOCKS_REQUIRED(cs);
 };
 
 #endif // BITCOIN_ADDRMAN_IMPL_H

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> UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category)
 #define LOG_TIME_MILLIS_WITH_CATEGORY(end_msg, log_category) \
     BCLog::Timer<std::chrono::milliseconds> UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category)
+#define LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE(end_msg, log_category) \
+    BCLog::Timer<std::chrono::milliseconds> UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category, /* msg_on_completion=*/false)
 #define LOG_TIME_SECONDS(end_msg) \
     BCLog::Timer<std::chrono::seconds> UNIQUE_NAME(logging_timer)(__func__, end_msg)
 

test/functional/feature_asmap.py

@@ -89,8 +89,8 @@ class AsmapTest(BitcoinTestFramework):
         self.restart_node(0, ["-asmap", "-checkaddrman=1"])
         with self.node.assert_debug_log(
             expected_msgs=[
-                "Addrman checks started: new 1, tried 1, total 2",
-                "Addrman checks completed successfully",
+                "CheckAddrman: new 1, tried 1, total 2 started",
+                "CheckAddrman: completed",
             ]
         ):
             self.node.getnodeaddresses()  # getnodeaddresses re-runs the addrman checks

test/functional/rpc_net.py

@@ -280,7 +280,7 @@ class NetTest(DashTestFramework):
 
         self.log.debug("Test that adding a valid address to the tried table succeeds")
         assert_equal(node.addpeeraddress(address="1.2.3.4", tried=True, port=8333), {"success": True})
-        with node.assert_debug_log(expected_msgs=["Addrman checks started: new 0, tried 1, total 1"]):
+        with node.assert_debug_log(expected_msgs=["CheckAddrman: new 0, tried 1, total 1 started"]):
             addrs = node.getnodeaddresses(count=0)  # getnodeaddresses re-runs the addrman checks
             assert_equal(len(addrs), 1)
             assert_equal(addrs[0]["address"], "1.2.3.4")
@@ -293,7 +293,7 @@ class NetTest(DashTestFramework):
 
         self.log.debug("Test that adding a second address, this time to the new table, succeeds")
         assert_equal(node.addpeeraddress(address="2.0.0.0", port=8333), {"success": True})
-        with node.assert_debug_log(expected_msgs=["Addrman checks started: new 1, tried 1, total 2"]):
+        with node.assert_debug_log(expected_msgs=["CheckAddrman: new 1, tried 1, total 2 started"]):
             addrs = node.getnodeaddresses(count=0)  # getnodeaddresses re-runs the addrman checks
             assert_equal(len(addrs), 2)