From 9b08006bc502e67956d6ab518388fad6397cac8d Mon Sep 17 00:00:00 2001
From: Jon Atack <jon@atack.com>
Date: Wed, 18 Aug 2021 19:53:42 +0200
Subject: [PATCH] log, sync: improve lock contention logging and add time
 duration
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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 <32963518+hebasto@users.noreply.github.com>
Co-authored-by: practicalswift <practicalswift@users.noreply.github.com>
---
 src/sync.cpp | 6 +++---
 src/sync.h   | 5 +++--
 2 files changed, 6 insertions(+), 5 deletions(-)

diff --git a/src/sync.cpp b/src/sync.cpp
index 9351417d431..ef46bbb22f5 100644
--- a/src/sync.cpp
+++ b/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 */
 
diff --git a/src/sync.h b/src/sync.h
index 146c2285925..f4f6ece41dd 100644
--- a/src/sync.h
+++ b/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 @@ private:
         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