validation, log: improve logging in FlushSnapshotToDisk()

jonatack · jonatack · commit 8e37fa83934a · 2021-12-10T22:32:41.000+01:00
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
diff --git 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(
