Disable lock contention logging in checkqueue_tests #23223

pull jonatack wants to merge 1 commits into bitcoin:master from jonatack:alleviate-checkqueue-tests-contention-logging changing 1 files +11 −1
  1. jonatack commented at 6:35 pm on October 7, 2021: member

    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:

    0$ ./src/test/test_bitcoin -t checkqueue_tests/test_CheckQueue_Correct_Random -- DEBUG_LOG_OUT > testlog.txt
1
2-rw-r--r--   87042178 Oct  8 12:41 testlog-with-DEBUG_LOCKCONTENTION-at-v22-run1.txt
3-rw-r--r--   73879896 Oct  8 12:42 testlog-with-DEBUG_LOCKCONTENTION-at-v22-run2.txt
4-rw-r--r--   65150518 Oct  8 12:51 testlog-with-DEBUG_LOCKCONTENTION-at-bb9f76a-run1.txt
5-rw-r--r--   65774554 Oct  8 12:52 testlog-with-DEBUG_LOCKCONTENTION-at-bb9f76a-run2.txt
6-rw-r--r--   73493309 Oct  8 13:00 testlog-current-master-at-991753e-run1.txt
7-rw-r--r--   65616977 Oct  8 13:01 testlog-current-master-at-991753e-run2.txt
8-rw-r--r--       5093 Oct  8 13:04 testlog-with-this-commit-run1.txt
9-rw-r--r--       5093 Oct  8 13:05 testlog-with-this-commit-run2.txt

    Resolves #23167.

  2. DrahtBot added the label Tests on Oct 7, 2021
  3. jonatack commented at 9:41 pm on October 7, 2021: member

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

     0Running 1 test case...
 12021-10-07T21:34:20Z Seed: Setting random seed for current tests to RANDOM_CTX_SEED=af952f85f519906580f814500cbea272d0337c9f6a57e4565b1449a7191939cb
 22021-10-07T21:34:20.979238Z [test] [init/common.cpp:165] [LogPackageVersion] Bitcoin Core version v22.99.0-af1b6dd28c73 (debug build)
 32021-10-07T21:34:20.979640Z [test] [init.cpp:904] [AppInitParameterInteraction] Assuming ancestors of block 00000000000000000008a89e854d57e5667df88f1cdef6fde2fbca1de5b639ad have valid signatures.
 42021-10-07T21:34:20.979675Z [test] [init.cpp:917] [AppInitParameterInteraction] Setting nMinimumChainWork=00000000000000000000000000000000000000001fa4663bbbe19f82de910280
 52021-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
 62021-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
 72021-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.
 82021-10-07T21:34:21.030388Z [test] [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully
 92021-10-07T21:34:21.030464Z [test] [dbwrapper.cpp:166] [CDBWrapper] Using obfuscation key for /tmp/test_common_Bitcoin Core/3f96173145376177754944c55c5bab576064058986990ff10474f63c96aa86a1/blocks/index: 0000000000000000
102021-10-07T21:34:21.043439Z [scheduler] [util/thread.cpp:17] [TraceThread] scheduler thread start
112021-10-07T21:34:21.053557Z [test] [validation.cpp:4700] [InitializeChainstate] Switching active chainstate to Chainstate [ibd] @ height -1 (null)
122021-10-07T21:34:21.053897Z [test] [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully
132021-10-07T21:34:21.054055Z [test] [dbwrapper.cpp:163] [CDBWrapper] Wrote new obfuscate key for /tmp/test_common_Bitcoin Core/3f96173145376177754944c55c5bab576064058986990ff10474f63c96aa86a1/chainstate: 8ccff399f33daf0b
142021-10-07T21:34:21.054088Z [test] [dbwrapper.cpp:166] [CDBWrapper] Using obfuscation key for /tmp/test_common_Bitcoin Core/3f96173145376177754944c55c5bab576064058986990ff10474f63c96aa86a1/chainstate: 8ccff399f33daf0b
152021-10-07T21:34:21.054330Z [test] [flatfile.cpp:69] [Allocate] Pre-allocating up to position 0x1000000 in blk00000.dat
162021-10-07T21:34:21.055063Z [test] [validation.cpp:2295] [ConnectTip]   - Load block from disk: 0.16ms [0.00s]
172021-10-07T21:34:21.055218Z [test] [validationinterface.cpp:249] [BlockChecked] BlockChecked: block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f state=Valid
182021-10-07T21:34:21.055278Z [test] [validation.cpp:2307] [ConnectTip]   - Connect total: 0.24ms [0.00s (0.24ms/blk)]
192021-10-07T21:34:21.055306Z [test] [validation.cpp:2312] [ConnectTip]   - Flush: 0.04ms [0.00s (0.04ms/blk)]
202021-10-07T21:34:21.055426Z [test] [validation.cpp:2318] [ConnectTip]   - Writing chainstate: 0.11ms [0.00s (0.11ms/blk)]
212021-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)
222021-10-07T21:34:21.055872Z [test] [validation.cpp:2329] [ConnectTip]   - Connect postprocess: 0.45ms [0.00s (0.45ms/blk)]
232021-10-07T21:34:21.055900Z [test] [validation.cpp:2330] [ConnectTip] - Connect block: 0.99ms [0.00s (0.99ms/blk)]
242021-10-07T21:34:21.055966Z [test] [txmempool.cpp:691] [check] Checking mempool with 0 transactions and 0 inputs
252021-10-07T21:34:21.056115Z [test] [validationinterface.cpp:226] [BlockConnected] Enqueuing BlockConnected: block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f block height=0
262021-10-07T21:34:21.056282Z [test] [validationinterface.cpp:199] [UpdatedBlockTip] Enqueuing UpdatedBlockTip: new block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f fork block hash=null (in IBD=true)
272021-10-07T21:34:21.067900Z [scheduler] [validationinterface.cpp:226] [operator()] BlockConnected: block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f block height=0
282021-10-07T21:34:21.068045Z [scheduler] [validationinterface.cpp:199] [operator()] UpdatedBlockTip: new block hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f fork block hash=null (in IBD=true)
292021-10-07T21:34:21.072298Z [test] [banman.cpp:27] [BanMan] Recreating the banlist database
302021-10-07T21:34:21.072533Z [test] [banman.cpp:55] [DumpBanlist] Flushed 0 banned node addresses/subnets to disk  0ms
312021-10-07T21:34:21.072589Z [test] [net.cpp:1783] [SetTryNewOutboundPeer] net: setting try another outbound peer=false
322021-10-07T21:34:21.072630Z [test] [net.cpp:2434] [SetNetworkActive] SetNetworkActive: true
332021-10-07T21:35:15.448296Z [scheduler] [util/thread.cpp:19] [TraceThread] scheduler thread exit
  4. fanquake commented at 1:03 am on October 8, 2021: member

    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.

  5. JeremyRubin commented at 1:44 am on October 8, 2021: 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?

  6. jonatack commented at 5:44 am on October 8, 2021: member

    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.

  7. in src/test/util/setup_common.h:113 in c48dc175a0 outdated 
    105@@ -106,6 +106,12 @@ struct RegTestingSetup : public TestingSetup {
106         : TestingSetup{CBaseChainParams::REGTEST} {}
107 };
108 
109+/** Identical to TestingSetup, but excludes lock contention logging. */
110+struct NoLockLoggingTestingSetup : public TestingSetup {
111+    NoLockLoggingTestingSetup()
112+        : TestingSetup{CBaseChainParams::MAIN, /*extra_args=*/{"-debugexclude=lock"}} {}
113+};
    MarcoFalke commented at 7:28 am on October 8, 2021:
    if there is no other test using this, you can move it to the only translation unit that needs it
    jonatack commented at 11:32 am on October 8, 2021:
    done
  8. MarcoFalke commented at 7:29 am on October 8, 2021: member
    So the large log file can be reproduced on prior commits (e.g. v22.0) with DDEBUG_LOCKCONTENTION and DEBUG_LOG_OUT?
  9. jonatack commented at 7:33 am on October 8, 2021: member

    Just finished running these steps:

    • git log 7e69873
    • git checkout bb9f76a7 (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.

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

    Edit: building v22.0 to test.

  10. jonatack commented at 11:10 am on October 8, 2021: member

    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

  11. Disable lock contention logging in 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
    6ae9f1cf96
  12. jonatack force-pushed on Oct 8, 2021
  13. jonatack renamed this:
    Add NoLockLoggingTestingSetup to test utilities, use in checkqueue_tests
    Disable lock contention logging in checkqueue_tests
    on Oct 8, 2021
  14. jonatack commented at 11:43 am on October 8, 2021: member
    Updated per @MarcoFalke’s suggestion.
  15. vasild approved
  16. vasild commented at 4:31 pm on November 2, 2021: member

    ACK 6ae9f1cf9604227e9dfda1f6c91fc711d154362e

    Some testing results in #23167 (comment)

  17. MarcoFalke merged this on Nov 2, 2021
  18. MarcoFalke closed this on Nov 2, 2021
  19. jonatack deleted the branch on Nov 3, 2021
  20. MarcoFalke referenced this in commit b4f647fa36 on Nov 29, 2021
  21. sidhujag referenced this in commit 537b8a836d on Nov 29, 2021
  22. PastaPastaPasta referenced this in commit c8374bd577 on Apr 7, 2022
  23. PastaPastaPasta referenced this in commit 25f8e062c0 on Apr 7, 2022
  24. PastaPastaPasta referenced this in commit 572737fff5 on Apr 7, 2022
  25. fanquake referenced this in commit c1059c9fef on Apr 8, 2022
  26. PastaPastaPasta referenced this in commit 22838d1b8c on Apr 11, 2022
  27. Fabcien referenced this in commit 5d9c53f2a6 on Sep 28, 2022
  28. DrahtBot locked this on Nov 3, 2022


jonatack fanquake JeremyRubin MarcoFalke vasild

Labels
Tests

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-12-22 15:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me