diff --git a/doc/developer-notes.md b/doc/developer-notes.md --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -17,6 +17,7 @@ - [Writing script integration tests](#writing-script-integration-tests) - [Testnet and Regtest modes](#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) @@ -276,6 +277,18 @@ 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 that, when enabled, +logs the location and duration of each lock contention to the `debug.log` file. + +To enable it, run cmake with `-DDEBUG_LOCKCONTENTION` added to your CPPFLAGS, +e.g. `-DCMAKE_CXX_FLAGS="-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 diff --git a/src/logging.h b/src/logging.h --- a/src/logging.h +++ b/src/logging.h @@ -61,6 +61,9 @@ AVALANCHE = (1 << 22), I2P = (1 << 23), CHRONIK = (1 << 24), +#ifdef DEBUG_LOCKCONTENTION + LOCK = (1 << 25), +#endif BLOCKSTORE = (1 << 26), ALL = ~uint32_t(0), }; diff --git a/src/logging.cpp b/src/logging.cpp --- a/src/logging.cpp +++ b/src/logging.cpp @@ -128,6 +128,9 @@ {BCLog::AVALANCHE, "avalanche"}, {BCLog::I2P, "i2p"}, {BCLog::CHRONIK, "chronik"}, +#ifdef DEBUG_LOCKCONTENTION + {BCLog::LOCK, "lock"}, +#endif {BCLog::BLOCKSTORE, "blockstorage"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, diff --git a/src/logging/timer.h b/src/logging/timer.h --- a/src/logging/timer.h +++ b/src/logging/timer.h @@ -9,6 +9,7 @@ #include #include #include +#include #include #include @@ -46,21 +47,21 @@ return strprintf("%s: %s", m_prefix, msg); } - std::string units = ""; - float divisor = 1; - - if (std::is_same::value) { - units = "μs"; - } else if (std::is_same::value) { - units = "ms"; - divisor = 1000.; - } else if (std::is_same::value) { - units = "s"; - divisor = 1000. * 1000.; + if constexpr (std::is_same::value) { + return strprintf("%s: %s (%iμs)", m_prefix, msg, end_time.count()); + } else if constexpr (std::is_same::value) { + return strprintf("%s: %s (%.2fms)", m_prefix, msg, + end_time.count() * 0.001); + } else if constexpr (std::is_same::value) { + return strprintf("%s: %s (%.2fs)", m_prefix, msg, + end_time.count() * 0.000001); + } else { + static_assert(ALWAYS_FALSE, + "Error: unexpected time type"); } - - const float time_ms = end_time.count() / divisor; - return strprintf("%s: %s (%.2f%s)", m_prefix, msg, time_ms, units); } private: @@ -79,6 +80,9 @@ } // 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) diff --git a/src/net.h b/src/net.h --- a/src/net.h +++ b/src/net.h @@ -18,6 +18,7 @@ #include #include #include +#include #include #include #include @@ -36,6 +37,7 @@ #include #include #include +#include #include #include #include diff --git a/src/sync.h b/src/sync.h --- a/src/sync.h +++ b/src/sync.h @@ -6,6 +6,11 @@ #ifndef BITCOIN_SYNC_H #define BITCOIN_SYNC_H +#ifdef DEBUG_LOCKCONTENTION +#include +#include +#endif + #include #include @@ -127,10 +132,6 @@ /** 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 - /** Wrapper around std::unique_lock style lock for Mutex. */ template class SCOPED_LOCKABLE UniqueLock : public Base { @@ -138,13 +139,14 @@ void Enter(const char *pszName, const char *pszFile, int nLine) { EnterCritical(pszName, pszFile, nLine, (void *)(Base::mutex())); #ifdef DEBUG_LOCKCONTENTION - if (!Base::try_lock()) { - PrintLockContention(pszName, pszFile, nLine); -#endif - Base::lock(); -#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(); } bool TryEnter(const char *pszName, const char *pszFile, int nLine) { diff --git a/src/sync.cpp b/src/sync.cpp --- a/src/sync.cpp +++ b/src/sync.cpp @@ -19,13 +19,6 @@ #include #include -#ifdef DEBUG_LOCKCONTENTION -void PrintLockContention(const char *pszName, const char *pszFile, int nLine) { - LogPrintf("LOCKCONTENTION: %s\n", pszName); - LogPrintf("Locker: %s:%d\n", pszFile, nLine); -} -#endif /* DEBUG_LOCKCONTENTION */ - #ifdef DEBUG_LOCKORDER // // Early deadlock detection. diff --git a/src/test/checkqueue_tests.cpp b/src/test/checkqueue_tests.cpp --- a/src/test/checkqueue_tests.cpp +++ b/src/test/checkqueue_tests.cpp @@ -21,7 +21,25 @@ #include #include -BOOST_FIXTURE_TEST_SUITE(checkqueue_tests, TestingSetup) +/** + * 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) static const unsigned int QUEUE_BATCH_SIZE = 128; static const int SCRIPT_CHECK_THREADS = 3; diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -14,10 +14,11 @@ BOOST_AUTO_TEST_CASE(logging_timer) { SetMockTime(1); - auto sec_timer = BCLog::Timer("tests", "end_msg"); + auto micro_timer = + BCLog::Timer("tests", "end_msg"); SetMockTime(2); - BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), - "tests: test secs (1.00s)"); + BOOST_CHECK_EQUAL(micro_timer.LogMsg("test micros"), + "tests: test micros (1000000μs)"); SetMockTime(1); auto ms_timer = BCLog::Timer("tests", "end_msg"); @@ -25,11 +26,10 @@ BOOST_CHECK_EQUAL(ms_timer.LogMsg("test ms"), "tests: test ms (1000.00ms)"); SetMockTime(1); - auto micro_timer = - BCLog::Timer("tests", "end_msg"); + auto sec_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(sec_timer.LogMsg("test secs"), + "tests: test secs (1.00s)"); SetMockTime(0); } diff --git a/src/util/types.h b/src/util/types.h new file mode 100644 --- /dev/null +++ b/src/util/types.h @@ -0,0 +1,10 @@ +// Copyright (c) 2021 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#ifndef BITCOIN_UTIL_TYPES_H +#define BITCOIN_UTIL_TYPES_H + +template inline constexpr bool ALWAYS_FALSE{false}; + +#endif // BITCOIN_UTIL_TYPES_H diff --git a/test/functional/rpc_misc.py b/test/functional/rpc_misc.py --- a/test/functional/rpc_misc.py +++ b/test/functional/rpc_misc.py @@ -59,7 +59,9 @@ self.log.info("test logging rpc and help") # Test logging RPC returns the expected number of logging categories. - assert_equal(len(node.logging()), 26) + # Use check if it is greater or equal because some logging categories + # are behind a preprocessor directive. + assert_greater_than_or_equal(len(node.logging()), 26) # Test toggling a logging category on/off/on with the logging RPC. assert_equal(node.logging()['qt'], True)