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.

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

Disable lock contention logging in checkqueue_tests #23223

Conversation

jonatack
Copy link
Member

@jonatack jonatack commented Oct 7, 2021

This patch disables lock contention logging in the checkqueue_tests 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 (up to v22) or with lock logging enabled by default in current master.

Examples running the following command:

$ ./src/test/test_bitcoin -t checkqueue_tests/test_CheckQueue_Correct_Random -- DEBUG_LOG_OUT > testlog.txt

-rw-r--r--   87042178 Oct  8 12:41 testlog-with-DEBUG_LOCKCONTENTION-at-v22-run1.txt
-rw-r--r--   73879896 Oct  8 12:42 testlog-with-DEBUG_LOCKCONTENTION-at-v22-run2.txt
-rw-r--r--   65150518 Oct  8 12:51 testlog-with-DEBUG_LOCKCONTENTION-at-bb9f76a-run1.txt
-rw-r--r--   65774554 Oct  8 12:52 testlog-with-DEBUG_LOCKCONTENTION-at-bb9f76a-run2.txt
-rw-r--r--   73493309 Oct  8 13:00 testlog-current-master-at-991753e-run1.txt
-rw-r--r--   65616977 Oct  8 13:01 testlog-current-master-at-991753e-run2.txt
-rw-r--r--       5093 Oct  8 13:04 testlog-with-this-commit-run1.txt
-rw-r--r--       5093 Oct  8 13:05 testlog-with-this-commit-run2.txt

Resolves #23167.

@DrahtBot DrahtBot added the Tests label Oct 7, 2021
@jonatack
Copy link
Member Author

jonatack commented Oct 7, 2021

This is the resulting log file with this pull. It is the same modulo no contention logging.

log

