Skip to content

Conversation

andrewtoth
Copy link
Contributor

After #30611 we periodically do a non-erasing flush of the dbcache to disk roughly every hour during IBD.
The intention was to also do this periodic flush during reindex-chainstate, so we would not risk losing progress during a system failure when reindexing with a high dbcache value.

It was discovered that reindex-chainstate does not perform a PERIODIC flush until it has already reached the tip. Since reindexing to tip usually happens within 24 hours, this behaviour was unnoticed with the previous periodic flush interval. Note that reindex-chainstate still does IF_NEEDED flushes during ConnectBlock, so this also would not be noticed when running with a lower dbcache value.

This patch moves the PERIODIC flush from after the outer loop in ActivateBestChain to inside the outer loop after we release cs_main. This will periodically flush during IBD, reindex-chainstate, and steady state.

@DrahtBot
Copy link
Contributor

DrahtBot commented May 3, 2025

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Code Coverage & Benchmarks

For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/32414.

Reviews

See the guideline for information on the review process.

Type Reviewers
ACK l0rinc
Concept ACK shahsb

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

No conflicts as of last run.

@andrewtoth
Copy link
Contributor Author

Thanks to @l0rinc for discovering this behaviour, and @mzumsande for the suggested fix.

Copy link
Contributor

@l0rinc l0rinc left a comment

Choose a reason for hiding this comment

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

I'm verifying is this fixes things or not, whether it slows down anything - or if it changes caching behavior in any other way.

Regardless, I think we should cover this with a test - do you think we could extend e.g. https://github.com/bitcoin/bitcoin/blob/master/test/functional/feature_reindex.py with an assert_debug_log checking the periodic write logs of #32404?

@l0rinc
Copy link
Contributor

l0rinc commented May 3, 2025

I can confirm that this fixes the periodic flushes for -reindex-chainstate:

Details
cat debug-7fc8d7f9c1f0fe3795b397327e38465ee6f76b83-1746277780.log | grep FlushStateToDisk
2025-05-03T14:14:56Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
2025-05-03T15:16:31Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
2025-05-03T16:16:31Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
2025-05-03T16:36:48Z [coindb] FlushStateToDisk write: flush mode=ALWAYS, prune=0, cache_large=0, cache_critical=0, periodic=0
2025-05-03T16:39:20Z [coindb] FlushStateToDisk write: flush mode=ALWAYS, prune=0, cache_large=0, cache_critical=0, periodic=0

height_vs_time
cache_vs_time


Nit: is this comment still accurate? https://github.com/bitcoin/bitcoin/blob/master/src/validation.cpp#L2782 Guess it just refers to the size based trigger, not the time based - which is probably fine given its small context.

@DrahtBot
Copy link
Contributor

DrahtBot commented May 3, 2025

🚧 At least one of the CI tasks failed.
Task lint: https://github.com/bitcoin/bitcoin/runs/41595509701
LLM reason (✨ experimental): The CI failure is caused by a trailing whitespace error detected during the lint check.

Hints

Try to run the tests locally, according to the documentation. However, a CI failure may still
happen due to a number of reasons, for example:

  • Possibly due to a silent merge conflict (the changes in this pull request being
    incompatible with the current code in the target branch). If so, make sure to rebase on the latest
    commit of the target branch.

  • A sanitizer issue, which can only be found by compiling with the sanitizer and running the
    affected test.

  • An intermittent issue.

Leave a comment here, if you need help tracking down a confusing failure.

@andrewtoth andrewtoth force-pushed the reindex-flush branch 2 times, most recently from 0f089bd to da4090e Compare May 3, 2025 23:40
@andrewtoth
Copy link
Contributor Author

andrewtoth commented May 3, 2025

is this comment still accurate? https://github.com/bitcoin/bitcoin/blob/master/src/validation.cpp#L2782 Guess it just refers to the size based trigger, not the time based - which is probably fine given its small context.

I think it's still accurate, and #30611 doesn't make it stale. I think the comment https://github.com/bitcoin/bitcoin/blob/master/src/validation.cpp#L2861 describes the behavior.

Regardless, I think we should cover this with a test - do you think we could extend e.g. https://github.com/bitcoin/bitcoin/blob/master/test/functional/feature_reindex.py with an assert_debug_log checking the periodic write logs of #32404?

Hmm I was wondering if we could do something with mocktime and validation interface to confirm it flushes.

