Added benchmark in mutex lock

src/sync.cpp

@@ -10,6 +10,8 @@
 
 #include <stdio.h>
 
+#include <mutex>
+
 #include <boost/foreach.hpp>
 #include <boost/thread.hpp>
 
@@ -80,7 +82,7 @@ static void potential_deadlock_detected(const std::pair<void*, void*>& mismatch,
 {
  LogPrintf("POTENTIAL DEADLOCK DETECTED\n");
  LogPrintf("Previous lock order was:\n");
- BOOST_FOREACH (const PAIRTYPE(void*, CLockLocation) & i, s2) {
+ for (const PAIRTYPE(void*, CLockLocation) & i : s2) {
  if (i.first == mismatch.first) {
  LogPrintf(" (1)");
  }
@@ -90,7 +92,7 @@ static void potential_deadlock_detected(const std::pair<void*, void*>& mismatch,
  LogPrintf(" %s\n", i.second.ToString());
  }
  LogPrintf("Current lock order is:\n");
- BOOST_FOREACH (const PAIRTYPE(void*, CLockLocation) & i, s1) {
+ for (const PAIRTYPE(void*, CLockLocation) & i : s1) {
  if (i.first == mismatch.first) {
  LogPrintf(" (1)");
  }
@@ -110,7 +112,7 @@ static void push_lock(void* c, const CLockLocation& locklocation, bool fTry)
 
  (*lockstack).push_back(std::make_pair(c, locklocation));
 
- BOOST_FOREACH (const PAIRTYPE(void*, CLockLocation) & i, (*lockstack)) {
+ for (const PAIRTYPE(void*, CLockLocation) & i : (*lockstack)) {
  if (i.first == c)
  break;
 
@@ -144,14 +146,14 @@ void LeaveCritical()
 std::string LocksHeld()
 {
  std::string result;
- BOOST_FOREACH (const PAIRTYPE(void*, CLockLocation) & i, *lockstack)
+ for (const PAIRTYPE(void*, CLockLocation) & i : *lockstack)
  result += i.second.ToString() + std::string("\n");
  return result;
 }
 
 void AssertLockHeldInternal(const char* pszName, const char* pszFile, int nLine, void* cs)
 {
- BOOST_FOREACH (const PAIRTYPE(void*, CLockLocation) & i, *lockstack)
+ for (const PAIRTYPE(void*, CLockLocation) & i : *lockstack)
  if (i.first == cs)
  return;
  fprintf(stderr, "Assertion failed: lock %s not held in %s:%i; locks held:\n%s", pszName, pszFile, nLine, LocksHeld().c_str());
@@ -181,3 +183,160 @@ void DeleteLock(void* cs)
 }
 
 #endif /* DEBUG_LOCKORDER */
+
+
+#ifdef DEBUG_LOCKBENCHMARK
+
+// using namespace to avoid name conflicting
+namespace benchmark { namespace {
+
+struct LockItem
+{
+ const void * lockInstance;
+ const void * mutexInstance;
+ std::string name;
+ std::string fileName;
+ int lineNumber;
+ bool isTry;
+ int64_t startTime; // milliseconds
+};
+
+using LockItemPtr = std::shared_ptr<LockItem>;
+
+using LockInstanceMap = std::map<const void *, LockItemPtr>;
+using LockItemStack = std::vector<LockItemPtr>;
+using MutextInstanceMap = std::map<const void *, LockItemStack>;
+
+LockInstanceMap lockInstanceMap;
+MutextInstanceMap mutexInstanceMap;
+std::mutex lockMutex;
+
+// The intervals are in milliseconds, <= 0 disables the detect of the slow.
+constexpr int64_t slowLockInterval = 1000 * 1;
+constexpr int64_t slowReleaseInterval = 1000 * 10;
+
+void removeLockItem(const void * lockInstance)
+{
+ std::lock_guard<std::mutex> guard(lockMutex);
+
+ auto lockIt = lockInstanceMap.find(lockInstance);
+ if(lockIt == lockInstanceMap.end()) {
+ return;
+ }
+
+ auto mutexIt = mutexInstanceMap.find(lockIt->second->mutexInstance);
+ if(mutexIt != mutexInstanceMap.end() && ! mutexIt->second.empty()) {
+ auto it = std::find_if(mutexIt->second.begin(), mutexIt->second.end(), [lockInstance](const LockItemPtr & item) {
+ return item->lockInstance == lockInstance;
+ });
+ if(it != mutexIt->second.end()) {
+ mutexIt->second.erase(it);
+ }
+ }
+
+ lockInstanceMap.erase(lockIt);
+}
+
+
+} }
+
+void BeforeAcquireLock(const void * lockInstance, const void * mutexInstance, const char* pszName, const char* pszFile, int nLine, bool fTry)
+{
+ const auto lockItem = benchmark::LockItemPtr(new benchmark::LockItem {
+ lockInstance,
+ mutexInstance,
+ pszName,
+ pszFile,
+ nLine,
+ fTry,
+ 0
+ });
+
+ std::lock_guard<std::mutex> guard(benchmark::lockMutex);
+ benchmark::lockInstanceMap[lockInstance] = lockItem;
+ benchmark::mutexInstanceMap[mutexInstance].push_back(lockItem);
+ lockItem->startTime = GetTimeMillis();
+}
+
+void AfterAcquireLock(const void * lockInstance, const bool ownsLock)
+{
+ if(! ownsLock) {
+ benchmark::removeLockItem(lockInstance);
+ return;
+ }
+
+ if(benchmark::slowLockInterval > 0) {
+ const auto currentTime = GetTimeMillis();
+
+ std::lock_guard<std::mutex> guard(benchmark::lockMutex);
+ auto lockIt = benchmark::lockInstanceMap.find(lockInstance);
+ if(lockIt != benchmark::lockInstanceMap.end()) {
+ if(currentTime - lockIt->second->startTime >= benchmark::slowLockInterval) {
+ auto mutexIt = benchmark::mutexInstanceMap.find(lockIt->second->mutexInstance);
+ if(mutexIt != benchmark::mutexInstanceMap.end()) {
+ const auto mutexCount = mutexIt->second.size();
+ switch(mutexCount) {
+ case 0:
+ LogPrintf("Lock benchmark: slow lock is detected, but the lock is not found in the stack.\n");
+ break;
+
+ case 1:
+ LogPrintf("Lock benchmark: slow lock is detected, but there is only 1 lock.\n");
+ break;
+
+ default:
+ if(mutexIt->second.back()->lockInstance != lockInstance) {
+ LogPrintf("Lock benchmark: error detect, the latest locked instance doesn't match the instance being locked.\n");
+ }
+ else {
+ LogPrintf(
+ "Lock benchmark: slow lock is detected. The slow is at line %d in file %s\n"
+ "The current lock is at line %d in file %s. Used seconds: %ld \n",
+ mutexIt->second[mutexCount - 2]->lineNumber, mutexIt->second[mutexCount - 2]->fileName.c_str(),
+ mutexIt->second[mutexCount - 1]->lineNumber, mutexIt->second[mutexCount - 1]->fileName.c_str(),
+ (long)((currentTime - lockIt->second->startTime) / 1000)
+ );
+ }
+ break;
+ }
+ }
+ else {
+ }
+ }
+ }
+ }
+}
+
+void AfterReleaseLock(const void * lockInstance, const bool ownsLock)
+{
+ if(ownsLock && benchmark::slowReleaseInterval > 0) {
+ const auto currentTime = GetTimeMillis();
+
+ std::lock_guard<std::mutex> guard(benchmark::lockMutex);
+ auto lockIt = benchmark::lockInstanceMap.find(lockInstance);
+ if(lockIt != benchmark::lockInstanceMap.end()) {
+ if(currentTime - lockIt->second->startTime >= benchmark::slowReleaseInterval) {
+ auto mutexIt = benchmark::mutexInstanceMap.find(lockIt->second->mutexInstance);
+ if(mutexIt != benchmark::mutexInstanceMap.end() && ! mutexIt->second.empty()) {
+ if(mutexIt->second.back()->lockInstance != lockInstance) {
+ LogPrintf("Lock benchmark: error detect, the latest locked instance doesn't match the instance being removed.\n");
+ }
+ else {
+ LogPrintf(
+ "Lock benchmark: slow release is detected. The current lock is at line %d in file %s. Used seconds: %ld \n",
+ mutexIt->second.back()->lineNumber, mutexIt->second.back()->fileName.c_str(),
+ (long)((currentTime - lockIt->second->startTime) / 1000)
+ );
+ }
+ }
+ else {
+ }
+ }
+ }
+ }
+
+ benchmark::removeLockItem(lockInstance);
+}
+
+
+#endif /* DEBUG_LOCKBENCHMARK */

src/sync.h

@@ -108,6 +108,18 @@ typedef boost::condition_variable CConditionVariable;
 void PrintLockContention(const char* pszName, const char* pszFile, int nLine);
 #endif
 
+//#define DEBUG_LOCKBENCHMARK
+
+#ifdef DEBUG_LOCKBENCHMARK
+void BeforeAcquireLock(const void * lockInstance, const void * mutexInstance, const char* pszName, const char* pszFile, int nLine, bool fTry);
+void AfterAcquireLock(const void * lockInstance, const bool ownsLock);
+void AfterReleaseLock(const void * lockInstance, const bool ownsLock);
+#else
+#define BeforeAcquireLock(lockInstance, mutexInstance, pszName, pszFile, nLine, fTry)
+#define AfterAcquireLock(lockInstance, ownsLock)
+#define AfterReleaseLock(lockInstance, ownsLock)
+#endif
+
 /** Wrapper around boost::unique_lock<CCriticalSection> */
 template <typename Mutex>
 class SCOPED_LOCKABLE CMutexLock
@@ -140,27 +152,37 @@ class SCOPED_LOCKABLE CMutexLock
 public:
  CMutexLock(Mutex& mutexIn, const char* pszName, const char* pszFile, int nLine, bool fTry = false) EXCLUSIVE_LOCK_FUNCTION(mutexIn) : lock(mutexIn, boost::defer_lock)
  {
+ BeforeAcquireLock(this, &mutexIn, pszName, pszFile, nLine, fTry);
+
  if (fTry)
  TryEnter(pszName, pszFile, nLine);
  else
  Enter(pszName, pszFile, nLine);
+
+ AfterAcquireLock(this, lock.owns_lock());
  }
 
  CMutexLock(Mutex* pmutexIn, const char* pszName, const char* pszFile, int nLine, bool fTry = false) EXCLUSIVE_LOCK_FUNCTION(pmutexIn)
  {
  if (!pmutexIn) return;
 
+ BeforeAcquireLock(this, pmutexIn, pszName, pszFile, nLine, fTry);
+
  lock = boost::unique_lock<Mutex>(*pmutexIn, boost::defer_lock);
  if (fTry)
  TryEnter(pszName, pszFile, nLine);
  else
  Enter(pszName, pszFile, nLine);
+
+ AfterAcquireLock(this, lock.owns_lock());
  }
 
  ~CMutexLock() UNLOCK_FUNCTION()
  {
  if (lock.owns_lock())
  LeaveCritical();
+
+ AfterReleaseLock(this, lock.owns_lock());
  }
 
  operator bool()
@@ -289,4 +311,4 @@ class CSemaphoreGrant
  }
 };
 
-#endif // BITCOIN_SYNC_H
+#endif // BITCOIN_SYNC_H