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

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