Moving this out of draft now, ready for review.

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

• #20487 (Add syscall sandboxing using seccomp-bpf (Linux secure computing mode) by practicalswift)
• #16365 (Log RPC parameters (arguments) if -debug=rpcparams by LarryRuane)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

Code review ACK ccd73de

Concept ACK

Nice idea. I've used something similar in my local tree when analysing lock contention locally.

Non-blocking suggestions:

• In my version I printed the duration too to make it clear from the log entry if the lock contention was significant or not. Perhaps worth adding here too?
• In addition to __FILE__ and __LINE__ it would be nice to have __FUNCTION__ printed as part of the log message too.

To rule out any accidental performance regressions: would it be possible to benchmark before vs after this PR (with and without -debug=lock) in some intelligent way?

In my version I printed the duration too to make it clear from the log entry if the lock contention was significant or not. Perhaps worth adding here too?

In addition to __FILE__ and __LINE__ it would be nice to have __FUNCTION__ printed as part of the log message too.

I think I'd need your help (propose a commit to pull in?) or you could do it as a follow-up.

To rule out any accidental performance regressions: would it be possible to benchmark before vs after this PR (with and without -debug=lock) in some intelligent way?

I'll look. Without -debug=lock it should be the same, and I'm not sure anyone besides developers would use the lock logging; it's still fairly verbose. In the worst case I suppose we could add a warning in the RPC logging help.

@laanwj: following up on our IRC convo in #bitcoin-core-builds, as a test just pushed a version with the HAVE_THREAD_LOCAL conditional compilation directives removed to see what happens...

To-do:

• add a smoke test with -debug=lock
• do some invocation frequency checks and research
• try benchmarking Mutex::UniqueLock lock() versus try_lock() and the overhead of LogAcceptCategory(BCLog::LOCK), which evaluates to m_categories.load(std::memory_order_relaxed) & category) != 0

add a smoke test with -debug=lock

Shouldn't this be enabled in the functional test already by default?

Shouldn't this be enabled in the functional test already by default?

You're right, TIL. I was thinking of adding something like this assertion but probably not worth it or reliable enough:

        with node.assert_debug_log(expected_msgs=["Lock contention: cs_main"]):
            node.generate(COINBASE_MATURITY)

Concept ACK

Observations

• void Mutex::UniqueLock::lock() acquires the mutex and blocks until it gains access to it

• bool Mutex::UniqueLock::try_lock() doesn't block but instead immediately returns whether it acquired the mutex; it may be used by lock() internally as part of the deadlock-avoidance algorithm

• IIUC the test-and-set logic of these calls is ~constant time, optimised and light/quick if used carefully (i.e. no mutex convoying), compared to system calls, memory/cache coherency and fences, wait queues, lock contentions

