Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: logging time inside lock to help debugging lock contentions #6477

Draft
wants to merge 1 commit into
base: develop
Choose a base branch
from
+22 −1
Draft

feat: logging time inside lock to help debugging lock contentions #6477

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 22 additions & 1 deletion src/sync.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -161,18 +161,31 @@ template <typename Mutex, typename Base = typename Mutex::UniqueLock>
class SCOPED_LOCKABLE UniqueLock : public Base
{
private:
#ifdef DEBUG_LOCKCONTENTION
std::string m_lock_log_time_prefix;
std::chrono::microseconds m_started_time{};
#endif
void Enter(const char* pszName, const char* pszFile, int nLine)
{
EnterCritical(pszName, pszFile, nLine, Base::mutex());
#ifdef DEBUG_LOCKCONTENTION
m_lock_log_time_prefix = strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine);
m_started_time = GetTime<std::chrono::microseconds>();
if (Base::try_lock()) return;
LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK);
LOG_TIME_MICROS_WITH_CATEGORY(m_lock_log_time_prefix, BCLog::LOCK);
#endif
Base::lock();
#ifdef DEBUG_LOCKCONTENTION
m_started_time = GetTime<std::chrono::microseconds>();
#endif
}

bool TryEnter(const char* pszName, const char* pszFile, int nLine)
{
#ifdef DEBUG_LOCKCONTENTION
m_lock_log_time_prefix = strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine);
m_started_time = GetTime<std::chrono::microseconds>();
#endif
EnterCritical(pszName, pszFile, nLine, Base::mutex(), true);
if (Base::try_lock()) {
return true;
Expand Down Expand Up @@ -203,8 +216,16 @@ class SCOPED_LOCKABLE UniqueLock : public Base

~UniqueLock() UNLOCK_FUNCTION()
{
#ifdef DEBUG_LOCKCONTENTION
const auto diff_time = (GetTime<std::chrono::microseconds>() - m_started_time);
#endif
if (Base::owns_lock())
LeaveCritical();
#ifdef DEBUG_LOCKCONTENTION
if (diff_time.count() > 100 && m_started_time.count() > 0) {
LogPrint(BCLog::LOCK, "%s inside %iμs\n", m_lock_log_time_prefix, diff_time.count());
}
#endif
}

operator bool()
Expand Down
Loading