From be2f913d5fc742b8f96df9e3e9739a9c80859d15 Mon Sep 17 00:00:00 2001 From: wqking Date: Wed, 11 Dec 2019 21:41:19 +0800 Subject: [PATCH] Added benchmark in mutex lock --- src/sync.cpp | 169 +++++++++++++++++++++++++++++++++++++++++++++++++-- src/sync.h | 24 +++++++- 2 files changed, 187 insertions(+), 6 deletions(-) diff --git a/src/sync.cpp b/src/sync.cpp index f2d75404f0b06..8d8237ef5bf04 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -10,6 +10,8 @@ #include +#include + #include #include @@ -80,7 +82,7 @@ static void potential_deadlock_detected(const std::pair& 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& 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; + +using LockInstanceMap = std::map; +using LockItemStack = std::vector; +using MutextInstanceMap = std::map; + +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 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 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 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 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 */ diff --git a/src/sync.h b/src/sync.h index 4838dfe9d913e..6568db35c377e 100644 --- a/src/sync.h +++ b/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 */ template 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(*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 \ No newline at end of file +#endif // BITCOIN_SYNC_H