diff --git a/src/logging.cpp b/src/logging.cpp index b456108b61..eb2c750296 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -159,6 +159,7 @@ const CLogCategoryDesc LogCategories[] = {BCLog::VALIDATION, "validation"}, {BCLog::I2P, "i2p"}, {BCLog::IPC, "ipc"}, + {BCLog::LOCK, "lock"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, }; diff --git a/src/logging.h b/src/logging.h index 38d73863e7..53a89d28bd 100644 --- a/src/logging.h +++ b/src/logging.h @@ -59,6 +59,7 @@ namespace BCLog { VALIDATION = (1 << 21), I2P = (1 << 22), IPC = (1 << 23), + LOCK = (1 << 24), ALL = ~(uint32_t)0, }; diff --git a/src/logging/timer.h b/src/logging/timer.h index 159920e397..647e3fa30e 100644 --- a/src/logging/timer.h +++ b/src/logging/timer.h @@ -58,12 +58,14 @@ public: return strprintf("%s: %s", m_prefix, msg); } - std::string units = ""; + if (std::is_same::value) { + return strprintf("%s: %s (%iμs)", m_prefix, msg, end_time.count()); + } + + std::string units; float divisor = 1; - if (std::is_same::value) { - units = "μs"; - } else if (std::is_same::value) { + if (std::is_same::value) { units = "ms"; divisor = 1000.; } else if (std::is_same::value) { @@ -93,6 +95,8 @@ private: } // namespace BCLog +#define LOG_TIME_MICROS_WITH_CATEGORY(end_msg, log_category) \ + BCLog::Timer PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category) #define LOG_TIME_MILLIS_WITH_CATEGORY(end_msg, log_category) \ BCLog::Timer PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, log_category) #define LOG_TIME_SECONDS(end_msg) \ diff --git a/src/sync.cpp b/src/sync.cpp index a2b62c2286..eace86d9dd 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -9,6 +9,7 @@ #include #include +#include #include #include #include @@ -23,16 +24,10 @@ #include #include -#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\n", pszName); - LogPrintf("Locker: %s:%d\n", pszFile, nLine); + LOG_TIME_MICROS_WITH_CATEGORY(strprintf("%s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK); } -#endif /* DEBUG_LOCKCONTENTION */ #ifdef DEBUG_LOCKORDER // diff --git a/src/sync.h b/src/sync.h index 146c228592..bf15c0b4eb 100644 --- a/src/sync.h +++ b/src/sync.h @@ -126,9 +126,8 @@ using RecursiveMutex = AnnotatedMixin; /** Wrapped mutex: supports waiting but not recursive locking */ typedef AnnotatedMixin 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 @@ -138,22 +137,18 @@ 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 - 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) { EnterCritical(pszName, pszFile, nLine, Base::mutex(), true); Base::try_lock(); - if (!Base::owns_lock()) + if (!Base::owns_lock()) { LeaveCritical(); + } return Base::owns_lock(); } diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index e99c6e0fc8..e2e31c62d7 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -27,7 +27,7 @@ BOOST_AUTO_TEST_CASE(logging_timer) SetMockTime(1); auto micro_timer = BCLog::Timer("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)"); } BOOST_AUTO_TEST_SUITE_END() diff --git a/test/functional/rpc_misc.py b/test/functional/rpc_misc.py index 563f2ea43e..13f33c321f 100755 --- a/test/functional/rpc_misc.py +++ b/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()), 24) + assert_equal(len(node.logging()), 25) # Test toggling a logging category on/off/on with the logging RPC. assert_equal(node.logging()['qt'], True)