-
Notifications
You must be signed in to change notification settings - Fork 37.7k
Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive #24770
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.
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
Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive #24770
Conversation
5fdb3a9
to
4394733
Compare
Added the developer notes commit and headers changes per IRC feedback. |
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers. ConflictsReviewers, this pull request conflicts with the following ones:
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 4394733 |
Copied over the PR description. |
Github-Pull: bitcoin#24770 Rebased-From: 39a34b6
Github-Pull: bitcoin#24770 Rebassedd-From: 4394733
Backported in #24807. |
e3e4be9 RPC: Switch getblockfrompeer back to standard param name blockhash (Luke Dashjr) 69cc83d Add DEBUG_LOCKCONTENTION documentation to the developer notes (Jon Atack) 6374e24 Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive (Jon Atack) Pull request description: Backports: * #24770 * #24806 ACKs for top commit: laanwj: Commit list and code review ACK e3e4be9 jonatack: Code review and commit metadata ACK e3e4be9 Tree-SHA512: eff2b506379a9396b12b42ed2858e3eb9403a55950d6dec0b5dcc95c4c2998cddf9e0ec88af2f8ac5a7bece4d4537acede1c75f59bbc6616bee273384f87f6b0
Summary: This diff: - adds a LOCK logging category if DEBUG_LOCKCONTENTION is defined at compilation. - adds a timing macro in microseconds, `LOG_TIME_MICROS_WITH_CATEGORY` - updates `BCLog::LogMsg()` to omit irrelevant decimals for microseconds and skip unneeded code and math. - improves the lock contention logging, drops the all-caps, and displays the duration in microseconds - makes unexpected time type in `BCLog::LogMsg()` a compile-time error - add a paragraph of documentation to developer-notes.md Lock contention logging in checkqueue_tests is disabled, as some of these tests are designed to be heavily contested to trigger race conditions or other issues. This created very large log files when run with DEBUG_LOCKCONTENTION defined. This is a backport of [[bitcoin/bitcoin#22736 | core#22736]], [[bitcoin/bitcoin#22904 | core#22904]], [[bitcoin/bitcoin#23223 | core#23223]] and [[bitcoin/bitcoin#24770 | core#24770]] The first pull request implements the lock category, the other pull requests are important follow-ups (mixed with minor refactorings) fixing various regressions (bugs and suspected performance issues). Co-authored-by: Hennadii Stepanov <32963518+hebasto@users.noreply.github.com> Co-authored-by: practicalswift <practicalswift@users.noreply.github.com> Co-authored-by: Martin Ankerl <martin.ankerl@gmail.com> Test Plan: `ninja all check-all` Follow the instructions in the new documentation and check that the logging works: ``` cmake .. -GNinja -DCMAKE_CXX_FLAGS="-DDEBUG_LOCKCONTENTION" ninja src/bitcoind -h | grep -A8 "debug=<category>" src/bitcoind -debug=lock ``` Reviewers: #bitcoin_abc, sdulfari Reviewed By: #bitcoin_abc, sdulfari Subscribers: sdulfari Differential Revision: https://reviews.bitcoinabc.org/D12049
This is a more minimal, no-frills version of #24734 for backport. The other fixes and improvements in that pull can be done after.
Copy of the PR 24734 description:
PRs #22736, #22904 and #23223 changed lock contention logging from a
DEBUG_LOCKCONTENTION
compile-time preprocessor directive to a runtimelock
log category and improved the logging output. This changed the locking from usinglock()
totry_lock()
:void Mutex::UniqueLock::lock()
acquires the mutex and blocks until it gains access to itbool Mutex::UniqueLock::try_lock()
doesn't block but instead immediately returns whether it acquired the mutex; it may be used bylock()
internally as part of the deadlock-avoidance algorithmIn theory the cost of
try_lock
might be essentially the same relative tolock
. The test-and-set logic of these calls is purported to be ~ 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, and (particularly) lock contentions. See the discussion around #22736 (comment) and after with respect to performance/cost aspects. However, there are reasonable concerns (see here and here) thatBase::try_lock()
may be potentially costly or risky compared toBase::lock()
in this very frequently called code.One alternative to keep the run-time lock logging would be to gate the
try_lock
call behind the logging conditional, for example as proposed in ccd73de and ACKed here. However, this would add the cost ofif (LogAcceptCategory(BCLog::LOCK))
to the hotspot, instead of replacinglock
withtry_lock
, for the most frequent happy path (non-contention).It turns out we can keep the advantages of the runtime lock contention logging (the ability to turn it on/off at runtime) while out of prudence putting the
try_lock()
call andlock
logging category behind aDEBUG_LOCKCONTENTION
compile-time preprocessor directive, and also still retain the lock logging enhancements of the mentioned PRs, as suggested in #24734 (comment) by W. J. van der Laan, in #22736 (comment), and in the linked IRC discussion.Proposed here and for backport to v23.