• added the following patch and tested a regular, non-debug clang 13 build of bitcoind synced on mainnet

        if (LogAcceptCategory(BCLog::LOCK)) {
             if (!Base::try_lock()) {
                 LogPrintf("Lock contention: %s, %s:%d\n", pszName, pszFile, nLine);
                 Base::lock();
+            } else {
+                LogPrintf("No lock contention\n");
             }

• with this, I'm seeing src/sync.h::UniqueLock::Enter() invoked 2500-5000 times per minute, sampled roughly an hour after startup

• of those, try_lock() returns true 99.26% to 99.91% of the time. In the true case the lock logging should have essentially the same performance as when the lock logging is off

• thus 0.09% to 0.74% of the time try_lock() returns false, the contention is logged and lock() is then called, in which case the additional overhead compared to lock() alone, if any (~depending on how long the mutex was blocked), is of trying the lock and initially returning false

• Overall, lock contention seems to be relatively infrequent as a percentage of locks. I'm seeing a few per minute. The most common one I see is cs_vNodes in net.cpp::2242/2277::ThreadMessageHandler.

Edit: recalculated the numbers and updated.

Some resources:

• https://preshing.com/20111118/locks-arent-slow-lock-contention-is/
• https://travisdowns.github.io/blog/2020/07/06/concurrency-costs.html
• https://probablydance.com/2019/12/30/measuring-mutexes-spinlocks-and-how-bad-the-linux-scheduler-really-is/
• https://stackoverflow.com/questions/3652056/how-efficient-is-locking-an-unlocked-mutex-what-is-the-cost-of-a-mutex

Concept ACK.

* benchmarking ... the overhead of `LogAcceptCategory(BCLog::LOCK)`, which evaluates to `m_categories.load(std::memory_order_relaxed) & category) != 0`

I think the benchmarking results could depend on a platform.

Could we sacrifice the ability to turn "lock" debugging on/off at runtime, and use just a const?

Could we sacrifice the ability to turn "lock" debugging on/off at runtime, and use just a const?

I could be wrong, and this goes way beyond my competence, but readings suggest that these options are low-level, fast, and near constant time compared to system calls, memory/cache coherency and fences, wait queues and (particularly) lock contentions. (Would a difference be apparent in, say, https://bitcoinperf.com? I don't know, but if this helps us reduce contentions, that may be a win. @jamesob, @0xB10C, @martinus thoughts?)

Could we sacrifice the ability to turn "lock" debugging on/off at runtime, and use just a const?

I could be wrong, and this goes way beyond my competence, but readings suggest that these options are low-level, fast, and near constant time compared to system calls, memory/cache coherency and fences, wait queues and (particularly) lock contentions. Would a difference be apparent in, say, https://bitcoinperf.com? I don't know, but if this helps us reduce contentions, that may be a win.

And m_categories.load(std::memory_order_relaxed) could cause cache lines switching, no?

And m_categories.load(std::memory_order_relaxed) could cause cache lines switching, no?

Alternative version:

    void Enter(const char* pszName, const char* pszFile, int nLine)
    {
        EnterCritical(pszName, pszFile, nLine, Base::mutex());
        if (Base::try_lock()) return;
        Base::lock();
        LogPrint(BCLog::LOCK, "Lock contention: %s, %s:%d\n", pszName, pszFile, nLine);
    }

And m_categories.load(std::memory_order_relaxed) could cause cache lines switching, no?

Alternative version:

    void Enter(const char* pszName, const char* pszFile, int nLine)
    {
        EnterCritical(pszName, pszFile, nLine, Base::mutex());
        if (Base::try_lock()) return;
        Base::lock();
        LogPrint(BCLog::LOCK, "Lock contention: %s, %s:%d\n", pszName, pszFile, nLine);
    }

Nice!

Maybe put logging before the blocking call Base::lock(); as it is now? The LogPrint call takes some time, and it could increase probability of releasing a mutex by another thread before the Base::lock() call.

And m_categories.load(std::memory_order_relaxed) could cause cache lines switching, no?

I don't know.

Maybe put logging before the blocking call Base::lock(); as it is now? The LogPrint call takes some time, and it could increase probability of releasing a mutex by another thread before the Base::lock() call.

Seems like a good idea--done.

And m_categories.load(std::memory_order_relaxed) could cause cache lines switching, no?

yes, the only guarantee with memory_order_relaxed is that the operation itself is atomic, but other operations are allowed to be shuffled that by the compiler. I personally try to avoid using any of the memory order stuff. It's too easy to get wrong.

By the way, I think that in that patch:

        if (LogAcceptCategory(BCLog::LOCK)) {
             if (!Base::try_lock()) {
                 LogPrintf("Lock contention: %s, %s:%d\n", pszName, pszFile, nLine);
                 Base::lock();
+            } else {
+                LogPrintf("No lock contention\n");
             }

If Base::try_lock() fails strictly speaking that does not necessarily mean that there's a lock contention. std::mutex's try_lock() can also spuriously fail even when no other thread is currently holding a lock: https://en.cppreference.com/w/cpp/thread/mutex/try_lock I have no idea though how often that can happen.

Thanks for the ideas and feedback. Updates:

• added a timing macro in microseconds, LOG_TIME_MICROS_WITH_CATEGORY
• improved BCLog::LogMsg() to omit irrelevant decimals for microseconds and skip unnecessary code/math
• added time duration in microseconds to the lock contention logging

If Base::try_lock() fails strictly speaking that does not necessarily mean that there's a lock contention. std::mutex's try_lock() can also spuriously fail even when no other thread is currently holding a lock: en.cppreference.com/w/cpp/thread/mutex/try_lock. I have no idea though how often that can happen.

Good point. I read that doc previously and admit to discounting the spurious failures a little, as we don't know the frequency. It seems to be an additional reason to log the contention duration.

Thanks for testing! For me, there seems to be a higher frequency of contention and occuring in more places on mainnet than on signet, presumably as the scale/numbers are larger. Also, a big difference in contention durations between a regular build and a debug build, which makes sense.