Merge bitcoin/bitcoin#23738: validation, log: improve logging of ChainstateManager snapshot persistance

50209a42ad05e92ad0945fa104c65d2b1f2a2c1c validation, doc: remove TODO comment (Jon Atack)
8e37fa83934ad47a4a73c326213e2073dfc35e29 validation, log: improve logging in FlushSnapshotToDisk() (Jon Atack)
271252c0bda5779a255f23a73ceb6f722559f0d1 validation, log: extract FlushSnapshotToDisk() function (Jon Atack)

Pull request description:

  Use the `LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE` macro to improve the logging of ChainstateManager snapshot persistance, log task start and completion separately and no longer manually track the duration, as suggested by Marco Falke in https://github.com/bitcoin/bitcoin/pull/22872#discussion_r715571280.

  Extract the flushing into one function, which clarifies the logic, extends the improved logging to both flushing call sites, and allows logging the prefix `FlushSnapshotToDisk`, which is similar to `FlushStateToDisk`.

  before
  ```
  [snapshot] flushing coins cache (0 MB)... done (0.00ms)

  [snapshot] flushing snapshot chainstate to disk
  ```
  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
  ```

Top commit has no ACKs.

Tree-SHA512: 5d954cd8c7455f8625152a43663a237f04717bb834aed62925a56e17c711fca6ccfc03783970b6b0bde44f64617d804b423a7048287c06ee816db36247acf272

1 files changed, 15 insertions, 11 deletions

diff --git a/src/validation.cpp b/src/validation.cpp
index d4203de56a..861831444a 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -4840,6 +4840,17 @@ bool ChainstateManager::ActivateSnapshot(
     return true;
 }
 
+static void FlushSnapshotToDisk(CCoinsViewCache& coins_cache, bool snapshot_loaded)
+{
+    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);
+
+    coins_cache.Flush();
+}
+
 bool ChainstateManager::PopulateAndValidateSnapshot(
     CChainState& snapshot_chainstate,
     CAutoFile& coins_file,
@@ -4877,7 +4888,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 +4931,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 +4968,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);