Merge bitcoin/bitcoin#24216: validation: improve connect bench logging

304ef73c83900a5439cdf8e6f0519471f59444d3 validation: improve connect bench logging (Sjors Provoost)

Pull request description:

  * mention when we're using a cached block rather than actually loading it from disk
  * add ms/blk to load block from disk
  * log writing of Undo data, so it's tracked separate from writing indexes

  Example outputs from `src/bitcoind -debug=bench` during IBD.

  When the pass the block in memory:

  ```
  2022-01-31T14:21:35Z - Connect block: 251.79ms [59.59s (419.65ms/blk)]
  2022-01-31T14:21:35Z   - Using cached block
  2022-01-31T14:21:35Z   - Load block from disk: 0.07ms [9.67s (68.12ms/blk)]
  2022-01-31T14:21:35Z     - Sanity checks: 0.00ms [0.27s (1.87ms/blk)]
  2022-01-31T14:21:35Z     - Fork checks: 0.02ms [0.26s (1.84ms/blk)]
  2022-01-31T14:21:35Z       - Connect 597 transactions: 154.84ms (0.259ms/tx, 0.022ms/txin) [34.89s (243.96ms/blk)]
  2022-01-31T14:21:35Z     - Verify 7043 txins: 169.60ms (0.024ms/txin) [35.67s (249.46ms/blk)]
  2022-01-31T14:21:35Z     - Write undo data: 19.72ms [10.68s (74.68ms/blk)]
  2022-01-31T14:21:35Z     - Index writing: 0.05ms [0.73s (5.12ms/blk)]
  2022-01-31T14:21:35Z   - Connect total: 189.66ms [48.18s (336.93ms/blk)]
  2022-01-31T14:21:35Z   - Flush: 5.23ms [1.19s (8.30ms/blk)]
  2022-01-31T14:21:35Z   - Writing chainstate: 0.04ms [0.58s (4.03ms/blk)]
  2022-01-31T14:21:35Z UpdateTip: new best=0000000000000000000b94a079a58d64f640f66b0cc338b5831b94c8739439a6 height=660135 version=0x20a00000 log2_work=92.494955 tx=593512887 date='2020-12-06T01:43:07Z' progress=0.850804 cache=138.8MiB(1031560txo)
  2022-01-31T14:21:35Z   - Connect postprocess: 0.26ms [0.17s (1.17ms/blk)]
  ```

  When we have to load the block from disk (when blocks are received out of order, they are saved after initial validation steps and then loaded again for the final validation steps and connecting to tip):

  ```
  2022-01-31T14:21:35Z - Connect block: 195.27ms [59.79s (418.08ms/blk)]
  2022-01-31T14:21:38Z   - Load block from disk: 23.35ms [9.70s (67.80ms/blk)]
  2022-01-31T14:21:38Z     - Sanity checks: 1.96ms [0.27s (1.87ms/blk)]
  2022-01-31T14:21:38Z     - Fork checks: 0.05ms [0.26s (1.83ms/blk)]
  2022-01-31T14:21:38Z       - Connect 404 transactions: 116.03ms (0.287ms/tx, 0.017ms/txin) [35.00s (243.07ms/blk)]
  2022-01-31T14:21:38Z     - Verify 7031 txins: 119.58ms (0.017ms/txin) [35.79s (248.56ms/blk)]
  2022-01-31T14:21:38Z     - Write undo data: 23.54ms [10.70s (74.33ms/blk)]
  2022-01-31T14:21:38Z     - Index writing: 1.42ms [0.73s (5.09ms/blk)]
  2022-01-31T14:21:38Z   - Connect total: 146.84ms [48.33s (335.61ms/blk)]
  2022-01-31T14:21:38Z   - Flush: 4.84ms [1.19s (8.28ms/blk)]
  2022-01-31T14:21:38Z   - Writing chainstate: 0.04ms [0.58s (4.00ms/blk)]
  2022-01-31T14:21:38Z UpdateTip: new best=00000000000000000004c2cad14fec645807ce236f8e1cc43fe106ee4f27692e height=660136 version=0x2000e000 log2_work=92.494972 tx=593513291 date='2020-12-06T01:46:08Z' progress=0.850804 cache=139.4MiB(1036010txo)
  2022-01-31T14:21:38Z   - Connect postprocess: 0.16ms [0.17s (1.16ms/blk)]
  ```

