Use number of dirty cache entries in flush warnings/logs #31703

nit

    size_t GetDirtyCount() const noexcept { return m_num_dirty; }

Done.

This tracepoint was previously recording an estimate of memory usage of the entire cache, now it is an estimate of the disk usage of the dirty entries that were just written. Is that what we want to record here?

cc @0xB10C

Reverted this change.

Hmm now we need to only declare coins_mem_usage if building trace points.

Added [[maybe_unused]], which seems to suffice.

This warning became more useful now - a few questions:

• Would it make sense to mention the coin count and do the warning based on that instead? May be too much information, not sure, it's just an idea:

“Flushing %s dirty coins to disk...”

• If we keep GiB (while double is likely still precise enough for the billions range), I wonder if the users are really interested in fraction of GiB here
• The limit for triggering this has changed here - does the WARN_FLUSH_COINS_SIZE threshold still make sense?

Should we make this consistent with FlushSnapshotToDisk and ChainstateManager::PopulateAndValidateSnapshot as well to log the estimated disk usage based on dirty count instead of DynamicMemoryUsage?

2025-01-22T11:56:22Z FlushSnapshotToDisk: saving snapshot chainstate (27440 MB) started

(and maybe use MiB as well to avoid further confusion) and

2025-01-22T11:56:22Z [snapshot] loaded 176948713 (27440 MB)

This is likely my mistake in #31534, but loading the UTXO set (as described in #31645) will call Flush via FlushSnapshotToDisk at the end (taking a really long time but never warning) https://github.com/bitcoin/bitcoin/blob/master/src/validation.cpp#L5878, reset m_num_dirty = 0 so when we get to FlushStateToDisk (through ActivateSnapshot) we're never warning since coins_dirty_count is always 0.

I have switched everything to be dirty-count based, rather than size-based.

I think that can wait for an independent improvement.

I'm not familiar with the snapshot code.

I posted the steps to reproduce it at #31645 - but we can move this warning to Flush in a different PR to make sure it works for AssumeUTXO as well.

Checked that the current PR displays the warning correctly.

2025-01-22T19:20:54Z UpdateTip: new best=0000000000000000000162ce2492545600d6e6780ee22bf464166a4faa28ba28 height=824665 version=0x32000000 log2_work=94.650129 tx=948674213 date='2024-01-06T21:32:54Z' progress=0.822859 cache=9687.2MiB(67719102txo) ... 2025-01-22T19:20:55Z [warning] Flushing large (67721262 entries) UTXO set to disk, it may take several minutes

I'm not familiar with the snapshot code.

It seems to me that it may make more sense to move the warning to CCoinsViewDB::BatchWrite instead, which could already have m_dirty available through the CoinsViewCacheCursor, and since it's called from Flush and Sync, an AssumeUTXO load-and-dump would also trigger the warning (not just an IBD).

I also don't mind doing it myself in a follow-up, if you think it's a good idea.

To clarify, currently AssumeUTXO doesn't display the warning:

2025-03-18T10:08:47Z [snapshot] 184000000 coins loaded (99.56%, 29332 MB)
2025-03-18T10:08:48Z [snapshot] loaded 184821030 (29456 MB) coins from snapshot 000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880
2025-03-18T10:08:48Z FlushSnapshotToDisk: saving snapshot chainstate (29456 MB) started
2025-03-18T10:09:57Z FlushSnapshotToDisk: completed (69461.66ms)

But if we moved the warning introduced in #31534 into to the method that does the actual long operation it would show the warning for AssumeUTXO case as well (i.e. both for Flush and Sync):

diff --git a/src/coins.h b/src/coins.h
index f897bce749..a23b663a1a 100644
--- a/src/coins.h
+++ b/src/coins.h
@@ -300,6 +300,7 @@ struct CoinsViewCacheCursor
     }
 
     inline bool WillErase(CoinsCachePair& current) const noexcept { return m_will_erase || current.second.coin.IsSpent(); }
+    size_t GetDirtyCount() const noexcept { return m_dirty; }
 private:
     size_t& m_usage;
     size_t& m_dirty;
