From b7a17444e0746c562ae97b26eba431577947b06a Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Wed, 18 Aug 2021 12:29:36 +0200 Subject: [PATCH 1/4] log, sync: add LOCK logging category, apply it to lock contention --- src/logging.cpp | 1 + src/logging.h | 1 + src/sync.cpp | 4 ++-- test/functional/rpc_misc.py | 2 +- 4 files changed, 5 insertions(+), 3 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index b456108b61c..eb2c750296d 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 38d73863e76..53a89d28bd5 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/sync.cpp b/src/sync.cpp index a2b62c2286b..9351417d431 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -29,8 +29,8 @@ static_assert(false, "thread_local is not supported"); #endif void PrintLockContention(const char* pszName, const char* pszFile, int nLine) { - LogPrintf("LOCKCONTENTION: %s\n", pszName); - LogPrintf("Locker: %s:%d\n", pszFile, nLine); + LogPrint(BCLog::LOCK, "LOCKCONTENTION: %s\n", pszName); + LogPrint(BCLog::LOCK, "Locker: %s:%d\n", pszFile, nLine); } #endif /* DEBUG_LOCKCONTENTION */ diff --git a/test/functional/rpc_misc.py b/test/functional/rpc_misc.py index 563f2ea43e0..13f33c321fc 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) From 3f4c6b87f1098436693c4990f2082515ec0ece26 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Wed, 1 Sep 2021 13:57:45 +0200 Subject: [PATCH 2/4] log, timer: add timing macro in usec LOG_TIME_MICROS_WITH_CATEGORY and update BCLog::LogMsg() to omit irrelevant decimals for microseconds and skip unneeded code and math. --- src/logging/timer.h | 12 ++++++++---- src/test/logging_tests.cpp | 2 +- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/src/logging/timer.h b/src/logging/timer.h index 159920e3972..647e3fa30e8 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/test/logging_tests.cpp b/src/test/logging_tests.cpp index e99c6e0fc8b..e2e31c62d70 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() From 9b08006bc502e67956d6ab518388fad6397cac8d Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Wed, 18 Aug 2021 19:53:42 +0200 Subject: [PATCH 3/4] log, sync: improve lock contention logging and add time duration MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit in microseconds. Change the function name in order to print "LockContention" instead of "PrintLockContention" to the log. Add Doxygen documentation. With this change, the lock contention log prints: 2021-09-01T11:29:03Z LockContention: pnode->cs_vSend, net.cpp:1373 started 2021-09-01T11:29:03Z LockContention: pnode->cs_vSend, net.cpp:1373 completed (31μs) 2021-09-01T11:29:03Z LockContention: cs_vNodes, net.cpp:2277 started 2021-09-01T11:29:03Z LockContention: cs_vNodes, net.cpp:2277 completed (6μs) 2021-09-01T11:29:04Z LockContention: cs_vNodes, net.cpp:2242 started 2021-09-01T11:29:04Z LockContention: cs_vNodes, net.cpp:2242 completed (3μs) Co-authored-by: Hennadii Stepanov <32963518+hebasto@users.noreply.github.com> Co-authored-by: practicalswift --- src/sync.cpp | 6 +++--- src/sync.h | 5 +++-- 2 files changed, 6 insertions(+), 5 deletions(-) diff --git a/src/sync.cpp b/src/sync.cpp index 9351417d431..ef46bbb22f5 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -9,6 +9,7 @@ #include #include +#include #include #include #include @@ -27,10 +28,9 @@ #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) { - LogPrint(BCLog::LOCK, "LOCKCONTENTION: %s\n", pszName); - LogPrint(BCLog::LOCK, "Locker: %s:%d\n", pszFile, nLine); + LOG_TIME_MICROS_WITH_CATEGORY(strprintf("%s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK); } #endif /* DEBUG_LOCKCONTENTION */ diff --git a/src/sync.h b/src/sync.h index 146c2285925..f4f6ece41dd 100644 --- a/src/sync.h +++ b/src/sync.h @@ -127,7 +127,8 @@ using RecursiveMutex = AnnotatedMixin; typedef AnnotatedMixin Mutex; #ifdef DEBUG_LOCKCONTENTION -void PrintLockContention(const char* pszName, const char* pszFile, int nLine); +/** Prints a lock contention to the log */ +void LockContention(const char* pszName, const char* pszFile, int nLine); #endif /** Wrapper around std::unique_lock style lock for Mutex. */ @@ -140,7 +141,7 @@ private: EnterCritical(pszName, pszFile, nLine, Base::mutex()); #ifdef DEBUG_LOCKCONTENTION if (!Base::try_lock()) { - PrintLockContention(pszName, pszFile, nLine); + LockContention(pszName, pszFile, nLine); // log the contention #endif Base::lock(); #ifdef DEBUG_LOCKCONTENTION From 7e698732836121912f179b7c743a72dd6fdffa72 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Wed, 18 Aug 2021 12:34:18 +0200 Subject: [PATCH 4/4] sync: remove DEBUG_LOCKCONTENTION preprocessor directives to allow logging the lock contentions without the need to define DEBUG_LOCKCONTENTION at compile time. --- src/sync.cpp | 5 ----- src/sync.h | 16 +++++----------- 2 files changed, 5 insertions(+), 16 deletions(-) diff --git a/src/sync.cpp b/src/sync.cpp index ef46bbb22f5..eace86d9dda 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -24,15 +24,10 @@ #include #include -#ifdef DEBUG_LOCKCONTENTION -#if !defined(HAVE_THREAD_LOCAL) -static_assert(false, "thread_local is not supported"); -#endif void LockContention(const char* pszName, const char* pszFile, int 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 f4f6ece41dd..bf15c0b4eb4 100644 --- a/src/sync.h +++ b/src/sync.h @@ -126,10 +126,8 @@ using RecursiveMutex = AnnotatedMixin; /** Wrapped mutex: supports waiting but not recursive locking */ typedef AnnotatedMixin Mutex; -#ifdef DEBUG_LOCKCONTENTION /** Prints a lock contention to the log */ void LockContention(const char* pszName, const char* pszFile, int nLine); -#endif /** Wrapper around std::unique_lock style lock for Mutex. */ template @@ -139,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()) { - LockContention(pszName, pszFile, nLine); // log the contention -#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(); }