sync, log: inline lock contention logging macro to fix duration, improve BCLog::LogMsg() #22904

Follow-up to #22736.

The first commit addresses the issue identified and reported by Martin Ankerl in #22736 (review) to fix the lock contention duration reporting.

The next three commits make improvements to the timer code in BCLog::LogMsg() and add util/types.h with an ALWAYS_FALSE template, that springboard from #22736 (review) by Marco Falke.

ACK 498b323425d960274c40472a6a847afc1982201d, code review & tested. Found ~two~ one potential improvements.

ACK f530202353a4f8bb444966559aa15681ab3cebc6

Thanks for catching the timing flaw @martinus (and also sorry to all for not noticing it in my review of #22736)! Indeed the numbers look way more plausible now -- on a signet non-debug build (src/bitcoind -signet -debug=lock), lock contention times are now in the range of hundreds to thousands micro-seconds on my machine.

re-ACK f530202353a4f8bb444966559aa15681ab3cebc6. I ran a fully synced node for about a day. My node was mostly idle though so not much was going on. I wrote a little script to parse the debug.log and summarize the output to see if anything interesting was going on, here is the result:

Almost all of the contention in cs_main, net_processing.cpp:4051 happened at the startup of the node.

I expect lock contention to be more pronounced in the GUI (or when there is an active RPC poll)

This seems to introduce a busy loop when running the checkqueue tests for me:

$ make -j5 check &
$ tail -f test/*.log
2021-09-29T18:35:19.275154Z [test] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:168 started
2021-09-29T18:35:19.275213Z [scriptch.2] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:77 completed (306μs)
2021-09-29T18:35:19.275244Z [scriptch.0] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:77 completed (222μs)
2021-09-29T18:35:19.275275Z [scriptch.1] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:77 completed (127μs)
2021-09-29T18:35:19.275293Z [scriptch.0] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:77 started
2021-09-29T18:35:19.275319Z [scriptch.2] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:77 started
2021-09-29T18:35:19.275347Z [test] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:168 completed (109μs)
2021-09-29T18:35:19.275366Z [scriptch.1] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:77 started
2021-09-29T18:35:19.275387Z [scriptch.0] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:77 completed (62μs)
2021-09-29T18:35:19.275404Z [test] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:168 started
2021-09-29T18:35:19.275425Z [scriptch.2] [logging/timer.h:51] [Log] Enter: lock contention m_mutex, ./checkqueue.h:77 completed (69μs)

It does finish eventually with a >1GB log file:

$ ls -l test/*.log --sort=s -h -r | tail -n2
-rw-r--r-- 1 aj aj   20M Sep 30 04:30 test/validationinterface_tests.cpp.log
-rw-r--r-- 1 aj aj  1.3G Sep 30 04:35 test/checkqueue_tests.cpp.log
$ cat test/checkqueue_tests.cpp.log | grep 'Enter: lock contention' | cut -d\  -f8,9 | sort | uniq -c
      2 instance->m_cs_callbacks_pending, scheduler.cpp:168
      6 m_cs_callbacks_pending, scheduler.cpp:183
2599034 m_mutex, ./checkqueue.h:168
7399288 m_mutex, ./checkqueue.h:77
 161286 m, test/checkqueue_tests.cpp:66
      2 newTaskMutex, scheduler.cpp:76

I was thinking that the fact that logging takes its own lock might have been a problem (leading to contention on that lock? or just taking more time leading to more contention on other locks?) but it seems like there really is that many instances of contention for the checkqueue mutex -- reducing the logging by a factor of 1000 only reduces the logging proportionally. But gigabyte log files and many minutes to run a simple test doesn't seem great...

I suspect you have a bunch of spurious failures. Regardless of whether that's the case or not, relying on unspecified behavior (spurious mutex failures) from libc/stdlib is a bad idea, especially if it leads to possible remote triggers (3 of the 4 most contended locks are in net_processing).

IMO this is far too dangerous to have turned on by default.

Following up: if this were to be reverted, here is an alternative solution to the header macro problem for lock contention and lock ordering. As a caveat, I haven't benchmarked to see the impact of the lost inlining.

I suspect you have a bunch of spurious failures.

I think the contentions are real and not spurious. For me the file checkqueue_tests.cpp.log is by far the largest, and it looks like most the contentions come from the test test_CheckQueue_Correct_Random. When I run

./src/test/test_bitcoin --run_test=checkqueue_tests/test_CheckQueue_Correct_Random -- DEBUG_LOG_OUT >out.txt

I get a 1.1GB log file. Parsing this with with this script I get this output:

the first 4 threads have almost the same number of contentions, so it seems to me that they are blocking each other. Especially the 3 scriptch threads have practically the same number of contentions. I suspect that these 3 threads are always started simultaneously but only one of them gets the lock, blocking the other 2.

Clearly this needs following up on. I've opened an issue, #23167, for further discussion / so this doesn't get lost.

I think the contentions are real and not spurious.

Good call @martinus. Testing this further, it was not only the case on every run but also pre-existing with DEBUG_LOCKCONTENTION defined, as some of these tests are heavily contested by design. Logging contentions by default in the tests served to bring the issue to light, which was the goal.

Opened #23223 to resolve.