@andrewtoth andrewtoth closed this May 3, 2025
@l0rinc
Copy link
Contributor

l0rinc commented May 4, 2025

You didn't mean to close it, right?


I can confirm that this change retains the flushing behavior during IBD as well as far as I can tell from the plots:
height_vs_time

cache_coins_vs_time


I'll compare the reindex-chainstate performance next, before & after, let's see if there's a regression (we do expect a 4% slowdown for max cache, like in IBD).

Move the periodic flush inside the outer loop of ActivateBestChain.
For very long activations, such as with reindex-chainstate, this
calls periodic flushes so progress can be saved to disk.

Co-Authored-By: l0rinc <pap.lorinc@gmail.com>
@andrewtoth andrewtoth force-pushed the reindex-flush branch 2 times, most recently from e4fbf33 to 8d1e9fe Compare May 4, 2025 17:40
Copy link
Contributor

@l0rinc l0rinc left a comment

Choose a reason for hiding this comment

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

Concept ACK

Thanks for fixing it!
I need a bit mor explanation to be able to fully ack

andrewtoth added 2 commits May 4, 2025 15:00
The main lock needs to be taken 3 separate times.
It simplifies readability to take it once, and is more efficient.
Copy link
Contributor

@l0rinc l0rinc left a comment

Choose a reason for hiding this comment

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

Code review ACK - I'm still running the reindex / IBD benchmarks to see if this changed anything unexpected.

Do you think I should stop and restart after the locking changes?