Running 1 test case...
2021-10-07T21:34:20Z Seed: Setting random seed for current tests to RANDOM_CTX_SEED=af952f85f519906580f814500cbea272d0337c9f6a57e4565b1449a7191939cb
2021-10-07T21:34:20.979238Z [test] [init/common.cpp:165] [LogPackageVersion] Bitcoin Core version v22.99.0-af1b6dd28c73 (debug build)
2021-10-07T21:34:20.979640Z [test] [init.cpp:904] [AppInitParameterInteraction] Assuming ancestors of block 00000000000000000008a89e854d57e5667df88f1cdef6fde2fbca1de5b639ad have valid signatures.
2021-10-07T21:34:20.979675Z [test] [init.cpp:917] [AppInitParameterInteraction] Setting nMinimumChainWork=00000000000000000000000000000000000000001fa4663bbbe19f82de910280
2021-10-07T21:34:21.004580Z [test] [script/sigcache.cpp:102] [InitSignatureCache] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2021-10-07T21:34:21.024300Z [test] [validation.cpp:1275] [InitScriptExecutionCache] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2021-10-07T21:34:21.029896Z [test] [policy/fees.cpp:530] [CBlockPolicyEstimator] Failed to read fee estimates from /tmp/test_common_Bitcoin Core/3f96173145376177754944c55c5bab576064058986990ff10474f63c96aa86a1/fee_estimates.dat. Continue anyway.
2021-10-07T21:34:21.030388Z [test] [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully
2021-10-07T21:34:21.030464Z [test] [dbwrapper.cpp:166] [CDBWrapper] Using obfuscation key for /tmp/test_common_Bitcoin Core/3f96173145376177754944c55c5bab576064058986990ff10474f63c96aa86a1/blocks/index: 0000000000000000
2021-10-07T21:34:21.043439Z [scheduler] [util/thread.cpp:17] [TraceThread] scheduler thread start
2021-10-07T21:34:21.053557Z [test] [validation.cpp:4700] [InitializeChainstate] Switching active chainstate to Chainstate [ibd] @ height -1 (null)
2021-10-07T21:34:21.053897Z [test] [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully
2021-10-07T21:34:21.054055Z [test] [dbwrapper.cpp:163] [CDBWrapper] Wrote new obfuscate key for /tmp/test_common_Bitcoin Core/3f96173145376177754944c55c5bab576064058986990ff10474f63c96aa86a1/chainstate: 8ccff399f33daf0b
2021-10-07T21:34:21.054088Z [test] [dbwrapper.cpp:166] [CDBWrapper] Using obfuscation key for /tmp/test_common_Bitcoin Core/3f96173145376177754944c55c5bab576064058986990ff10474f63c96aa86a1/chainstate: 8ccff399f33daf0b
2021-10-07T21:34:21.054330Z [test] [flatfile.cpp:69] [Allocate] Pre-allocating up to position 0x1000000 in blk00000.dat
2021-10-07T21:34:21.055063Z [test] [validation.cpp:2295] [ConnectTip]   - Load block from disk: 0.16ms [0.00s]
2021-10-07T21:34:21.055218Z [test] [validationinterface.cpp:249] [BlockChecked] BlockChecked: block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f state=Valid
2021-10-07T21:34:21.055278Z [test] [validation.cpp:2307] [ConnectTip]   - Connect total: 0.24ms [0.00s (0.24ms/blk)]
2021-10-07T21:34:21.055306Z [test] [validation.cpp:2312] [ConnectTip]   - Flush: 0.04ms [0.00s (0.04ms/blk)]
2021-10-07T21:34:21.055426Z [test] [validation.cpp:2318] [ConnectTip]   - Writing chainstate: 0.11ms [0.00s (0.11ms/blk)]
2021-10-07T21:34:21.055806Z [test] [validation.cpp:2112] [UpdateTipLog] UpdateTip: new best=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f height=0 version=0x00000001 log2_work=32.000022 tx=1 date='2009-01-03T18:15:05Z' progress=0.000000 cache=0.0MiB(0txo)
2021-10-07T21:34:21.055872Z [test] [validation.cpp:2329] [ConnectTip]   - Connect postprocess: 0.45ms [0.00s (0.45ms/blk)]
2021-10-07T21:34:21.055900Z [test] [validation.cpp:2330] [ConnectTip] - Connect block: 0.99ms [0.00s (0.99ms/blk)]
2021-10-07T21:34:21.055966Z [test] [txmempool.cpp:691] [check] Checking mempool with 0 transactions and 0 inputs
2021-10-07T21:34:21.056115Z [test] [validationinterface.cpp:226] [BlockConnected] Enqueuing BlockConnected: block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f block height=0
2021-10-07T21:34:21.056282Z [test] [validationinterface.cpp:199] [UpdatedBlockTip] Enqueuing UpdatedBlockTip: new block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f fork block hash=null (in IBD=true)
2021-10-07T21:34:21.067900Z [scheduler] [validationinterface.cpp:226] [operator()] BlockConnected: block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f block height=0
2021-10-07T21:34:21.068045Z [scheduler] [validationinterface.cpp:199] [operator()] UpdatedBlockTip: new block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f fork block hash=null (in IBD=true)
2021-10-07T21:34:21.072298Z [test] [banman.cpp:27] [BanMan] Recreating the banlist database
2021-10-07T21:34:21.072533Z [test] [banman.cpp:55] [DumpBanlist] Flushed 0 banned node addresses/subnets to disk  0ms
2021-10-07T21:34:21.072589Z [test] [net.cpp:1783] [SetTryNewOutboundPeer] net: setting try another outbound peer=false
2021-10-07T21:34:21.072630Z [test] [net.cpp:2434] [SetNetworkActive] SetNetworkActive: true
2021-10-07T21:35:15.448296Z [scheduler] [util/thread.cpp:19] [TraceThread] scheduler thread exit

@fanquake
Copy link
Member

fanquake commented Oct 8, 2021

The addition of lock contention logging to the test suite

You've always been able to run with logging? #22736 & #22904 just changed the logging to be unconditional, rather than needing to compile with -DDEBUG_LOCKCONTENTION.

This alleviates #23167 until the test or code can be refactored, if possible and applicable, to reduce the number of contentions.

Concept NACK. Wouldn't it be better to either further debug/fix the actual issue, or revert the broken change(s), rather than just ignoring the problem by turning off the logging?

There has already been one comment in regards to these changes (#22736 & #22904) being:

far too dangerous to have turned on by default.

@JeremyRubin
Copy link
Contributor

the checkqueue tests are designed to be hevily contested, since we're hoping to trigger any race conditions or other issues, I don't think that if we're logging normal operation contentions we can really 'fix' the tests without making the tests less likely to uncover bugs.

maybe we can move checkqueue tests to fuzzing since it's a bit more fuzz like?

@jonatack
Copy link
Member Author

jonatack commented Oct 8, 2021

the checkqueue tests are designed to be hevily contested

Right, in which case it didn't make sense to log contentions in the checkqueue tests before, either. Logging contentions by default in the tests only revealed the issue, which was the goal.

Copy link
Member

@maflcko maflcko left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So the large log file can be reproduced on prior commits (e.g. v22.0) with DDEBUG_LOCKCONTENTION and DEBUG_LOG_OUT?

src/test/util/setup_common.h Outdated Show resolved Hide resolved
@jonatack
Copy link
Member Author

jonatack commented Oct 8, 2021

Just finished running these steps:

  • git log 7e69873
  • git checkout bb9f76a (last commit before)
  • rebuild with DEBUG_LOCKCONTENTION (debian clang 13)
  • ./src/test/test_bitcoin -t checkqueue_tests/test_CheckQueue_Correct_Random -- DEBUG_LOG_OUT > out.txt

They show that (for me) the issue was pre-existing.

-rw-r--r--  1 jon     5093 Oct  7 23:35 out-with-this-pull.txt
-rw-r--r--  1 jon 70258976 Oct  8 08:50 out-with-DEBUG_LOCKCONTENTION-at-bb9f76a.txt
-rw-r--r--  1 jon 28068863 Oct  7 20:46 out-on-current-master.txt

Edit: building v22.0 to test.

@jonatack
Copy link
Member Author

jonatack commented Oct 8, 2021

Added v22.0 to the results, and re-ran each result twice at the same CPU speed.

Screenshot from 2021-10-08 13-07-06

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 (up to v22) or with lock logging enabled by default
in current master.

Examples running the following command:

./src/test/test_bitcoin -t checkqueue_tests/test_CheckQueue_Correct_Random -- DEBUG_LOG_OUT > testlog.txt

-rw-r--r--   87042178 Oct  8 12:41 testlog-with-DEBUG_LOCKCONTENTION-at-v22-run1.txt
-rw-r--r--   73879896 Oct  8 12:42 testlog-with-DEBUG_LOCKCONTENTION-at-v22-run2.txt
-rw-r--r--   65150518 Oct  8 12:51 testlog-with-DEBUG_LOCKCONTENTION-at-bb9f76a-run1.txt
-rw-r--r--   65774554 Oct  8 12:52 testlog-with-DEBUG_LOCKCONTENTION-at-bb9f76a-run2.txt
-rw-r--r--   73493309 Oct  8 13:00 testlog-current-master-at-991753e-run1.txt
-rw-r--r--   65616977 Oct  8 13:01 testlog-current-master-at-991753e-run2.txt
-rw-r--r--       5093 Oct  8 13:04 testlog-with-this-commit-run1.txt
-rw-r--r--       5093 Oct  8 13:05 testlog-with-this-commit-run2.txt
@jonatack jonatack force-pushed the alleviate-checkqueue-tests-contention-logging branch from c48dc17 to 6ae9f1c Compare October 8, 2021 11:32
@jonatack jonatack changed the title Add NoLockLoggingTestingSetup to test utilities, use in checkqueue_tests Disable lock contention logging in checkqueue_tests Oct 8, 2021
@jonatack
Copy link
Member Author

jonatack commented Oct 8, 2021

Updated per @MarcoFalke's suggestion.

Copy link
Contributor

@vasild vasild left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK 6ae9f1c

Some testing results in #23167 (comment)

@maflcko maflcko merged commit 3c4729a into bitcoin:master Nov 2, 2021
@jonatack jonatack deleted the alleviate-checkqueue-tests-contention-logging branch November 3, 2021 09:48
maflcko pushed a commit that referenced this pull request Nov 29, 2021
459e208 Exit early for an empty vChecks in CCheckQueue::Add (Hennadii Stepanov)
c43aa62 Avoid excessive lock contention in CCheckQueue::Add (Hennadii Stepanov)

Pull request description:

  This PR significantly reduces lock contention in the `CCheckQueue` class by releasing a mutex before calling `std::condition_variable::notify_one` and `std::condition_variable::notify_all`.

  From C++ [docs](https://en.cppreference.com/w/cpp/thread/condition_variable/notify_one):
  > The notifying thread does not need to hold the lock on the same mutex as the one held by the waiting thread(s); in fact doing so is a pessimization, since the notified thread would immediately block again, waiting for the notifying thread to release the lock.

  Related to:
  - #23167
  - #23223

ACKs for top commit:
  martinus:
    ACK 459e208, codereview and tested. I first thought this introduced a segfault in `psbt_wallet_tests/psbt_updater_test` because that test failed for me, but thats a different issue fixed in #23403.
  vasild:
    ACK 459e208
  theStack:
    Code-review ACK 459e208

Tree-SHA512: c197858656392ba3ebcd638d713cf93c9fb48b7b3bad193209490d2828f9c7e3ae4dee6f84674f2f34dceed894139562e29579ee7299e06756c8c990caddc5ed
sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Nov 29, 2021
459e208 Exit early for an empty vChecks in CCheckQueue::Add (Hennadii Stepanov)
c43aa62 Avoid excessive lock contention in CCheckQueue::Add (Hennadii Stepanov)

Pull request description:

  This PR significantly reduces lock contention in the `CCheckQueue` class by releasing a mutex before calling `std::condition_variable::notify_one` and `std::condition_variable::notify_all`.

  From C++ [docs](https://en.cppreference.com/w/cpp/thread/condition_variable/notify_one):
  > The notifying thread does not need to hold the lock on the same mutex as the one held by the waiting thread(s); in fact doing so is a pessimization, since the notified thread would immediately block again, waiting for the notifying thread to release the lock.

  Related to:
  - bitcoin#23167
  - bitcoin#23223

ACKs for top commit:
  martinus:
    ACK 459e208, codereview and tested. I first thought this introduced a segfault in `psbt_wallet_tests/psbt_updater_test` because that test failed for me, but thats a different issue fixed in bitcoin#23403.
  vasild:
    ACK 459e208
  theStack:
    Code-review ACK 459e208

Tree-SHA512: c197858656392ba3ebcd638d713cf93c9fb48b7b3bad193209490d2828f9c7e3ae4dee6f84674f2f34dceed894139562e29579ee7299e06756c8c990caddc5ed
PastaPastaPasta pushed a commit to PastaPastaPasta/dash that referenced this pull request Apr 7, 2022
459e208 Exit early for an empty vChecks in CCheckQueue::Add (Hennadii Stepanov)
c43aa62 Avoid excessive lock contention in CCheckQueue::Add (Hennadii Stepanov)

Pull request description:

  This PR significantly reduces lock contention in the `CCheckQueue` class by releasing a mutex before calling `std::condition_variable::notify_one` and `std::condition_variable::notify_all`.

  From C++ [docs](https://en.cppreference.com/w/cpp/thread/condition_variable/notify_one):
  > The notifying thread does not need to hold the lock on the same mutex as the one held by the waiting thread(s); in fact doing so is a pessimization, since the notified thread would immediately block again, waiting for the notifying thread to release the lock.

  Related to:
  - bitcoin#23167
  - bitcoin#23223

ACKs for top commit:
  martinus:
    ACK 459e208, codereview and tested. I first thought this introduced a segfault in `psbt_wallet_tests/psbt_updater_test` because that test failed for me, but thats a different issue fixed in bitcoin#23403.
  vasild:
    ACK 459e208
  theStack:
    Code-review ACK 459e208

Tree-SHA512: c197858656392ba3ebcd638d713cf93c9fb48b7b3bad193209490d2828f9c7e3ae4dee6f84674f2f34dceed894139562e29579ee7299e06756c8c990caddc5ed
PastaPastaPasta pushed a commit to PastaPastaPasta/dash that referenced this pull request Apr 7, 2022
459e208 Exit early for an empty vChecks in CCheckQueue::Add (Hennadii Stepanov)
c43aa62 Avoid excessive lock contention in CCheckQueue::Add (Hennadii Stepanov)

Pull request description:

  This PR significantly reduces lock contention in the `CCheckQueue` class by releasing a mutex before calling `std::condition_variable::notify_one` and `std::condition_variable::notify_all`.

  From C++ [docs](https://en.cppreference.com/w/cpp/thread/condition_variable/notify_one):
  > The notifying thread does not need to hold the lock on the same mutex as the one held by the waiting thread(s); in fact doing so is a pessimization, since the notified thread would immediately block again, waiting for the notifying thread to release the lock.

  Related to:
  - bitcoin#23167
  - bitcoin#23223

ACKs for top commit:
  martinus:
    ACK 459e208, codereview and tested. I first thought this introduced a segfault in `psbt_wallet_tests/psbt_updater_test` because that test failed for me, but thats a different issue fixed in bitcoin#23403.
  vasild:
    ACK 459e208
  theStack:
    Code-review ACK 459e208

Tree-SHA512: c197858656392ba3ebcd638d713cf93c9fb48b7b3bad193209490d2828f9c7e3ae4dee6f84674f2f34dceed894139562e29579ee7299e06756c8c990caddc5ed
PastaPastaPasta pushed a commit to PastaPastaPasta/dash that referenced this pull request Apr 7, 2022
459e208 Exit early for an empty vChecks in CCheckQueue::Add (Hennadii Stepanov)
c43aa62 Avoid excessive lock contention in CCheckQueue::Add (Hennadii Stepanov)

Pull request description:

  This PR significantly reduces lock contention in the `CCheckQueue` class by releasing a mutex before calling `std::condition_variable::notify_one` and `std::condition_variable::notify_all`.

  From C++ [docs](https://en.cppreference.com/w/cpp/thread/condition_variable/notify_one):
  > The notifying thread does not need to hold the lock on the same mutex as the one held by the waiting thread(s); in fact doing so is a pessimization, since the notified thread would immediately block again, waiting for the notifying thread to release the lock.

  Related to:
  - bitcoin#23167
  - bitcoin#23223

ACKs for top commit:
  martinus:
    ACK 459e208, codereview and tested. I first thought this introduced a segfault in `psbt_wallet_tests/psbt_updater_test` because that test failed for me, but thats a different issue fixed in bitcoin#23403.
  vasild:
    ACK 459e208
  theStack:
    Code-review ACK 459e208

Tree-SHA512: c197858656392ba3ebcd638d713cf93c9fb48b7b3bad193209490d2828f9c7e3ae4dee6f84674f2f34dceed894139562e29579ee7299e06756c8c990caddc5ed
fanquake added a commit that referenced this pull request Apr 8, 2022
…or directive

4394733 Add DEBUG_LOCKCONTENTION documentation to the developer notes (Jon Atack)
39a34b6 Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive (Jon Atack)

Pull request description:

  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 runtime `lock` log category and improved the logging output. This changed the locking from using `lock()` to `try_lock()`:

  - `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

  In theory the cost of `try_lock` might be essentially the [same](https://www.erisian.com.au/bitcoin-core-dev/log-2022-03-31.html#l-697) relative to `lock`. 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](#22736 (comment)) and [here](https://www.erisian.com.au/bitcoin-core-dev/log-2022-03-31.html#l-620)) that `Base::try_lock()` may be potentially [costly](https://www.erisian.com.au/bitcoin-core-dev/log-2022-03-31.html#l-700) or [risky](#22904 (comment)) compared to `Base::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](#22736 (comment)). However, this would add the [cost](#22736 (comment)) of `if (LogAcceptCategory(BCLog::LOCK))` to the hotspot, instead of replacing `lock` with `try_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 and `lock` logging category behind a  `DEBUG_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.

ACKs for top commit:
  laanwj:
    Code review ACK 4394733

Tree-SHA512: 89b1271cae1dca0eb251914b1a60fc5b68320aab4a3939c57eec3a33a3c8f01688f05d95dfc31f91d71a6ed80cfe2d67b77ff14742611cc206175e47b2e5d3b1
PastaPastaPasta pushed a commit to PastaPastaPasta/dash that referenced this pull request Apr 11, 2022
459e208 Exit early for an empty vChecks in CCheckQueue::Add (Hennadii Stepanov)
c43aa62 Avoid excessive lock contention in CCheckQueue::Add (Hennadii Stepanov)

Pull request description:

  This PR significantly reduces lock contention in the `CCheckQueue` class by releasing a mutex before calling `std::condition_variable::notify_one` and `std::condition_variable::notify_all`.

  From C++ [docs](https://en.cppreference.com/w/cpp/thread/condition_variable/notify_one):
  > The notifying thread does not need to hold the lock on the same mutex as the one held by the waiting thread(s); in fact doing so is a pessimization, since the notified thread would immediately block again, waiting for the notifying thread to release the lock.

  Related to:
  - bitcoin#23167
  - bitcoin#23223

ACKs for top commit:
  martinus:
    ACK 459e208, codereview and tested. I first thought this introduced a segfault in `psbt_wallet_tests/psbt_updater_test` because that test failed for me, but thats a different issue fixed in bitcoin#23403.
  vasild:
    ACK 459e208
  theStack:
    Code-review ACK 459e208

Tree-SHA512: c197858656392ba3ebcd638d713cf93c9fb48b7b3bad193209490d2828f9c7e3ae4dee6f84674f2f34dceed894139562e29579ee7299e06756c8c990caddc5ed
Fabcien pushed a commit to Bitcoin-ABC/bitcoin-abc that referenced this pull request Sep 28, 2022
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
@bitcoin bitcoin locked and limited conversation to collaborators Nov 3, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

lock contentions in checkqueue_tests after #22904
6 participants