Merge bitcoin#22736: log, sync: change lock contention from preproces…

…sor 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#22736 (review)) review.
  theStack:
    re-ACK 7e69873 🔏 ⏲️

Tree-SHA512: c4b5eb88d3a2c051acaa842b3055ce30efde1f114f61da6e55fcaa27476c1c33a60bc419f7f5ccda532e1bdbe70815222ec2b2b6d9226f29c8e94e598aacfee7

src/logging.cpp

@@ -165,6 +165,7 @@ const CLogCategoryDesc LogCategories[] =
     {BCLog::LEVELDB, "leveldb"},
     {BCLog::VALIDATION, "validation"},
     {BCLog::I2P, "i2p"},
+    {BCLog::LOCK, "lock"},
     {BCLog::ALL, "1"},
     {BCLog::ALL, "all"},
 

src/logging.h

@@ -58,6 +58,7 @@ namespace BCLog {
         LEVELDB     = (1 << 20),
         VALIDATION  = (1 << 21),
         I2P         = (1 << 22),
+        LOCK        = (1 << 24),
 
         //Start Dash
         CHAINLOCKS  = ((uint64_t)1 << 32),

src/logging/timer.h

@@ -7,7 +7,7 @@
 #define BITCOIN_LOGGING_TIMER_H
 
 #include <logging.h>
-#include <sync.h>
+#include <util/macros.h>
 #include <util/time.h>
 
 #include <chrono>
@@ -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,15 +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 Locker: %s:%d\n", pszName, 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

@@ -124,9 +124,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>
@@ -136,14 +135,9 @@ 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)

src/test/logging_tests.cpp

@@ -28,7 +28,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)");
 
     SetMockTime(0);
 }

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()), 36)
+        assert_equal(len(node.logging()), 37)
 
         # Test toggling a logging category on/off/on with the logging RPC.
         assert_equal(node.logging()['qt'], True)

test/lint/lint-circular-dependencies.sh

@@ -99,6 +99,7 @@ EXPECTED_CIRCULAR_DEPENDENCIES=(
     "evo/deterministicmns -> validation -> evo/deterministicmns"
     "evo/chainhelper -> masternode/payments -> validation -> evo/chainhelper"
     "evo/deterministicmns -> validationinterface -> evo/deterministicmns"
+    "logging -> util/system -> sync -> logging/timer -> logging"
 )
 
 EXIT_CODE=0