From 271252c0bda5779a255f23a73ceb6f722559f0d1 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Fri, 10 Dec 2021 17:12:27 +0100 Subject: [PATCH 1/3] validation, log: extract FlushSnapshotToDisk() function This moves the flushing and logging into one method and adds logging of time duration and memory for the snapshot chainstate flushing. --- src/validation.cpp | 29 ++++++++++++++++++----------- 1 file changed, 18 insertions(+), 11 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index d4203de56ad..0f65f56ca1c 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -4840,6 +4840,20 @@ bool ChainstateManager::ActivateSnapshot( return true; } +static void FlushSnapshotToDisk(CCoinsViewCache& coins_cache, bool snapshot_loaded) +{ + LogPrintf("[snapshot] flushing %s (%.2f MB)... ", /* Continued */ + snapshot_loaded ? "snapshot chainstate to disk" : "coins cache", + coins_cache.DynamicMemoryUsage() / (1000 * 1000)); + + const int64_t flush_now{GetTimeMillis()}; + + // TODO: if #17487 is merged, add erase=false here if snapshot is loaded, for better performance. + coins_cache.Flush(); + + LogPrintf("done (%.2fms)\n", GetTimeMillis() - flush_now); +} + bool ChainstateManager::PopulateAndValidateSnapshot( CChainState& snapshot_chainstate, CAutoFile& coins_file, @@ -4877,7 +4891,6 @@ bool ChainstateManager::PopulateAndValidateSnapshot( uint64_t coins_left = metadata.m_coins_count; LogPrintf("[snapshot] loading coins from snapshot %s\n", base_blockhash.ToString()); - int64_t flush_now{0}; int64_t coins_processed{0}; while (coins_left > 0) { @@ -4921,19 +4934,14 @@ bool ChainstateManager::PopulateAndValidateSnapshot( const auto snapshot_cache_state = WITH_LOCK(::cs_main, return snapshot_chainstate.GetCoinsCacheSizeState()); - if (snapshot_cache_state >= - CoinsCacheSizeState::CRITICAL) { - LogPrintf("[snapshot] flushing coins cache (%.2f MB)... ", /* Continued */ - coins_cache.DynamicMemoryUsage() / (1000 * 1000)); - flush_now = GetTimeMillis(); - + if (snapshot_cache_state >= CoinsCacheSizeState::CRITICAL) { // This is a hack - we don't know what the actual best block is, but that // doesn't matter for the purposes of flushing the cache here. We'll set this // to its correct value (`base_blockhash`) below after the coins are loaded. coins_cache.SetBestBlock(GetRandHash()); - coins_cache.Flush(); - LogPrintf("done (%.2fms)\n", GetTimeMillis() - flush_now); + // No need to acquire cs_main since this chainstate isn't being used yet. + FlushSnapshotToDisk(coins_cache, /*snapshot_loaded=*/false); } } } @@ -4963,9 +4971,8 @@ bool ChainstateManager::PopulateAndValidateSnapshot( coins_cache.DynamicMemoryUsage() / (1000 * 1000), base_blockhash.ToString()); - LogPrintf("[snapshot] flushing snapshot chainstate to disk\n"); // No need to acquire cs_main since this chainstate isn't being used yet. - coins_cache.Flush(); // TODO: if #17487 is merged, add erase=false here for better performance. + FlushSnapshotToDisk(coins_cache, /*snapshot_loaded=*/true); assert(coins_cache.GetBestBlock() == base_blockhash); From 8e37fa83934ad47a4a73c326213e2073dfc35e29 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Fri, 10 Dec 2021 17:16:34 +0100 Subject: [PATCH 2/3] validation, log: improve logging in FlushSnapshotToDisk() Use the `LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE` macro to improve the logging of snapshot persistance and no longer manually track the duration. before [snapshot] flushing coins cache (0 MB)... done (0.00ms) [snapshot] flushing snapshot chainstate to disk (0 MB)... done (0.00ms) after FlushSnapshotToDisk: flushing coins cache (0 MB) started FlushSnapshotToDisk: completed (0.00ms) FlushSnapshotToDisk: saving snapshot chainstate (0 MB) started FlushSnapshotToDisk: completed (0.00ms) The logging can be observed in the output of ./src/test/test_bitcoin -t validation_chainstate_tests -- DEBUG_LOG_OUT --- src/validation.cpp | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index 0f65f56ca1c..d389617582d 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -4842,16 +4842,14 @@ bool ChainstateManager::ActivateSnapshot( static void FlushSnapshotToDisk(CCoinsViewCache& coins_cache, bool snapshot_loaded) { - LogPrintf("[snapshot] flushing %s (%.2f MB)... ", /* Continued */ - snapshot_loaded ? "snapshot chainstate to disk" : "coins cache", - coins_cache.DynamicMemoryUsage() / (1000 * 1000)); - - const int64_t flush_now{GetTimeMillis()}; + LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE( + strprintf("%s (%.2f MB)", + snapshot_loaded ? "saving snapshot chainstate" : "flushing coins cache", + coins_cache.DynamicMemoryUsage() / (1000 * 1000)), + BCLog::LogFlags::ALL); // TODO: if #17487 is merged, add erase=false here if snapshot is loaded, for better performance. coins_cache.Flush(); - - LogPrintf("done (%.2fms)\n", GetTimeMillis() - flush_now); } bool ChainstateManager::PopulateAndValidateSnapshot( From 50209a42ad05e92ad0945fa104c65d2b1f2a2c1c Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Sat, 11 Dec 2021 12:45:11 +0100 Subject: [PATCH 3/3] validation, doc: remove TODO comment It would make for sense for the TODO to be done in PR 17487 (or noted in the review feedback for a follow-up), no need to continue maintaining the TODO in the codebase. --- src/validation.cpp | 1 - 1 file changed, 1 deletion(-) diff --git a/src/validation.cpp b/src/validation.cpp index d389617582d..861831444a2 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -4848,7 +4848,6 @@ static void FlushSnapshotToDisk(CCoinsViewCache& coins_cache, bool snapshot_load coins_cache.DynamicMemoryUsage() / (1000 * 1000)), BCLog::LogFlags::ALL); - // TODO: if #17487 is merged, add erase=false here if snapshot is loaded, for better performance. coins_cache.Flush(); }