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

50209a42ad validation, doc: remove TODO comment (Jon Atack)
8e37fa8393 validation, log: improve logging in FlushSnapshotToDisk() (Jon Atack)
271252c0bd 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
This commit is contained in:
MarcoFalke
2021-12-13 15:07:11 +01:00

View File

@@ -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);