Page MenuHomePhabricator

log, sync: add LOCK logging category, apply it to lock contention
ClosedPublic

Authored by PiRK on Sep 23 2022, 16:32.

Details

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 core#22736, core#22904, core#23223 and 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

Event Timeline

PiRK requested review of this revision.Sep 23 2022, 16:32
sdulfari requested changes to this revision.Sep 23 2022, 21:35
sdulfari added a subscriber: sdulfari.

Which change was from https://github.com/bitcoin/bitcoin/pull/24470 ? I could not find it.

doc/developer-notes.md
282–283

DEBUG_LOCKCONTENTION is just a logging category and not strictly related to RPC.

src/net.h
40

Are either of these includes necessary?

src/sync.h
141

Is the #ifdef intended to remain?

test/functional/rpc_misc.py
62

Why remove this check?

This revision now requires changes to proceed.Sep 23 2022, 21:35

Which change was from https://github.com/bitcoin/bitcoin/pull/24470 ? I could not find it.

I made a mistake in the PR number. I fixed it in the description (https://github.com/bitcoin/bitcoin/pull/24770 )

doc/developer-notes.md
282–283

OK.

src/net.h
40

I'm not sure why these were added in this stack, but they are correct: there are 3 std::list in this file, and it uses BCLog from looging.h.

It probably worked until now only because of indirect inclusion via other libraries.

For reference: https://github.com/bitcoin/bitcoin/pull/24770#issuecomment-1088557064

src/sync.h
141

yes. Thats the PR that previously had a typo in the the description: https://github.com/bitcoin/bitcoin/pull/24770

The rationale for keeping the DEBUG_LOCKCONTENTION flag is

there are reasonable concerns (see here and here) that Base::try_lock() may be potentially costly or risky compared to Base::lock() in this very frequently called code.

test/functional/rpc_misc.py
62

Now the number of logging categories depends on a compile time flag. I briefly considered looking for a way to adjust the test (similar to how some tests are skipped when the wallet is not compiled), but the test does not seem very valuable and will have to be maintained every time a category is added. I does not seem to be worth the effort.

Thanks for fixing the last backport link. I've reviewed the remainder and they look ok.

test/functional/rpc_misc.py
62

Categories are not added often, so this is not very concerning. What about changing this to assert_greater_or_equal? That way we keep the check that a minimum number of categories exist, but toggling additional categories on will not break the test.

restore functional test for number of logging categories using assert_greater_than_or_equal.

This revision is now accepted and ready to land.Sep 27 2022, 17:38