diff options
author | merge-script <falke.marco@gmail.com> | 2021-09-09 15:55:03 +0200 |
---|---|---|
committer | merge-script <falke.marco@gmail.com> | 2021-09-09 15:55:03 +0200 |
commit | d2dd1697cee9d6d0f13f9cb351bce84eaa4a72b4 (patch) | |
tree | 309aa312ea277a0fc8e5861a39e27bd64eb8a479 /src | |
parent | 1d0c57a05c2f59025eedd41ed72309505c795969 (diff) | |
parent | f530202353a4f8bb444966559aa15681ab3cebc6 (diff) | |
download | bitcoin-d2dd1697cee9d6d0f13f9cb351bce84eaa4a72b4.tar.xz |
Merge bitcoin/bitcoin#22904: sync, log: inline lock contention logging macro to fix duration, improve BCLog::LogMsg()
f530202353a4f8bb444966559aa15681ab3cebc6 Make unexpected time type in BCLog::LogMsg() a compile-time error (Martin Ankerl)
bddae7e7ff7bb5931ed807acaef7336f2ee98476 Add util/types.h with ALWAYS_FALSE template (MarcoFalke)
498b323425d960274c40472a6a847afc1982201d log, timer: improve BCLog::LogMsg() (Jon Atack)
8d2f847ed913f15677ae978a412015ac844ffceb sync: inline lock contention logging macro to fix time duration (Jon Atack)
Pull request description:
Follow-up to #22736.
The first commit addresses the issue identified and reported by Martin Ankerl in https://github.com/bitcoin/bitcoin/pull/22736#discussion_r703019629 to fix the lock contention duration reporting.
The next three commits make improvements to the timer code in `BCLog::LogMsg()` and add `util/types.h` with an `ALWAYS_FALSE` template, that springboard from https://github.com/bitcoin/bitcoin/pull/22736#discussion_r702747920 by Marco Falke.
ACKs for top commit:
martinus:
re-ACK f530202353a4f8bb444966559aa15681ab3cebc6. I ran a fully synced node for about a day. My node was mostly idle though so not much was going on. I [wrote a little script](https://github.com/martinus/bitcoin-stuff/blob/main/scripts/parse-debuglog-contention-single.rb) to parse the `debug.log` and summarize the output to see if anything interesting was going on, here is the result:
theStack:
ACK f530202353a4f8bb444966559aa15681ab3cebc6
Tree-SHA512: 37d093eac5590e1b5846ab5994d0950d71e131177d1afe4a5f7fcd614270f977e0ea117e7af788e9a74ddcccab35b42ec8fa4db3a3378940d4988df7d21cdaaa
Diffstat (limited to 'src')
-rw-r--r-- | src/Makefile.am | 1 | ||||
-rw-r--r-- | src/logging/timer.h | 24 | ||||
-rw-r--r-- | src/sync.cpp | 6 | ||||
-rw-r--r-- | src/sync.h | 7 | ||||
-rw-r--r-- | src/test/logging_tests.cpp | 8 | ||||
-rw-r--r-- | src/util/types.h | 11 |
6 files changed, 27 insertions, 30 deletions
diff --git a/src/Makefile.am b/src/Makefile.am index 6f8245de8a..eea98c7f22 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -268,6 +268,7 @@ BITCOIN_CORE_H = \ util/tokenpipe.h \ util/trace.h \ util/translation.h \ + util/types.h \ util/ui_change_type.h \ util/url.h \ util/vector.h \ diff --git a/src/logging/timer.h b/src/logging/timer.h index 647e3fa30e..79627b1fe3 100644 --- a/src/logging/timer.h +++ b/src/logging/timer.h @@ -9,6 +9,7 @@ #include <logging.h> #include <util/macros.h> #include <util/time.h> +#include <util/types.h> #include <chrono> #include <string> @@ -58,23 +59,15 @@ public: return strprintf("%s: %s", m_prefix, msg); } - if (std::is_same<TimeType, std::chrono::microseconds>::value) { + if constexpr (std::is_same<TimeType, std::chrono::microseconds>::value) { return strprintf("%s: %s (%iμs)", m_prefix, msg, end_time.count()); + } else if constexpr (std::is_same<TimeType, std::chrono::milliseconds>::value) { + return strprintf("%s: %s (%.2fms)", m_prefix, msg, end_time.count() * 0.001); + } else if constexpr (std::is_same<TimeType, std::chrono::seconds>::value) { + return strprintf("%s: %s (%.2fs)", m_prefix, msg, end_time.count() * 0.000001); + } else { + static_assert(ALWAYS_FALSE<TimeType>, "Error: unexpected time type"); } - - std::string units; - float divisor = 1; - - if (std::is_same<TimeType, std::chrono::milliseconds>::value) { - units = "ms"; - divisor = 1000.; - } else if (std::is_same<TimeType, std::chrono::seconds>::value) { - units = "s"; - divisor = 1000. * 1000.; - } - - const float time_ms = end_time.count() / divisor; - return strprintf("%s: %s (%.2f%s)", m_prefix, msg, time_ms, units); } private: @@ -89,7 +82,6 @@ private: //! Forwarded on to LogPrint if specified - has the effect of only //! outputting the timing log when a particular debug= category is specified. const BCLog::LogFlags m_log_category{}; - }; } // namespace BCLog diff --git a/src/sync.cpp b/src/sync.cpp index eace86d9dd..98e6d3d65d 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -9,7 +9,6 @@ #include <sync.h> #include <logging.h> -#include <logging/timer.h> #include <tinyformat.h> #include <util/strencodings.h> #include <util/threadnames.h> @@ -24,11 +23,6 @@ #include <utility> #include <vector> -void LockContention(const char* pszName, const char* pszFile, int nLine) -{ - LOG_TIME_MICROS_WITH_CATEGORY(strprintf("%s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK); -} - #ifdef DEBUG_LOCKORDER // // Early deadlock detection. diff --git a/src/sync.h b/src/sync.h index bf15c0b4eb..6ba63d5e4d 100644 --- a/src/sync.h +++ b/src/sync.h @@ -6,6 +6,8 @@ #ifndef BITCOIN_SYNC_H #define BITCOIN_SYNC_H +#include <logging.h> +#include <logging/timer.h> #include <threadsafety.h> #include <util/macros.h> @@ -126,9 +128,6 @@ using RecursiveMutex = AnnotatedMixin<std::recursive_mutex>; /** Wrapped mutex: supports waiting but not recursive locking */ typedef AnnotatedMixin<std::mutex> Mutex; -/** 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> class SCOPED_LOCKABLE UniqueLock : public Base @@ -138,7 +137,7 @@ private: { EnterCritical(pszName, pszFile, nLine, Base::mutex()); if (Base::try_lock()) return; - LockContention(pszName, pszFile, nLine); // log the contention + LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK); Base::lock(); } diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index e2e31c62d7..84ddbc50c6 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -15,9 +15,9 @@ BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup) BOOST_AUTO_TEST_CASE(logging_timer) { SetMockTime(1); - auto sec_timer = BCLog::Timer<std::chrono::seconds>("tests", "end_msg"); + auto micro_timer = BCLog::Timer<std::chrono::microseconds>("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<std::chrono::milliseconds>("tests", "end_msg"); @@ -25,9 +25,9 @@ BOOST_AUTO_TEST_CASE(logging_timer) BOOST_CHECK_EQUAL(ms_timer.LogMsg("test ms"), "tests: test ms (1000.00ms)"); SetMockTime(1); - auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg"); + auto sec_timer = BCLog::Timer<std::chrono::seconds>("tests", "end_msg"); SetMockTime(2); - BOOST_CHECK_EQUAL(micro_timer.LogMsg("test micros"), "tests: test micros (1000000μs)"); + BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)"); } BOOST_AUTO_TEST_SUITE_END() diff --git a/src/util/types.h b/src/util/types.h new file mode 100644 index 0000000000..0047b00026 --- /dev/null +++ b/src/util/types.h @@ -0,0 +1,11 @@ +// 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 <class> +inline constexpr bool ALWAYS_FALSE{false}; + +#endif // BITCOIN_UTIL_TYPES_H |