ACKs for top commit:
  laanwj:
    Code review ACK 304ef73c83900a5439cdf8e6f0519471f59444d3
  theStack:
    Concept and code-review ACK 304ef73c83900a5439cdf8e6f0519471f59444d3
  jonatack:
    re-ACK 304ef73c83900a5439cdf8e6f0519471f59444d3 per `git range-diff 4faf7a1d8 cfb027d 304ef7` rebase only since my last review

Tree-SHA512: 2009e1db3c30eacd15c11629903334eda4f016da614afe2a1275d00c2a80d42e37edb10e79ceb58b3bd8855e7c6915e67d455aec15f73a25f48f48f64aa51a29

1 files changed, 11 insertions, 6 deletions

diff --git a/src/validation.cpp b/src/validation.cpp
index 6db13f1f70..de52610def 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -1896,8 +1896,9 @@ static unsigned int GetBlockScriptFlags(const CBlockIndex& block_index, const Co
 
 static int64_t nTimeCheck = 0;
 static int64_t nTimeForks = 0;
-static int64_t nTimeVerify = 0;
 static int64_t nTimeConnect = 0;
+static int64_t nTimeVerify = 0;
+static int64_t nTimeUndo = 0;
 static int64_t nTimeIndex = 0;
 static int64_t nTimeTotal = 0;
 static int64_t nBlocksTotal = 0;
@@ -2191,6 +2192,9 @@ bool CChainState::ConnectBlock(const CBlock& block, BlockValidationState& state,
         return false;
     }
 
+    int64_t nTime5 = GetTimeMicros(); nTimeUndo += nTime5 - nTime4;
+    LogPrint(BCLog::BENCH, "    - Write undo data: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime5 - nTime4), nTimeUndo * MICRO, nTimeUndo * MILLI / nBlocksTotal);
+
     if (!pindex->IsValid(BLOCK_VALID_SCRIPTS)) {
         pindex->RaiseValidity(BLOCK_VALID_SCRIPTS);
         m_blockman.m_dirty_blockindex.insert(pindex);
@@ -2200,8 +2204,8 @@ bool CChainState::ConnectBlock(const CBlock& block, BlockValidationState& state,
     // add this block to the view's block chain
     view.SetBestBlock(pindex->GetBlockHash());
 
-    int64_t nTime5 = GetTimeMicros(); nTimeIndex += nTime5 - nTime4;
-    LogPrint(BCLog::BENCH, "    - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime5 - nTime4), nTimeIndex * MICRO, nTimeIndex * MILLI / nBlocksTotal);
+    int64_t nTime6 = GetTimeMicros(); nTimeIndex += nTime6 - nTime5;
+    LogPrint(BCLog::BENCH, "    - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime6 - nTime5), nTimeIndex * MICRO, nTimeIndex * MILLI / nBlocksTotal);
 
     TRACE6(validation, block_connected,
         block_hash.data(),
@@ -2540,7 +2544,7 @@ bool CChainState::DisconnectTip(BlockValidationState& state, DisconnectedBlockTr
     return true;
 }
 
-static int64_t nTimeReadFromDisk = 0;
+static int64_t nTimeReadFromDiskTotal = 0;
 static int64_t nTimeConnectTotal = 0;
 static int64_t nTimeFlush = 0;
 static int64_t nTimeChainState = 0;
@@ -2608,13 +2612,14 @@ bool CChainState::ConnectTip(BlockValidationState& state, CBlockIndex* pindexNew
         }
         pthisBlock = pblockNew;
     } else {
+        LogPrint(BCLog::BENCH, "  - Using cached block\n");
         pthisBlock = pblock;
     }
     const CBlock& blockConnecting = *pthisBlock;
     // Apply the block atomically to the chain state.
-    int64_t nTime2 = GetTimeMicros(); nTimeReadFromDisk += nTime2 - nTime1;
+    int64_t nTime2 = GetTimeMicros(); nTimeReadFromDiskTotal += nTime2 - nTime1;
     int64_t nTime3;
-    LogPrint(BCLog::BENCH, "  - Load block from disk: %.2fms [%.2fs]\n", (nTime2 - nTime1) * MILLI, nTimeReadFromDisk * MICRO);
+    LogPrint(BCLog::BENCH, "  - Load block from disk: %.2fms [%.2fs (%.2fms/blk)]\n", (nTime2 - nTime1) * MILLI, nTimeReadFromDiskTotal * MICRO, nTimeReadFromDiskTotal * MILLI / nBlocksTotal);
     {
         CCoinsViewCache view(&CoinsTip());
         bool rv = ConnectBlock(blockConnecting, state, pindexNew, view);