validation: write chainstate to disk every hour

[andrewtoth]

Since #28233, periodically writing the chainstate to disk every 24 hours does not clear the dbcache. Since #28280, periodically writing the chainstate to disk is proportional only to the amount of dirty entries in the cache. Due to these changes, it is no longer beneficial to only write the chainstate to disk every 24 hours. The periodic flush interval was necessary because every write of the chainstate would clear the dbcache. Now, we can get rid of the periodic flush interval and simply write the chainstate along with blocks and block index at least every hour.

Three benefits of doing this:

1. For IBD or reindex-chainstate with a combination of large dbcache setting, slow CPU, slow internet speed/unreliable peers, it could be up to 24 hours until the chainstate is persisted to disk. A power outage or crash could potentially lose up to 24 hours of progress. If there is a very large amount of dirty cache entries, writing to disk when a flush finally does occur will take a very long time. Crashing during this window of writing can cause "Rolling forward" at startup can take a long time, and is not interruptible (after unclean shutdown) #11600. By syncing every hour in unison with the block index we avoid this problem. Only a maximum of one hour of progress can be lost, and the window for crashing during writing is much smaller. For IBD with lower dbcache settings, faster CPU, or better internet speed/reliable peers, chainstate writes are already triggered more often than every hour so this change will have no effect on IBD.
2. Based on discussion in Don't empty dbcache on prune flushes: >30% faster IBD #28280, writing only once every 24 hours during long running operation of a node causes IO spikes. Writing smaller chainstate changes every hour like we do with blocks and block index will reduce IO spikes.
3. Faster shutdown speeds. All dirty chainstate entries must be persisted to disk on shutdown. If we have a lot of dirty entries, such as when close to 24 hours or if we sync with a large dbcache, it can take a long time to shutdown. By keeping the chainstate clean we avoid this problem.

Inspired by this comment.

Resolves #11600

[DrahtBot]

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/30611.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	achow101, davidgumberg, l0rinc, sipa

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

• #31703 (Use number of dirty cache entries in flush warnings/logs by sipa)
• #30610 (validation: do not wipe utxo cache for stats/scans/snapshots by sipa)
• #29365 (Extend signetchallenge to set target block spacing by starius)

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.

[gmaxwell]

Before someone suggests that it should do this every block, a reason to not do this too much is that delaying writes prevents many writes from ever happening at all because many outputs are quickly spent.

I don't see a particular problem for this, there will be some write traffic increase but I don't expect it will be enough to meaningfully reduce the life time of flash on cheap devices (and if that were a concern the default level of logging is probably more of an issue). It's the sort of thing someone could test, however.

Someone might also want to test the latency impact (e.g. on block template creation) of the traversal.

Though long term it would be preferable to introduce a data structure to track pending writes and keep a constantly flushing going which always lags the tip by N blocks, both avoiding the latency spikes and preventing unnecessary writes of entries that are just going to be spent in the next couple blocks.

[mzumsande]

Did you check if this would slow down IBD noticeably when running with a large dbcache?
If i understand it right, coins that are created and destroyed more than 1 hour of syncing apart would not have been written to disk before, but will be written and deleted after this PR - though presumably this is not a frequent event, so there wouldn't be much of an impact?!

[andrewtoth]

Before someone suggests that it should do this every block, a reason to not do this too much is that delaying writes prevents many writes from ever happening at all because many outputs are quickly spent.

If i understand it right, coins that are created and destroyed more than 1 hour of syncing apart would not have been written to disk before, but will be written and deleted after this PR

Correct, there will be significantly less utxo cut through with this PR.

I don't see a particular problem for this, there will be some write traffic increase but I don't expect it will be enough to meaningfully reduce the life time of flash on cheap devices (and if that were a concern the default level of logging is probably more of an issue). It's the sort of thing someone could test, however.

though presumably this is not a frequent event, so there wouldn't be much of an impact?!

For normal operation, this would mean writing 10s of MB every hour, vs 100s of MB every 24 hours. I don't think that we should be concerned about that increase in disk IO? Seems negligible to me.

Did you check if this would slow down IBD noticeably when running with a large dbcache?

Not yet. I will run a reindex-chainstate benchmark with max dbcache and see what the impact is.

[sipa]

