log, sync: improve lock contention logging and add time duration

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 <[email protected]>
Co-authored-by: practicalswift <[email protected]>

Author: 3 people

src/sync.cpp

@@ -9,6 +9,7 @@
 #include <sync.h>
 
 #include <logging.h>
+#include <logging/timer.h>
 #include <tinyformat.h>
 #include <util/strencodings.h>
 #include <util/threadnames.h>
@@ -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 */
 

src/sync.h

@@ -127,7 +127,8 @@ using RecursiveMutex = AnnotatedMixin<std::recursive_mutex>;
 typedef AnnotatedMixin<std::mutex> 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 @@ class SCOPED_LOCKABLE UniqueLock : public Base
         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