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

436a5783c7 Merge bitcoin/bitcoin#22736: log, sync: change lock contention from preprocessor directive to log category (MarcoFalke)

Pull request description:

  7e698732836121912f179b7c743a72dd6fdffa72 sync: remove DEBUG_LOCKCONTENTION preprocessor directives (Jon Atack)
  9b08006bc502e67956d6ab518388fad6397cac8d log, sync: improve lock contention logging and add time duration (Jon Atack)
  3f4c6b87f1098436693c4990f2082515ec0ece26 log, timer: add timing macro in usec LOG_TIME_MICROS_WITH_CATEGORY (Jon Atack)
  b7a17444e0746c562ae97b26eba431577947b06a 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`.

  ## Checklist:
    _Go over all the following points, and put an `x` in all the boxes that apply._
  - [ ] I have performed a self-review of my own code
  - [ ] I have commented my code, particularly in hard-to-understand areas
  - [ ] I have added or updated relevant unit/integration/functional/e2e tests
  - [ ] I have made corresponding changes to the documentation
  - [x] I have assigned this pull request to a milestone _(for repository code-owners and collaborators only)_

Top commit has no ACKs.

Tree-SHA512: ecd15833b9e5752067c92a074f61d88fb8528157b1c0446f9f74d4898acb9c09ebb5f652c75152785a41126fdf777032a6f85d472cd1d9a0b6013519329dc2e7

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 @@ public:
             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 @@ private:
 } // 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 @@ private:
     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
+        if (Base::try_lock()) return;
+        LockContention(pszName, pszFile, nLine); // log the contention
         Base::lock();
-#ifdef DEBUG_LOCKCONTENTION
-        }
-#endif
     }
 
     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 @@ class RpcMiscTest(BitcoinTestFramework):
         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