diff --git a/src/txdb.cpp b/src/txdb.cpp
index 1622039d63..083cab3279 100644
--- a/src/txdb.cpp
+++ b/src/txdb.cpp
@@ -25,6 +25,9 @@ static constexpr uint8_t DB_HEAD_BLOCKS{'H'};
 // Keys used in previous version that might still be found in the DB:
 static constexpr uint8_t DB_COINS{'c'};
 
+// Threshold for warning when writing this many dirty cache entries to disk.
+static constexpr size_t WARN_FLUSH_COINS_COUNT{10'000'000};
+
 bool CCoinsViewDB::NeedsUpgrade()
 {
     std::unique_ptr<CDBIterator> cursor{m_db->NewIterator()};
@@ -109,6 +112,8 @@ bool CCoinsViewDB::BatchWrite(CoinsViewCacheCursor& cursor, const uint256 &hashB
         }
     }
 
+    if (cursor.GetDirtyCount() > WARN_FLUSH_COINS_COUNT) LogWarning("Flushing large (%d entries) UTXO set to disk, it may take several minutes", cursor.GetDirtyCount());
+
     // In the first batch, mark the database as being in the middle of a
     // transition from old_tip to hashBlock.
     // A vector is used for future extensibility, as we may want to support
diff --git a/src/validation.cpp b/src/validation.cpp
index 1f4f2e1ae8..3323a037dc 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -88,8 +88,6 @@ using node::CBlockIndexHeightOnlyComparator;
 using node::CBlockIndexWorkComparator;
 using node::SnapshotMetadata;
 
-/** Threshold for warning when writing this many dirty cache entries to disk. */
-static constexpr size_t WARN_FLUSH_COINS_COUNT = 10'000'000;
 /** Time to wait between writing blocks/block index to disk. */
 static constexpr std::chrono::hours DATABASE_WRITE_INTERVAL{1};
 /** Time to wait between flushing chainstate to disk. */
