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

src/Makefile.am

@@ -360,6 +360,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 \

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

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.

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>
 
@@ -149,9 +151,6 @@ inline void AssertLockNotHeldInline(const char* name, const char* file, int line
 inline void AssertLockNotHeldInline(const char* name, const char* file, int line, SharedMutex* cs) LOCKS_EXCLUDED(cs) { AssertLockNotHeldInternal(name, file, line, cs); }
 #define AssertLockNotHeld(cs) AssertLockNotHeldInline(#cs, __FILE__, __LINE__, &cs)
 
-/** 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
@@ -161,7 +160,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();
     }
 

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()

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