Merge #16805: logs: add timing information to FlushStateToDisk()

dcef9a2922317cb2849f397366b6c56d755db6c9 logs: add timing information to FlushStateToDisk() (James O'Beirne)
41edaf227a69bc4846d5996675e8763fdfe0f367 logs: add BCLog::Timer and related macros (James O'Beirne)

Pull request description:

  It's currently annoying to detect FlushStateToDisk() calls when benchmarking since they have to be inferred from a drop in coins count from the `UpdateTip: ` log messages. This adds a new logging utility, `BCLog::Timer`, and some related macros that are generally useful for printing timing-related logging messages, and a message that is unconditionally written when the coins cache is flushed to disk.

  ```
  2019-09-04T20:17:51Z FlushStateToDisk: write block and undo data to disk completed (3ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write block index to disk completed (370ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write coins cache to disk (2068451 coins, 294967kB) completed (21481ms)
  ```

ACKs for top commit:
  laanwj:
    Thanks, ACK dcef9a2922317cb2849f397366b6c56d755db6c9
  ryanofsky:
    Code review ACK dcef9a2922317cb2849f397366b6c56d755db6c9. No changes since last review other than moving code to new timer.h header

Tree-SHA512: 6d61e48a062d3edb48d0e056a6f0b1f8031773cc99289ee4544f8349d24526b88519e1e304009d56e428f1eaf76c857bf8e7e1c0b6873a6f270306accb5edc3d

1 files changed, 26 insertions, 3 deletions

diff --git a/src/validation.cpp b/src/validation.cpp
index 11072b6038..01803223d1 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -18,6 +18,8 @@
 #include <flatfile.h>
 #include <hash.h>
 #include <index/txindex.h>
+#include <logging.h>
+#include <logging/timer.h>
 #include <policy/fees.h>
 #include <policy/policy.h>
 #include <policy/settings.h>
@@ -2199,6 +2201,10 @@ bool CChainState::FlushStateToDisk(
     static int64_t nLastFlush = 0;
     std::set<int> setFilesToPrune;
     bool full_flush_completed = false;
+
+    const size_t coins_count = CoinsTip().GetCacheSize();
+    const size_t coins_mem_usage = CoinsTip().DynamicMemoryUsage();
+
     try {
     {
         bool fFlushForPrune = false;
@@ -2206,8 +2212,12 @@ bool CChainState::FlushStateToDisk(
         LOCK(cs_LastBlockFile);
         if (fPruneMode && (fCheckForPruning || nManualPruneHeight > 0) && !fReindex) {
             if (nManualPruneHeight > 0) {
+                LOG_TIME_MILLIS("find files to prune (manual)", BCLog::BENCH);
+
                 FindFilesToPruneManual(setFilesToPrune, nManualPruneHeight);
             } else {
+                LOG_TIME_MILLIS("find files to prune", BCLog::BENCH);
+
                 FindFilesToPrune(setFilesToPrune, chainparams.PruneAfterHeight());
                 fCheckForPruning = false;
             }
@@ -2246,10 +2256,17 @@ bool CChainState::FlushStateToDisk(
             if (!CheckDiskSpace(GetBlocksDir())) {
                 return AbortNode(state, "Disk space is too low!", _("Error: Disk space is too low!").translated, CClientUIInterface::MSG_NOPREFIX);
             }
-            // First make sure all block and undo data is flushed to disk.
-            FlushBlockFile();
+            {
+                LOG_TIME_MILLIS("write block and undo data to disk", BCLog::BENCH);
+
+                // First make sure all block and undo data is flushed to disk.
+                FlushBlockFile();
+            }
+
             // Then update all block file information (which may refer to block and undo files).
             {
+                LOG_TIME_MILLIS("write block index to disk", BCLog::BENCH);
+
                 std::vector<std::pair<int, const CBlockFileInfo*> > vFiles;
                 vFiles.reserve(setDirtyFileInfo.size());
                 for (std::set<int>::iterator it = setDirtyFileInfo.begin(); it != setDirtyFileInfo.end(); ) {
@@ -2267,12 +2284,18 @@ bool CChainState::FlushStateToDisk(
                 }
             }
             // Finally remove any pruned files
-            if (fFlushForPrune)
+            if (fFlushForPrune) {
+                LOG_TIME_MILLIS("unlink pruned files", BCLog::BENCH);
+
                 UnlinkPrunedFiles(setFilesToPrune);
+            }
             nLastWrite = nNow;
         }
         // Flush best chain related state. This can only be done if the blocks / block index write was also done.
         if (fDoFullFlush && !CoinsTip().GetBestBlock().IsNull()) {
+            LOG_TIME_SECONDS(strprintf("write coins cache to disk (%d coins, %.2fkB)",
+                coins_count, coins_mem_usage / 1000));
+
             // Typical Coin structures on disk are around 48 bytes in size.
             // Pushing a new one to the database can cause it to be written
             // twice (once in the log, and once in the tables). This is already