Merge bitcoin/bitcoin#22736: log, sync: change lock contention from preprocessor directive to log category

7e69873 sync: remove DEBUG_LOCKCONTENTION preprocessor directives (Jon Atack)
9b08006 log, sync: improve lock contention logging and add time duration (Jon Atack)
3f4c6b8 log, timer: add timing macro in usec LOG_TIME_MICROS_WITH_CATEGORY (Jon Atack)
b7a1744 log, sync: add LOCK logging category, apply it to lock contention (Jon Atack)

Pull request description:

  To enable lock contention logging, `DEBUG_LOCKCONTENTION` has to be defined at compilation. Once built, the logging is not limited to a category and is high frequency, verbose and in all-caps. With these factors combined, it seems likely to be rarely used.

  This patch:
  - adds a `lock` logging category
  - adds a timing macro in microseconds, `LOG_TIME_MICROS_WITH_CATEGORY`
  - updates `BCLog::LogMsg()` to omit irrelevant decimals for microseconds and skip unneeded code and math
  - improves the lock contention logging, drops the all-caps, and displays the duration in microseconds
  - removes the conditional compilation directives
  - allows lock contentions to be logged on startup with `-debug=lock` or at run time with `bitcoin-cli logging '["lock"]'`

  ```
  $ bitcoind -signet -debug=lock
  2021-09-01T12:40:01Z LockContention: cs_vNodes, net.cpp:1920 started
  2021-09-01T12:40:01Z LockContention: cs_vNodes, net.cpp:1920 completed (4μs)
  2021-09-01T12:40:01Z LockContention: cs_vNodes, net.cpp:1302 started
  2021-09-01T12:40:01Z LockContention: cs_vNodes, net.cpp:1302 completed (4μs)
  2021-09-01T12:40:02Z LockContention: cs_vNodes, net.cpp:2242 started
  2021-09-01T12:40:02Z LockContention: cs_vNodes, net.cpp:2242 completed (20μs)
  2021-09-01T12:43:04Z LockContention: ::cs_main, validation.cpp:4980 started
  2021-09-01T12:43:04Z LockContention: ::cs_main, validation.cpp:4980 completed (3μs)

  $ bitcoin-cli -signet logging
    "lock": true,

  $ bitcoin-cli -signet logging [] '["lock"]'
    "lock": false,

  $ bitcoin-cli -signet logging '["lock"]'
    "lock": true,
  ```

  I've tested this with Clang 13 and GCC 10.2.1, on Debian, with and without `--enable-debug`.

ACKs for top commit:
  hebasto:
    re-ACK 7e69873, added a contention duration to the log message since my [previous](bitcoin/bitcoin#22736 (review)) review.
  theStack:
    re-ACK 7e69873 🔏 ⏲️

Tree-SHA512: c4b5eb88d3a2c051acaa842b3055ce30efde1f114f61da6e55fcaa27476c1c33a60bc419f7f5ccda532e1bdbe70815222ec2b2b6d9226f29c8e94e598aacfee7

Author: MarcoFalke

src/logging.cpp

@@ -159,6 +159,7 @@ const CLogCategoryDesc LogCategories[] =
     {BCLog::VALIDATION, "validation"},
     {BCLog::I2P, "i2p"},
     {BCLog::IPC, "ipc"},
+    {BCLog::LOCK, "lock"},
     {BCLog::ALL, "1"},
     {BCLog::ALL, "all"},
 };

src/logging.h

@@ -59,6 +59,7 @@ namespace BCLog {
         VALIDATION  = (1 << 21),
         I2P         = (1 << 22),
         IPC         = (1 << 23),
+        LOCK        = (1 << 24),
         ALL         = ~(uint32_t)0,
     };
 

src/logging/timer.h

@@ -58,12 +58,14 @@ class Timer
             return strprintf("%s: %s", m_prefix, msg);
         }
 
-        std::string units = "";
+        if (std::is_same<TimeType, std::chrono::microseconds>::value) {
+            return strprintf("%s: %s (%iμs)", m_prefix, msg, end_time.count());
+        }
+
+        std::string units;
         float divisor = 1;
 
