From 8d2f847ed913f15677ae978a412015ac844ffceb Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Mon, 6 Sep 2021 20:59:58 +0200 Subject: [PATCH 1/4] sync: inline lock contention logging macro to fix time duration Co-authored-by: Martin Ankerl --- src/sync.cpp | 6 ------ src/sync.h | 7 +++---- 2 files changed, 3 insertions(+), 10 deletions(-) diff --git a/src/sync.cpp b/src/sync.cpp index eace86d9dda..98e6d3d65d8 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -9,7 +9,6 @@ #include #include -#include #include #include #include @@ -24,11 +23,6 @@ #include #include -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 bf15c0b4eb4..6ba63d5e4de 100644 --- a/src/sync.h +++ b/src/sync.h @@ -6,6 +6,8 @@ #ifndef BITCOIN_SYNC_H #define BITCOIN_SYNC_H +#include +#include #include #include @@ -126,9 +128,6 @@ using RecursiveMutex = AnnotatedMixin; /** Wrapped mutex: supports waiting but not recursive locking */ typedef AnnotatedMixin 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 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(); } From 498b323425d960274c40472a6a847afc1982201d Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Mon, 6 Sep 2021 21:01:57 +0200 Subject: [PATCH 2/4] log, timer: improve BCLog::LogMsg() - make timer code more homogeneous - replace division with multiplication - log if the time type is unexpected --- src/logging/timer.h | 18 +++++------------- src/test/logging_tests.cpp | 13 +++++++++---- 2 files changed, 14 insertions(+), 17 deletions(-) diff --git a/src/logging/timer.h b/src/logging/timer.h index 647e3fa30e8..6d584084cad 100644 --- a/src/logging/timer.h +++ b/src/logging/timer.h @@ -60,21 +60,13 @@ public: 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 = "ms"; - divisor = 1000.; + } else if (std::is_same::value) { + return strprintf("%s: %s (%.2fms)", m_prefix, msg, end_time.count() * 0.001); } else if (std::is_same::value) { - units = "s"; - divisor = 1000. * 1000.; + return strprintf("%s: %s (%.2fs)", m_prefix, msg, end_time.count() * 0.000001); + } else { + return "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: diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index e2e31c62d70..0e384f72e2a 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("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,9 +25,14 @@ 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("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μs)"); + BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)"); + + SetMockTime(1); + auto minute_timer = BCLog::Timer("tests", "end_msg"); + SetMockTime(2); + BOOST_CHECK_EQUAL(minute_timer.LogMsg("test minutes"), "Error: unexpected time type"); } BOOST_AUTO_TEST_SUITE_END() From bddae7e7ff7bb5931ed807acaef7336f2ee98476 Mon Sep 17 00:00:00 2001 From: MarcoFalke Date: Mon, 31 May 2021 15:59:24 +0200 Subject: [PATCH 3/4] Add util/types.h with ALWAYS_FALSE template --- src/Makefile.am | 1 + src/util/types.h | 11 +++++++++++ 2 files changed, 12 insertions(+) create mode 100644 src/util/types.h diff --git a/src/Makefile.am b/src/Makefile.am index 6f8245de8a0..eea98c7f221 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/util/types.h b/src/util/types.h new file mode 100644 index 00000000000..0047b00026b --- /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 +inline constexpr bool ALWAYS_FALSE{false}; + +#endif // BITCOIN_UTIL_TYPES_H From f530202353a4f8bb444966559aa15681ab3cebc6 Mon Sep 17 00:00:00 2001 From: Martin Ankerl Date: Tue, 7 Sep 2021 18:16:09 +0200 Subject: [PATCH 4/4] Make unexpected time type in BCLog::LogMsg() a compile-time error --- src/logging/timer.h | 10 +++++----- src/test/logging_tests.cpp | 5 ----- 2 files changed, 5 insertions(+), 10 deletions(-) diff --git a/src/logging/timer.h b/src/logging/timer.h index 6d584084cad..79627b1fe31 100644 --- a/src/logging/timer.h +++ b/src/logging/timer.h @@ -9,6 +9,7 @@ #include #include #include +#include #include #include @@ -58,14 +59,14 @@ public: return strprintf("%s: %s", m_prefix, msg); } - if (std::is_same::value) { + if constexpr (std::is_same::value) { return strprintf("%s: %s (%iμs)", m_prefix, msg, end_time.count()); - } else if (std::is_same::value) { + } else if constexpr (std::is_same::value) { return strprintf("%s: %s (%.2fms)", m_prefix, msg, end_time.count() * 0.001); - } else if (std::is_same::value) { + } else if constexpr (std::is_same::value) { return strprintf("%s: %s (%.2fs)", m_prefix, msg, end_time.count() * 0.000001); } else { - return "Error: unexpected time type"; + static_assert(ALWAYS_FALSE, "Error: unexpected time type"); } } @@ -81,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/test/logging_tests.cpp b/src/test/logging_tests.cpp index 0e384f72e2a..84ddbc50c66 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -28,11 +28,6 @@ BOOST_AUTO_TEST_CASE(logging_timer) auto sec_timer = BCLog::Timer("tests", "end_msg"); SetMockTime(2); BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)"); - - SetMockTime(1); - auto minute_timer = BCLog::Timer("tests", "end_msg"); - SetMockTime(2); - BOOST_CHECK_EQUAL(minute_timer.LogMsg("test minutes"), "Error: unexpected time type"); } BOOST_AUTO_TEST_SUITE_END()