It would be good to know what impact it has on IBD, as it's necessarily going to make things slower (more syncs means more disk writes, and more memory/cpu to remember UTXOs which must be marked spent on disk), for the benefit of reducing losses in case of crashes. The question is how much time & I/O it adds.

Regarding doing it for every block (during steady state), the trade-off there is different but still exists. On the pro side there is a reduction of latency spikes instead of reducing crash losses (as these are inherently less relevant in steady state). On the con side there is an increase in frequency of writes (and the latency spikes they bring, albeit smaller ones) instead of a sync speed slowdown.

We don't necessarily need to use the same sync frequency during IBD and during steady state, but the effects during steady state seem harder to measure, so it's hard to say what is acceptable there.

One related idea: maybe we should randomize the sync event times a bit (say, uniformly random intervals between 50 and 70 minutes) to prevent a situation where the network over time settles into a few cohorts of synchronized syncers (think like communicating metronomes: they start randomly, but have synchronized events (blocks arriving) that slightly delay sync events if they were to coincide).

[andrewtoth]

It would be good to know what impact it has on IBD, as it's necessarily going to make things slower

Note that it is only necessarily slower when running with very high dbcache settings. For default settings the cache fills up and is flushed far more often than every hour, so this will have no effect.

[andrewtoth]

This change didn't appear to have any speed impact for a reindex-chainstate using max dbcache. Ran the following benchmark:

nohup hyperfine \
--export-markdown ~/bench.md \
--show-output \
--parameter-list commit 81508954f1f89f95b6fdca10c3c471cdb6566c80,27a770b34b8f1dbb84760f442edb3e23a0c2420b \
--prepare 'git checkout {commit} && \
make -j$(nproc) src/bitcoind; \
sync; sudo /sbin/sysctl vm.drop_caches=3;' \
-M 2 \
'echo '{commit}' && \
./src/bitcoind -datadir=/home/user/.bitcoin \
-reindex-chainstate \
-dbcache=16384 \
-printtoconsole=0 \
-connect=0 \
-stopatheight=820000' &

Results are the same:

Benchmark 1: echo 81508954f1f89f95b6fdca10c3c471cdb6566c80 && \
./src/bitcoind -datadir=/home/user/.bitcoin \
-reindex-chainstate \
-dbcache=16384 \
-printtoconsole=0 \
-connect=0 \
-stopatheight=820000

81508954f1f89f95b6fdca10c3c471cdb6566c80
  Time (mean ± σ):     12239.620 s ±  3.156 s    [User: 12366.988 s, System: 562.121 s]
  Range (min … max):   12237.388 s … 12241.851 s    2 runs
 
Benchmark 2: echo 27a770b34b8f1dbb84760f442edb3e23a0c2420b && \
./src/bitcoind -datadir=/home/user/.bitcoin \
-reindex-chainstate \
-dbcache=16384 \
-printtoconsole=0 \
-connect=0 \
-stopatheight=820000

27a770b34b8f1dbb84760f442edb3e23a0c2420b
  Time (mean ± σ):     12243.072 s ±  6.588 s    [User: 12382.386 s, System: 559.349 s]
  Range (min … max):   12238.413 s … 12247.730 s    2 runs
 
Summary
  'echo 81508954f1f89f95b6fdca10c3c471cdb6566c80 && \
./src/bitcoind -datadir=/home/user/.bitcoin \
-reindex-chainstate \
-dbcache=16384 \
-printtoconsole=0 \
-connect=0 \
-stopatheight=820000' ran
    1.00 ± 0.00 times faster than 'echo 27a770b34b8f1dbb84760f442edb3e23a0c2420b && \
./src/bitcoind -datadir=/home/user/.bitcoin \
-reindex-chainstate \
-dbcache=16384 \
-printtoconsole=0 \
-connect=0 \
-stopatheight=820000'

So, I would say this PR is strictly beneficial for IBD/reindex-chainstate. It is the same speed, but protects against data loss.

[gmaxwell]

I didn't comment on IBD because I figured a hit per hour isn't that significant in the context of IBD and likely pays for itself in improving crash robustness. I'm a little surprised that the effect is quite so small, but it does probably improve performance too by making writes a little more concurrent.

Sipa: good point on the injection locking, I've previously wondered if the the 24 hour behavior could sync up.

[andrewtoth]

I'm a little surprised that the effect is quite so small

@gmaxwell I was as well, so I ran the same benchmark with -reindex as well and it gave me similar results:

Command	Mean [s]	Min [s]	Max [s]	Relative
echo 81508954f1f89f95b6fdca10c3c471cdb6566c80 && ./src/bitcoind -datadir=/home/user/.bitcoin -reindex -dbcache=16384 -printtoconsole=0 -connect=0 -stopatheight=820000	40765.075 ± 132.452	40671.417	40858.733	1.01 ± 0.00
echo 27a770b34b8f1dbb84760f442edb3e23a0c2420b && ./src/bitcoind -datadir=/home/user/.bitcoin -reindex -dbcache=16384 -printtoconsole=0 -connect=0 -stopatheight=820000	40536.484 ± 46.379	40503.689	40569.279	1.00

Will get some measurements for total chainstate bytes written and total time writing chainstate before and after this change during steady state. But, this will take a few weeks to get meaningful data. Even then there will be a lot of variance depending on how many utxos are being eagerly spent within 24 hours vs 1 hour at the time I am measuring.

Someone might also want to test the latency impact (e.g. on block template creation) of the traversal.

I'm not sure I understand what you are suggesting to measure here, or what you mean by traversal. We can measure the total time writing chainstate to disk with -debug=bench, which would be the latency impact if that's what you mean.

Though long term it would be preferable to introduce a data structure to track pending writes and keep a constantly flushing going which always lags the tip by N blocks, both avoiding the latency spikes and preventing unnecessary writes of entries that are just going to be spent in the next couple blocks.

You mentioned a similar idea a while ago here. I agree with you there that it is a much bigger project. If this change is accepted and merged, would there really be a benefit anymore of adding something like that?

[l0rinc]

I'll review this in more detail later, but I have a question first:
Whenever a production change is made without corresponding test changes (yet the build passes), it suggests to me that there might be a gap in our coverage.
Do you think it would make sense to add a test that reproduces some aspect of the old behavior before making the change—one that would need to be updated in the commit that introduces the change?

[andrewtoth]

it would make sense to add a test that reproduces some aspect of the old behavior before making the change—one that would need to be updated in the commit that introduces the change?

Good point, I can add a test that that expects flush every 24 hours, then reduce it to 1 hour after this change.

[DrahtBot]

🚧 At least one of the CI tasks failed.
_{Debug: https://github.com/bitcoin/bitcoin/runs/29514781087}

Hints

Make sure to run all tests locally, according to the documentation.

The failure may 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]

I got some stats for running in steady state for this branch and master.
I ran 4 nodes for 11 days and 18 hours using identical aws t2-small instances backed by 20GB EBS volumes all connected to another node in the same VPC.

Branch	Total time writing chainstate	Total bytes written
master 1	26372ms	497 MiB
master 2	28188ms	497 MiB
branch 1	32496ms	760 MiB
branch 2	32566ms	760 MiB

By writing every hour, we write about 50% more data, but we are only spending 20% more time writing.
On master we write about 42 MiB every 24 hours which locks the main thread for 2.3 seconds.
On this branch we write about 2.7 MiB every hour which locks the main thread for 115 milliseconds.
So it's about 0.9 MiB more data written every hour, which I think is a negligible amount. Note that this extra data is ephemeral and will be erased as these extra utxos are spent. It will not cause nodes to have to store more data.

Here are the write operations charts for the time period. You can see the write operations are more evenly spaced out by writing every hour.

[andrewtoth]

@gmaxwell @l0rinc @mzumsande @sipa thank you all for your reviews! I've updated the PR to have a random window for periodic flushes of between 50 and 70 minutes. I've also added a unit test that checks for a flush in this window. That unit test can be cherry-picked to master and verified that it does not pass.

[l0rinc]

The test runs unreliably for some reason, we need to fix that first.

NACK 5cad9d16dd07859a76c6637789695bf1b4f36e1c

On this branch [...] main thread for 115 milliseconds.

This sounds awesome!

Good point, I can add a test that that expects flush every 24 hours, then reduce it to 1 hour after this change.

Do you think we could still do something like this, i.e. add a test as a very first commit, which reproduces the old behavior first?