@@ -2932,7 +2930,6 @@ bool Chainstate::FlushStateToDisk(
         }
         // Flush best chain related state. This can only be done if the blocks / block index write was also done.
         if (fDoFullFlush && !CoinsTip().GetBestBlock().IsNull()) {
-            if (coins_dirty_count >= WARN_FLUSH_COINS_COUNT) LogWarning("Flushing large (%d entries) UTXO set to disk, it may take several minutes", coins_dirty_count);
             LOG_TIME_MILLIS_WITH_CATEGORY(strprintf("write coins cache to disk (%d out of %d cached coins)",
                 coins_dirty_count, coins_count), BCLog::BENCH);

Reproducer:

cmake -B build -DCMAKE_BUILD_TYPE=Release && cmake --build build -j$(nproc)
mkdir -p demo && rm -rfd demo/chainstate demo/chainstate_snapshot demo/debug.log
build/bin/bitcoind -datadir=demo -stopatheight=1
build/bin/bitcoind -datadir=demo -daemon -blocksonly=1 -connect=0 -dbcache=30000
build/bin/bitcoin-cli -datadir=demo -rpcclienttimeout=0 loadtxoutset ~/utxo-880000.dat
build/bin/bitcoin-cli -datadir=demo stop

Result:

2025-03-18T09:59:40Z [snapshot] 184000000 coins loaded (99.56%, 29332 MB)
2025-03-18T09:59:41Z [snapshot] loaded 184821030 (29456 MB) coins from snapshot 000000000000000000010b17283c3c400507969a9c2afd1dcf2082ec5cca2880
2025-03-18T09:59:41Z FlushSnapshotToDisk: saving snapshot chainstate (29456 MB) started
*2025-03-18T09:59:41Z [warning] Flushing large (184821030 entries) UTXO set to disk, it may take several minutes*
2025-03-18T10:00:50Z FlushSnapshotToDisk: completed (68776.27ms)

Would it be simpler if I pushed this change in a separate PR instead?

We're already in a Cache object, maybe we could clarify that this is a running count:

    /* Running count of dirty Coin entries. */

Done.

I understand that the hard-coded value was here before, and was wondering if we could explain how we got to this magic number (and not mention the value in comments at all since code can express that better), maybe something like:

static constexpr size_t COIN_DISK_USAGE_BYTES{sizeof(Coin)}; // Approximate size on disk

Loading the UTXO set to memory:

2025-01-22T11:56:22Z [snapshot] loaded 176948713 (27440 MB) coins from snapshot 0000000000000000000320283a032748cef8227873ff4872689bf23f1cda83a5

and checking the resulting disk size:

du -sk /Users/lorinc/IdeaProjects/bitcoin/demo/chainstate_snapshot | cut -f1
11524472

Suggests we may want to add a ~40% overhead here:

((11524472*1024)/176948713)/48

i.e.

static constexpr size_t COIN_DISK_USAGE_BYTES{static_cast<size_t>(sizeof(Coin) * 1.4)}; // Approximate size on disk

Estimating sizes of the UTXO set is hard, because these are all very distinct numbers:

• The size on disk in a snapshot of a UTXO set
• The size on disk in the chainstate LevelDB database (the database has different per-entry overhead, prefix compression, bloom filters, ...).
• The amount of data that will be written to disk to flush a number of dirty entries (because e.g. writing a removal/spending of a UTXO temporarily takes up space in the log before it's compacted into the tables)
• The amount of memory a UTXO entry takes up in RAM (as approximated by DynamicMemoryUsage()).

If we actually care about disk sizes, we should actually try to estimate the thing we care about, and not use snapshot size as a proxy.

I understand that it's complex, but we seem to be off here by 40% - I don't mind if we tackle that in a separate PR/issue and would appreciate your opinion on how to handle this better.

I don't understand why you're looking at snapshot size at all, that's not a good measure of data written. We may be off by a lot more, or a lot less. If we want to do better, we should look at how much is actually written, and then add to CCoinsViewCache a way to predict that number. None of that seems a good fit for this PR, though.

I don't understand why you're looking at snapshot size

not a good measure of data written

and not use snapshot size as a proxy

I understand that the dirty entries in the snapshot are not a perfect representation (except for the AssumeUTXO tests I was doing, which likely skewed my recommendations), but I though it's what we're already doing here when we're calculating "approx_disk_usage" from "coins_dirty_count".

None of that seems a good fit for this PR, though

I agree, if we want a better representation. But replacing the magic 48 with sizeof(Coin) could be. But I'm also fine if not, it's just an alternative that I found.

given that this is mainly used for logging, do we want to crash the client when this isn't accurate?

Changed to Assume.

Nit 1: num doesn't obviate what the number represents, just its type. It could mean bytes or count or an int representation of a boolean. Given that in other cases we called this DirtyCount, could we use that here as well? Nit 2: not sure it matters, but in other cases here we didn't add the "Get" prefix, I don't see the value it adds (and it kinda' gets confusing when we're mutating it in SingleEntryCacheTest), might as well trim it I guess.

    size_t& DirtyCount() const { return m_dirty_count; }

Changed to m_dirty_count and GetDirtyCount() everywhere.

Super-nit: m_num_dirty increment is related to the SetDirty call, not the Clear call, if you think it makes sense, we could group them as such (like we do in EmplaceCoinInternalDANGER and BatchWrite)

Done.

I don't mind either the conditional increment or the implicit boolean-to-int conversion, but I get distracted when both are used without an easy to understand reason. Unless there's a good reason here, could we change this to:

        m_dirty -= current.second.IsDirty();

Done.

Nit: it's test code so it's not super-important, but we're basically returning the state of a modified parameter here - seems a bit hacky to me. I think we could return the same value as before and call IsDirty() on the call site, e.g.

size_t usage{cache_coin ? InsertCoinsMapEntry(map, sentinel, *cache_coin) : 0};
size_t dirty{cache_coin->IsDirty()};

and

cache.usage() += InsertCoinsMapEntry(cache.map(), cache.sentinel(), *cache_coin);
cache.GetNumDirty() += cache_coin->IsDirty();

Done.

Slightly unrelated, but we probably need something similar for memory as well. Currently, there's no explicit warning when -dbcache is set to a value exceeding available system memory (especially problematic after #28358). A similar warning in this scenario would be very helpful - but likely outside the scope of this PR.

It took me a while to understand this one - still not sure I follow completely.

I've reworked it a bit. LMK if it's clearer now.

Yes, thank you. The only remaining nit is that in other cases we set it dirty first, before incrementing (edit: to obviate that the call doesn't rely on the value of m_dirty_count).

We're modifying m_num_dirty multiple times in the AddCoin method, possibly even cancelling out previous modifications. If it's not too involved, could we calculate the final diff and only update it a single time in this method for clarity? Same applies to SpendCoin.

Before we merge I'd like to run a full IBD with SanityCheck enabled throughout the code - can you recommend other settings that I should enable?

Anything that involves a reorg would perhaps be interesting to test.

I ran an IBD until 800k with -DCMAKE_BUILD_TYPE=Debug for the current PR (it's really slow this way) - no issues found.

a reorg would perhaps be interesting to test

Do we have a way of triggering random reorgs during IBD (at least undo/redo style)? If not, would it be helpful to create a PR that adds a hidden -simulatereorgonibd argument (similarly to -dbcrashratio) that randomly triggers small, temporary reorgs during IBD on mainnet? Specifically, at a random height between every ~[10,000, 100,000] blocks, we disconnect and reconnect ~[1, 100] blocks (favoring smaller counts), performing a CoinsTip#SanityCheck() before and after (and maybe validating that we have the UTXOs in cache that will be removed, asserting after undo that they're missing, and revalidating after reapplication that they're back in cache). This would test reorg logic in a semi-realistic scenario - though it wouldn't stress diverging chains, as it reconnects the same blocks.

Alternatively, we could collect a few hundred stale blocks (found 219 raw blocks so far via https://github.com/bitcoin-data/stale-blocks and https://learnmeabitcoin.com) and create a stale-block-proxy node for end-to-end regression testing of reorgs with historical data:

• A freshly built test node would connect only to this proxy, which would simulate the original chain forks.
• It serves headers & blocks exactly as they were originally seen (without storing them, requesting non-stale ones from the network).
• The proxy pretends a stale block is the tip, letting the test node sync up to it.
• Once the test node reaches that stale block, the proxy sets the next stale block as the new tip, triggering a natural reorg.

Would that work and be a useful way to test reorg behavior during IBD?

I will do this later to test reorg behavior in a functional test, you can resolve this comment.

I guess we can't just inline this, but maybe we can guard it with #ifdef ENABLE_TRACING alternatively

I think [[maybe_unused]] is fine.

Sure, though this won't warn us if it actually becomes unused.

This now hides GetDirtyCount in CCoinsViewCache with a size_t return value (changed to size_t& here), used later as cache.usage() += and cache.GetDirtyCount() +=.

To avoid the confusing override and the method return value assignment, please consider making them explicit setters/adders:

void AddUsage(size_t usage) const { cachedCoinsUsage += usage; }
void AddDirtyCount(size_t count) const { m_dirty_count += count; }

cache.AddUsage(InsertCoinsMapEntry(cache.map(), cache.sentinel(), *cache_coin));
cache.AddDirtyCount(cache_coin->IsDirty());

👍 10m seems like a good approximation for the previous value:

2025-01-31T09:45:42Z UpdateTip: new best=0000000000000000cc22cc938f92ecc3a3844f23775c4ad4e66404563c8594c8 height=287000 version=0x00000002 log2_work=76.752105 tx=33340892 date='2014-02-2 1T05:18:42Z' progress=0.028794 cache=1245.8MiB(10004443txo)

This change doesn't seem to be covered by coins_tests at all. Can we extend SimulationTest to call stack.back()->EmplaceCoinInternalDANGER instead of AddCoin randomly?

Maybe something like:

if (COutPoint op(txid, 0); !stack.back()->map().contains(op) && !(coin.IsSpent() || (m_rng.rand32() & 1))) {
    stack.back()->EmplaceCoinInternalDANGER(std::move(op), std::move(newcoin));
} else {
    stack.back()->AddCoin(std::move(op), std::move(newcoin), /*possible_overwrite=*/(!coin.IsSpent() || (m_rng.rand32() & 1)));
}

The documentation of EmplaceCoinInternalDANGER claims that:

Emplace a coin into cacheCoins without performing any checks, marking the emplaced coin as dirty.

How come we're updating cachedCoinsUsage unconditionally in this method - but m_dirty_count only when inserted?

That's a bug from #28280. It should be done conditionally. I fix it in the first commit of #31132. The only caller of this method will not add coins that already exist in the cache though, so it will always enter the if (inserted) block.

Thanks for validating it, I only noticed it now, when trying to test EmplaceCoinInternalDANGER in SimulationTest

Following @andrewtoth's solution we can do:

void CCoinsViewCache::EmplaceCoinInternalDANGER(COutPoint&& outpoint, Coin&& coin) {
    const auto mem_usage{coin.DynamicMemoryUsage()};
    auto [it, inserted] = cacheCoins.try_emplace(std::move(outpoint), std::move(coin));
    if (inserted) {
        cachedCoinsUsage += mem_usage;
        CCoinsCacheEntry::SetDirty(*it, m_sentinel);
        ++m_dirty_count;
    }
}

nit: parameters slightly unaligned with first parameter

Do we still need to track CCoinsViewDB::BatchWrite#changed now that we're tracking dirty count already? I think we should be able to use the new m_dirty(_count) there instead, i.e. something like:

size_t dirty_count{cursor.GetDirtyCount()};
size_t changed{0};
...
if (dirty_count > WARN_FLUSH_COINS_COUNT) LogWarning("Flushing large (%d entries) UTXO set to disk, it may take several minutes", dirty_count);
...
assert(changed == dirty_count); // TODO remove `changed` after all scenarios pass
LogDebug(BCLog::COINDB, "Committed %u changed transaction outputs (out of %u) to coin database...", (unsigned int)dirty_count, (unsigned int)count);

For me locally this passes all tests, quick IBD (ran it with -dbcache=5 -maxmempool=5 -stopatheight=120000), reindex and AssumeUTXO.

I don't mind if we're mixing booleans and ints as long as the types and names are obvious, e.g.

size_t dirty = cache_coin ? cache_coin->IsDirty() : 0;
auto cursor{CoinsViewCacheCursor(usage, dirty, sentinel, map, /*will_erase=*/true)};

where we're setting a parameter called dirty to the result of IsDirty, but it gets converted to dirty count. We could obviate this by calling it dirty_count here as well:

    CoinsViewCacheCursor(size_t& usage LIFETIMEBOUND,
                         size_t& dirty_count LIFETIMEBOUND,
                         CoinsCachePair& sentinel LIFETIMEBOUND,
                         CCoinsMap& map LIFETIMEBOUND,
                         bool will_erase) noexcept
        : m_usage(usage), m_dirty_count(dirty_count), m_sentinel(sentinel), m_map(map), m_will_erase(will_erase) {}

This could also be useful to avoid the needless DB_HEAD_BLOCKS erase and rewrite for empty batches.

leftover num_dirty (& other comments here end with fullstop)

        // Recompute m_dirty_count.

Leftover num_dirty

in other cases we set it to dirty first and only increment m_dirty_count after (shouldn't matter on single thread but at least we don't have to think about whether that's the case or not):

                    CCoinsCacheEntry::SetDirty(*itUs, m_sentinel);
                    ++m_dirty_count;

It seems https://github.com/bitcoin/bitcoin/pull/32602/files#diff-1ef3b6a1936b50f3d5ec4a1786d9e2d63d1a3e1815b103e67f20601995f355b4R312-R321 revealed that there's a silent conflict here, we need the first commit from #32313 for this to pass after rebase