-        if (std::is_same<TimeType, std::chrono::microseconds>::value) {
-            units = "μs";
-        } else if (std::is_same<TimeType, std::chrono::milliseconds>::value) {
+        if (std::is_same<TimeType, std::chrono::milliseconds>::value) {
             units = "ms";
             divisor = 1000.;
         } else if (std::is_same<TimeType, std::chrono::seconds>::value) {
@@ -93,6 +95,8 @@ class Timer
 } // namespace BCLog
 
 
+#define LOG_TIME_MICROS_WITH_CATEGORY(end_msg, log_category) \
+    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_SECONDS(end_msg) \

src/sync.cpp

@@ -9,6 +9,7 @@
 #include <sync.h>
 
 #include <logging.h>
+#include <logging/timer.h>
 #include <tinyformat.h>
 #include <util/strencodings.h>
 #include <util/threadnames.h>
@@ -23,16 +24,10 @@
 #include <utility>
 #include <vector>
 
-#ifdef DEBUG_LOCKCONTENTION
-#if !defined(HAVE_THREAD_LOCAL)
-static_assert(false, "thread_local is not supported");
-#endif
-void PrintLockContention(const char* pszName, const char* pszFile, int nLine)
+void LockContention(const char* pszName, const char* pszFile, int nLine)
 {
-    LogPrintf("LOCKCONTENTION: %s\n", pszName);
-    LogPrintf("Locker: %s:%d\n", pszFile, nLine);
+    LOG_TIME_MICROS_WITH_CATEGORY(strprintf("%s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK);
 }
-#endif /* DEBUG_LOCKCONTENTION */
 
 #ifdef DEBUG_LOCKORDER
 //

src/sync.h

@@ -126,9 +126,8 @@ using RecursiveMutex = AnnotatedMixin<std::recursive_mutex>;
 /** Wrapped mutex: supports waiting but not recursive locking */
 typedef AnnotatedMixin<std::mutex> Mutex;
 
-#ifdef DEBUG_LOCKCONTENTION
-void PrintLockContention(const char* pszName, const char* pszFile, int nLine);
-#endif
+/** Prints a lock contention to the log */
+void LockContention(const char* pszName, const char* pszFile, int nLine);
 
 /** Wrapper around std::unique_lock style lock for Mutex. */
 template <typename Mutex, typename Base = typename Mutex::UniqueLock>
@@ -138,22 +137,18 @@ class SCOPED_LOCKABLE UniqueLock : public Base
     void Enter(const char* pszName, const char* pszFile, int nLine)
     {
         EnterCritical(pszName, pszFile, nLine, Base::mutex());
-#ifdef DEBUG_LOCKCONTENTION
-        if (!Base::try_lock()) {
-            PrintLockContention(pszName, pszFile, nLine);
-#endif
-            Base::lock();
-#ifdef DEBUG_LOCKCONTENTION
-        }
-#endif
+        if (Base::try_lock()) return;
+        LockContention(pszName, pszFile, nLine); // log the contention
+        Base::lock();
     }
 
     bool TryEnter(const char* pszName, const char* pszFile, int nLine)
     {
         EnterCritical(pszName, pszFile, nLine, Base::mutex(), true);
         Base::try_lock();
-        if (!Base::owns_lock())
+        if (!Base::owns_lock()) {
             LeaveCritical();
+        }
         return Base::owns_lock();
     }
 

src/test/logging_tests.cpp

@@ -27,7 +27,7 @@ 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.00μs)");
+    BOOST_CHECK_EQUAL(micro_timer.LogMsg("test micros"), "tests: test micros (1000000μs)");
 }
 
 BOOST_AUTO_TEST_SUITE_END()

test/functional/rpc_misc.py

@@ -57,7 +57,7 @@ def run_test(self):
         self.log.info("test logging rpc and help")
 
         # Test logging RPC returns the expected number of logging categories.
-        assert_equal(len(node.logging()), 24)
+        assert_equal(len(node.logging()), 25)
 
         # Test toggling a logging category on/off/on with the logging RPC.
         assert_equal(node.logging()['qt'], True)