nits
diff --git a/src/test/chainstate_write_tests.cpp b/src/test/chainstate_write_tests.cpp
index e1b82ebc12..44257d5591 100644
--- a/src/test/chainstate_write_tests.cpp
+++ b/src/test/chainstate_write_tests.cpp
@@ -16,7 +16,8 @@ BOOST_AUTO_TEST_SUITE(chainstate_write_tests)
 
 BOOST_FIXTURE_TEST_CASE(chainstate_write_interval, TestingSetup)
 {
-    struct TestSubscriber final : CValidationInterface {
+    struct TestSubscriber final : CValidationInterface
+    {
         bool m_did_flush{false};
         void ChainStateFlushed(ChainstateRole, const CBlockLocator&) override
         {
@@ -34,13 +35,12 @@ BOOST_FIXTURE_TEST_CASE(chainstate_write_interval, TestingSetup)
     m_node.validation_signals->SyncWithValidationInterfaceQueue();
     BOOST_CHECK(!sub->m_did_flush);
 
-    // The periodic flush interval is between 50 and 70 minutes (inclusive)
-    SetMockTime(GetTime<std::chrono::minutes>() + DATABASE_WRITE_INTERVAL_MIN - 1min);
+    SetMockTime(GetMockTime() + DATABASE_WRITE_INTERVAL_MIN - 1min);
     chainstate.FlushStateToDisk(state_dummy, FlushStateMode::PERIODIC);
     m_node.validation_signals->SyncWithValidationInterfaceQueue();
     BOOST_CHECK(!sub->m_did_flush);
 
-    SetMockTime(GetTime<std::chrono::minutes>() + DATABASE_WRITE_INTERVAL_MAX);
+    SetMockTime(GetMockTime() + DATABASE_WRITE_INTERVAL_MAX);
     chainstate.FlushStateToDisk(state_dummy, FlushStateMode::PERIODIC);
     m_node.validation_signals->SyncWithValidationInterfaceQueue();
     BOOST_CHECK(sub->m_did_flush);
@@ -59,7 +59,8 @@ BOOST_FIXTURE_TEST_CASE(write_during_multiblock_activation, TestChain100Setup)
         {
             m_flushed_at_block = m_tip;
         }
-        void UpdatedBlockTip(const CBlockIndex* block_index, const CBlockIndex*, bool) override {
+        void UpdatedBlockTip(const CBlockIndex* block_index, const CBlockIndex*, bool) override
+        {
             m_tip = block_index;
         }
     };
@@ -82,7 +83,6 @@ BOOST_FIXTURE_TEST_CASE(write_during_multiblock_activation, TestChain100Setup)
     // Set m_next_write to current time
     chainstate.FlushStateToDisk(state_dummy, FlushStateMode::ALWAYS);
     m_node.validation_signals->SyncWithValidationInterfaceQueue();
-    // The periodic flush interval is between 50 and 70 minutes (inclusive)
     // The next call to a PERIODIC write will flush
     SetMockTime(GetMockTime() + DATABASE_WRITE_INTERVAL_MAX);

// before reaching chain tip.
BOOST_FIXTURE_TEST_CASE(write_during_multiblock_activation, TestChain100Setup)
{
struct TestSubscriber final : CValidationInterface
Copy link
Contributor

@l0rinc l0rinc May 4, 2025

Choose a reason for hiding this comment

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

nit: if you edit again please reformat TestSubscriber and UpdatedBlockTip as well

@@ -31,15 +35,68 @@ BOOST_FIXTURE_TEST_CASE(chainstate_write_interval, TestingSetup)
BOOST_CHECK(!sub->m_did_flush);

// The periodic flush interval is between 50 and 70 minutes (inclusive)
Copy link
Contributor

Choose a reason for hiding this comment

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

now that we have the constants these comments don't really add anything

// Set m_next_write to current time
chainstate.FlushStateToDisk(state_dummy, FlushStateMode::ALWAYS);
m_node.validation_signals->SyncWithValidationInterfaceQueue();
// The periodic flush interval is between 50 and 70 minutes (inclusive)
Copy link
Contributor

Choose a reason for hiding this comment

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

same, can be removed now I think (and 70 minutes isn't inclusive anymore, right?)

Copy link

@shahsb shahsb left a comment

Choose a reason for hiding this comment

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

Concept ACK

@l0rinc
Copy link
Contributor

l0rinc commented May 6, 2025

Finished measuring reindex-chainstate performance for max dbcache (best case scenario), where this PR shines most (i.e. to avoid the worst-case scenario of doing everything in-memory and crashing at the end without anything saved).

Measured it on an HDD with i7 processor, so disk writes are expensive here - would likely be better on SSD.
Unfortunately this change results in a 11% slowdown for scenarios that were hoarding memory, since it has to flush intermediary results regularly, so the invalidations happen on disk now instead of in-memory.

Benchmark
COMMITS="eba5f9c4b63fe46261fbb3e71b9a94832d105b23 b56a7e2e983c78eca9acdf12a77f60a3cc6b53a0"; \                                
STOP_HEIGHT=888888; DBCACHE=45000; \                                                                                                                                                      
CC=gcc; CXX=g++; \                                                                                                                                                                        
BASE_DIR="/mnt/my_storage"; DATA_DIR="$BASE_DIR/BitcoinData"; LOG_DIR="$BASE_DIR/logs"; \                                                                                                 
(echo ""; for c in $COMMITS; do git fetch origin $c -q && git log -1 --pretty=format:'%h %s' $c || exit 1; done; echo "") && \                                                            
hyperfine \                                                                                                                                                                               
  --sort 'command' \                                                                                                                                                                      
  --runs 2 \                                                                                                                                                                              
  --export-json "$BASE_DIR/rdx-${COMMITS// /-}-$STOP_HEIGHT-$DBCACHE-$CC.json" \                                                                                                          
  --parameter-list COMMIT ${COMMITS// /,} \
  --prepare "killall bitcoind; rm -f $DATA_DIR/debug.log; git checkout {COMMIT}; git clean -fxd; git reset --hard; \
    cmake -B build -DCMAKE_BUILD_TYPE=Release -DENABLE_WALLET=OFF && cmake --build build -j$(nproc) --target bitcoind && \
    ./build/bin/bitcoind -datadir=$DATA_DIR -stopatheight=$STOP_HEIGHT -dbcache=5000 -printtoconsole=0; sleep 100" \
  --cleanup "cp $DATA_DIR/debug.log $LOG_DIR/debug-{COMMIT}-$(date +%s).log" \
  "COMPILER=$CC ./build/bin/bitcoind -datadir=$DATA_DIR -stopatheight=$STOP_HEIGHT -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=$DBCACHE"

eba5f9c Merge #32403: test: remove Boost SIGCHLD workaround.
b56a7e2 validation: periodically flush dbcache during reindex-chainstate

Benchmark 1: COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=888888 -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=45000 (COMMIT = eba5f9c4b63fe46261fbb3e71b9a94832d105b23) 
  Time (mean ± σ):     22404.449 s ± 77.811 s    [User: 20909.449 s, System: 563.985 s]
  Range (minmax):   22349.428 s22459.469 s    2 runs
  
Benchmark 2: COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=888888 -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=45000 (COMMIT = b56a7e2e983c78eca9acdf12a77f60a3cc6b53a0) 
  Time (mean ± σ):     24821.312 s ± 19.392 s    [User: 22218.160 s, System: 746.676 s]
  Range (minmax):   24807.600 s24835.024 s    2 runs
Relative speed comparison
        1.00          COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=888888 -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=45000 (COMMIT = eba5f9c4b63fe46261fbb3e71b9a94832d105b23)
        1.11 ±  0.00  COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=888888 -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=45000 (COMMIT = b56a7e2e983c78eca9acdf12a77f60a3cc6b53a0)

It's unfortunate to lose this much performance, as suggested before, maybe the change from 24 hours to 1 hour was too big - what if we tried an average of 100 minutes instead?

Will measure IBD with latest changes now.

@andrewtoth
Copy link
Contributor Author

It's unfortunate to lose this much performance, as suggested before, maybe the change from 24 hours to 1 hour was too big - what if we tried an average of 100 minutes instead?

I'm not sure it's worth bike shedding over the amount of time to periodically flush. The difference with an HDD is 6 hours 13 minutes vs 6 hours 53 minutes. So we could be saving a maximum of 40 minutes over something that takes over 6 hours anyways.

@l0rinc
Copy link
Contributor

l0rinc commented May 7, 2025

I'll compare the reindex-chainstate performance next, before & after, let's see if there's a regression (we do expect a 4% slowdown for max cache, like in IBD).

IBD seems to be basically the same as before, this change indeed only affects reindex-chainstate.

Details
COMMITS="baa848b8d38187ce6b24a57cfadf1ea180209711 c822dd1f355b6f403191072cdd3c9c3e234bbcaa"; \
STOP_HEIGHT=888888; DBCACHE=45000; \
CC=gcc; CXX=g++; \
BASE_DIR="/mnt/my_storage"; DATA_DIR="$BASE_DIR/BitcoinData"; LOG_DIR="$BASE_DIR/logs"; \
(echo ""; for c in $COMMITS; do git fetch origin $c -q && git log -1 --pretty=format:'%h %s' $c || exit 1; done; echo "") && \
hyperfine \
  --sort 'command' \
  --runs 1 \
  --export-json "$BASE_DIR/ibd-${COMMITS// /-}-$STOP_HEIGHT-$DBCACHE-$CC.json" \
  --parameter-list COMMIT ${COMMITS// /,} \
  --prepare "killall bitcoind; rm -rf $DATA_DIR/*; git checkout {COMMIT}; git clean -fxd; git reset --hard; \
    cmake -B build -DCMAKE_BUILD_TYPE=Release -DENABLE_WALLET=OFF && cmake --build build -j$(nproc) --target bitcoind && \
    ./build/bin/bitcoind -datadir=$DATA_DIR -stopatheight=1 -printtoconsole=0; sleep 10" \
  --cleanup "cp $DATA_DIR/debug.log $LOG_DIR/debug-{COMMIT}-$(date +%s).log" \
  "COMPILER=$CC ./build/bin/bitcoind -datadir=$DATA_DIR -blocksonly -printtoconsole=0 -stopatheight=$STOP_HEIGHT -dbcache=$DBCACHE"

baa848b Merge #32405: build: replace header checks with __has_include
c822dd1 refactor: consolidate 3 separate locks into one block

Benchmark 1: COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -blocksonly -printtoconsole=0 -stopatheight=888888 -dbcache=45000 (COMMIT = baa848b8d38187ce6b24a57cfadf1ea180209711)
  Time (abs ≡):        38323.520 s               [User: 36485.235 s, System: 2391.492 s]
 
Benchmark 2: COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -blocksonly -printtoconsole=0 -stopatheight=888888 -dbcache=45000 (COMMIT = c822dd1f355b6f403191072cdd3c9c3e234bbcaa)
  Time (abs ≡):        38063.544 s               [User: 35628.341 s, System: 1952.398 s]
Relative speed comparison
        1.01          COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -blocksonly -printtoconsole=0 -stopatheight=888888 -dbcache=45000 (COMMIT = baa848b8d38187ce6b24a57cfadf1ea180209711)
        1.00          COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -blocksonly -printtoconsole=0 -stopatheight=888888 -dbcache=45000 (COMMIT = c822dd1f355b6f403191072cdd3c9c3e234bbcaa)

So we could be saving a maximum of 40 minutes

Yes, it's a significant difference. I'll retry it with 100 minutes to see if it would fix the situation.

@l0rinc
Copy link
Contributor

l0rinc commented May 12, 2025

I'll retry it with 100 minutes to see if it would fix the situation.

With 100 mins it's 7% slower instead of 11% - still quite bad, but we shouldn't have to choose between performance and persistence, so let's find ways to reduce that. And IBD is the usecase that matters most anyway.

Details
COMMITS="59d3e4ed34eb55cb40928d524cb0bd5e183ed85a cf75a7b599fe459935b7aa4776e91526fcfb0fcc"; \
STOP_HEIGHT=888888; DBCACHE=45000; \
CC=gcc; CXX=g++; \
BASE_DIR="/mnt/my_storage"; DATA_DIR="$BASE_DIR/BitcoinData"; LOG_DIR="$BASE_DIR/logs"; \
(echo ""; for c in $COMMITS; do git fetch origin $c -q && git log -1 --pretty=format:'%h %s' $c || exit 1; done; echo "") && \
hyperfine \
  --sort 'command' \
  --runs 2 \
  --export-json "$BASE_DIR/rdx-${COMMITS// /-}-$STOP_HEIGHT-$DBCACHE-$CC.json" \
  --parameter-list COMMIT ${COMMITS// /,} \
  --prepare "killall bitcoind; rm -f $DATA_DIR/debug.log; git checkout {COMMIT}; git clean -fxd; git reset --hard; \
    cmake -B build -DCMAKE_BUILD_TYPE=Release -DENABLE_WALLET=OFF && cmake --build build -j$(nproc) --target bitcoind && \
    ./build/bin/bitcoind -datadir=$DATA_DIR -stopatheight=$STOP_HEIGHT -dbcache=5000 -printtoconsole=0; sleep 10" \
  --cleanup "cp $DATA_DIR/debug.log $LOG_DIR/debug-{COMMIT}-$(date +%s).log" \
  "COMPILER=$CC ./build/bin/bitcoind -datadir=$DATA_DIR -stopatheight=$STOP_HEIGHT -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=$DBCACHE"

59d3e4e Merge #32415: scripted-diff: adapt script error constant names in feature_taproot.py
cf75a7b DATABASE_WRITE_INTERVAL ~100min

Benchmark 1: COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=888888 -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=45000 (COMMIT = 59d3e4ed34eb55cb40928d524cb0bd5e183ed85a)
  Time (mean ± σ):     22098.816 s ±  5.810 s    [User: 20814.326 s, System: 557.473 s]
  Range (minmax):   22094.707 s22102.924 s    2 runs
 
Benchmark 2: COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=888888 -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=45000 (COMMIT = cf75a7b599fe459935b7aa4776e91526fcfb0fcc)
  Time (mean ± σ):     23737.633 s ± 159.720 s    [User: 21704.678 s, System: 682.595 s]
  Range (minmax):   23624.694 s23850.572 s    2 runs
Relative speed comparison
        1.00          COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=888888 -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=45000 (COMMIT = 59d3e4ed34eb55cb40928d524cb0bd5e183ed85a)
        1.07 ±  0.01  COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=888888 -reindex-chainstate -blocksonly -connect=0 -printtoconsole=0 -dbcache=45000 (COMMIT = cf75a7b599fe459935b7aa4776e91526fcfb0fcc)

ACK c1e554d

Nit: I'd squash the first two commits, they should be split by features, not by files.
The test demonstrates the need for the solution, it's weird to have the answer first, followed by the question.

@DrahtBot DrahtBot requested a review from shahsb May 12, 2025 12:08
luke-jr pushed a commit to bitcoinknots/bitcoin that referenced this pull request Jun 5, 2025
Move the periodic flush inside the outer loop of ActivateBestChain.
For very long activations, such as with reindex-chainstate, this
calls periodic flushes so progress can be saved to disk.

Co-Authored-By: l0rinc <pap.lorinc@gmail.com>

Github-Pull: bitcoin#32414
Rebased-From: 8482056
luke-jr pushed a commit to bitcoinknots/bitcoin that referenced this pull request Jun 5, 2025
@DrahtBot DrahtBot requested a review from achow101 July 31, 2025 22:57
@achow101 achow101 removed request for achow101 and shahsb July 31, 2025 23:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants