Merge bitcoin/bitcoin#24770: Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive

4394733 Add DEBUG_LOCKCONTENTION documentation to the developer notes (Jon Atack)
39a34b6 Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive (Jon Atack)

Pull request description:

  This is a more minimal, no-frills version of #24734 for backport. The other fixes and improvements in that pull can be done after.

  *Copy of the PR 24734 description:*

  PRs #22736, #22904 and #23223 changed lock contention logging from a `DEBUG_LOCKCONTENTION` compile-time preprocessor directive to a runtime `lock` log category and improved the logging output. This changed the locking from using `lock()` to `try_lock()`:

  - `void Mutex::UniqueLock::lock()` acquires the mutex and blocks until it gains access to it

  - `bool Mutex::UniqueLock::try_lock()` doesn't block but instead immediately returns whether it acquired the mutex; it may be used by `lock()` internally as part of the deadlock-avoidance algorithm

  In theory the cost of `try_lock` might be essentially the [same](https://www.erisian.com.au/bitcoin-core-dev/log-2022-03-31.html#l-697) relative to `lock`. The test-and-set logic of these calls is purported to be ~ constant time, optimised and light/quick if used carefully (i.e. no mutex convoying), compared to system calls, memory/cache coherency and fences, wait queues, and (particularly) lock contentions. See the discussion around bitcoin/bitcoin#22736 (comment) and after with respect to performance/cost aspects.  However, there are reasonable concerns (see [here](bitcoin/bitcoin#22736 (comment)) and [here](https://www.erisian.com.au/bitcoin-core-dev/log-2022-03-31.html#l-620)) that `Base::try_lock()` may be potentially [costly](https://www.erisian.com.au/bitcoin-core-dev/log-2022-03-31.html#l-700) or [risky](bitcoin/bitcoin#22904 (comment)) compared to `Base::lock()` in this very frequently called code.

  One alternative to keep the run-time lock logging would be to gate the `try_lock` call behind the logging conditional, for example as proposed in bitcoin/bitcoin@ccd73de and ACKed [here](bitcoin/bitcoin#22736 (comment)). However, this would add the [cost](bitcoin/bitcoin#22736 (comment)) of `if (LogAcceptCategory(BCLog::LOCK))` to the hotspot, instead of replacing `lock` with `try_lock`, for the most frequent happy path (non-contention).

  It turns out we can keep the advantages of the runtime lock contention logging (the ability to turn it on/off at runtime) while out of prudence putting the `try_lock()` call and `lock` logging category behind a  `DEBUG_LOCKCONTENTION` compile-time preprocessor directive, and also still retain the lock logging enhancements of the mentioned PRs, as suggested in bitcoin/bitcoin#24734 (comment) by W. J. van der Laan, in bitcoin/bitcoin#22736 (comment), and in the linked IRC discussion.

  Proposed here and for backport to v23.

ACKs for top commit:
  laanwj:
    Code review ACK 4394733

Tree-SHA512: 89b1271cae1dca0eb251914b1a60fc5b68320aab4a3939c57eec3a33a3c8f01688f05d95dfc31f91d71a6ed80cfe2d67b77ff14742611cc206175e47b2e5d3b1

Author: fanquake

doc/developer-notes.md

@@ -17,6 +17,7 @@ Developer Notes
         - [`debug.log`](#debuglog)
         - [Signet, testnet, and regtest modes](#signet-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)
@@ -362,6 +363,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 bitcoind.
+
+You can then use the `-debug=lock` configuration option at bitcoind startup or
+`bitcoin-cli logging '["lock"]'` at runtime to turn on lock contention logging.
+It can be toggled off again with `bitcoin-cli logging [] '["lock"]'`.
+
 ### Assertions and Checks
 
 The util file `src/util/check.h` offers helpers to protect against coding and

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::UTIL, "util"},
     {BCLog::BLOCKSTORE, "blockstorage"},
     {BCLog::ALL, "1"},

src/logging.h

@@ -60,7 +60,9 @@ namespace BCLog {
         VALIDATION  = (1 << 21),
         I2P         = (1 << 22),
         IPC         = (1 << 23),
+#ifdef DEBUG_LOCKCONTENTION
         LOCK        = (1 << 24),
+#endif
         UTIL        = (1 << 25),
         BLOCKSTORE  = (1 << 26),
         ALL         = ~(uint32_t)0,

src/net.h

@@ -13,6 +13,7 @@
 #include <crypto/siphash.h>
 #include <hash.h>
 #include <i2p.h>
+#include <logging.h>
 #include <net_permissions.h>
 #include <netaddress.h>
 #include <netbase.h>
@@ -32,6 +33,7 @@
 #include <cstdint>
 #include <deque>
 #include <functional>
+#include <list>
 #include <map>
 #include <memory>
 #include <optional>

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>
 
@@ -136,8 +139,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

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