merge bitcoin#24770: Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive

Author: kwvg

doc/developer-notes.md

@@ -17,6 +17,7 @@ Developer Notes
         - [`debug.log`](#debuglog)
         - [Testnet and Regtest modes](#testnet-and-regtest-modes)
         - [DEBUG_LOCKORDER](#debug_lockorder)
+        - [DEBUG_LOCKCONTENTION](#debug_lockcontention)
         - [Valgrind suppressions file](#valgrind-suppressions-file)
         - [Compiling for test coverage](#compiling-for-test-coverage)
         - [Performance profiling with perf](#performance-profiling-with-perf)
@@ -412,6 +413,19 @@ configure option adds `-DDEBUG_LOCKORDER` to the compiler flags. This inserts
 run-time checks to keep track of which locks are held and adds warnings to the
 `debug.log` file if inconsistencies are detected.
 
+### DEBUG_LOCKCONTENTION
+
+Defining `DEBUG_LOCKCONTENTION` adds a "lock" logging category to the logging
+RPC that, when enabled, logs the location and duration of each lock contention
+to the `debug.log` file.
+
+To enable it, run configure with `-DDEBUG_LOCKCONTENTION` added to your
+CPPFLAGS, e.g. `CPPFLAGS="-DDEBUG_LOCKCONTENTION"`, then build and run dashd.
+
+You can then use the `-debug=lock` configuration option at dashd startup or
+`dash-cli logging '["lock"]'` at runtime to turn on lock contention logging.
+It can be toggled off again with `dash-cli logging [] '["lock"]'`.
+
 ### Assertions and Checks
 
 The util file `src/util/check.h` offers helpers to protect against coding and

src/evo/creditpool.h

@@ -10,6 +10,7 @@
 #include <serialize.h>
 #include <sync.h>
 #include <threadsafety.h>
+#include <tinyformat.h>
 #include <unordered_lru_cache.h>
 #include <util/ranges_set.h>
 

src/llmq/quorums.h

@@ -15,6 +15,7 @@
 #include <saltedhasher.h>
 #include <threadinterrupt.h>
 #include <unordered_lru_cache.h>
+#include <util/time.h>
 
 #include <atomic>
 #include <map>

src/logging.cpp

@@ -160,7 +160,9 @@ const CLogCategoryDesc LogCategories[] =
     {BCLog::VALIDATION, "validation"},
     {BCLog::I2P, "i2p"},
     {BCLog::IPC, "ipc"},
+#ifdef DEBUG_LOCKCONTENTION
     {BCLog::LOCK, "lock"},
+#endif
     {BCLog::BLOCKSTORE, "blockstorage"},
     {BCLog::TXRECONCILIATION, "txreconciliation"},
     {BCLog::ALL, "1"},

src/logging.h

@@ -61,7 +61,9 @@ namespace BCLog {
         VALIDATION  = (1 << 21),
         I2P         = (1 << 22),
         IPC         = (1 << 23),
+#ifdef DEBUG_LOCKCONTENTION
         LOCK        = (1 << 24),
+#endif
         BLOCKSTORE  = (1 << 26),
         TXRECONCILIATION = (1 << 27),
 

src/net.h

@@ -16,6 +16,7 @@
 #include <hash.h>
 #include <i2p.h>
 #include <limitedmap.h>
+#include <logging.h>
 #include <net_permissions.h>
 #include <netaddress.h>
 #include <netbase.h>
@@ -42,6 +43,7 @@
 #include <cstdint>
 #include <deque>
 #include <functional>
+#include <list>
 #include <map>
 #include <memory>
 #include <optional>

src/stats/rawsender.cpp

@@ -5,6 +5,7 @@
 
 #include <stats/rawsender.h>
 
+#include <logging.h>
 #include <netaddress.h>
 #include <netbase.h>
 #include <util/sock.h>

src/sync.h

@@ -6,8 +6,11 @@
 #ifndef BITCOIN_SYNC_H
 #define BITCOIN_SYNC_H
 
+#ifdef DEBUG_LOCKCONTENTION
 #include <logging.h>
 #include <logging/timer.h>
+#endif
+
 #include <threadsafety.h>
 #include <util/macros.h>
 
@@ -161,8 +164,10 @@ 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()) return;
         LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK);
+#endif
         Base::lock();
     }
 

src/test/checkqueue_tests.cpp

@@ -18,13 +18,17 @@
 #include <vector>
 
 /**
- * Identical to TestingSetup but excludes lock contention logging, as some of
- * these tests are designed to be heavily contested to trigger race conditions
- * or other issues.
+ * Identical to TestingSetup but excludes lock contention logging if
+ * `DEBUG_LOCKCONTENTION` is defined, as some of these tests are designed to be
+ * heavily contested to trigger race conditions or other issues.
  */
 struct NoLockLoggingTestingSetup : public TestingSetup {
     NoLockLoggingTestingSetup()
+#ifdef DEBUG_LOCKCONTENTION
         : TestingSetup{CBaseChainParams::MAIN, /*extra_args=*/{"-debugexclude=lock"}} {}
+#else
+        : TestingSetup{CBaseChainParams::MAIN} {}
+#endif
 };
 
 BOOST_FIXTURE_TEST_SUITE(checkqueue_tests, NoLockLoggingTestingSetup)

test/functional/rpc_misc.py

@@ -56,9 +56,6 @@ 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()), 40)
-
         # Test toggling a logging category on/off/on with the logging RPC.
         assert_equal(node.logging()['qt'], True)
         node.logging(exclude=['qt'])