validation: improve connect bench logging #24216

pull Sjors wants to merge 1 commits into bitcoin:master from Sjors:2022/01/bench_log changing 1 files +11 −6
  1. Sjors commented at 2:25 pm on January 31, 2022: member
    • 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:

     02022-01-31T14:21:35Z - Connect block: 251.79ms [59.59s (419.65ms/blk)]
 12022-01-31T14:21:35Z   - Using cached block
 22022-01-31T14:21:35Z   - Load block from disk: 0.07ms [9.67s (68.12ms/blk)]
 32022-01-31T14:21:35Z     - Sanity checks: 0.00ms [0.27s (1.87ms/blk)]
 42022-01-31T14:21:35Z     - Fork checks: 0.02ms [0.26s (1.84ms/blk)]
 52022-01-31T14:21:35Z       - Connect 597 transactions: 154.84ms (0.259ms/tx, 0.022ms/txin) [34.89s (243.96ms/blk)]
 62022-01-31T14:21:35Z     - Verify 7043 txins: 169.60ms (0.024ms/txin) [35.67s (249.46ms/blk)]
 72022-01-31T14:21:35Z     - Write undo data: 19.72ms [10.68s (74.68ms/blk)]
 82022-01-31T14:21:35Z     - Index writing: 0.05ms [0.73s (5.12ms/blk)]
 92022-01-31T14:21:35Z   - Connect total: 189.66ms [48.18s (336.93ms/blk)]
102022-01-31T14:21:35Z   - Flush: 5.23ms [1.19s (8.30ms/blk)]
112022-01-31T14:21:35Z   - Writing chainstate: 0.04ms [0.58s (4.03ms/blk)]
122022-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)
132022-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):

     02022-01-31T14:21:35Z - Connect block: 195.27ms [59.79s (418.08ms/blk)]
 12022-01-31T14:21:38Z   - Load block from disk: 23.35ms [9.70s (67.80ms/blk)]
 22022-01-31T14:21:38Z     - Sanity checks: 1.96ms [0.27s (1.87ms/blk)]
 32022-01-31T14:21:38Z     - Fork checks: 0.05ms [0.26s (1.83ms/blk)]
 42022-01-31T14:21:38Z       - Connect 404 transactions: 116.03ms (0.287ms/tx, 0.017ms/txin) [35.00s (243.07ms/blk)]
 52022-01-31T14:21:38Z     - Verify 7031 txins: 119.58ms (0.017ms/txin) [35.79s (248.56ms/blk)]
 62022-01-31T14:21:38Z     - Write undo data: 23.54ms [10.70s (74.33ms/blk)]
 72022-01-31T14:21:38Z     - Index writing: 1.42ms [0.73s (5.09ms/blk)]
 82022-01-31T14:21:38Z   - Connect total: 146.84ms [48.33s (335.61ms/blk)]
 92022-01-31T14:21:38Z   - Flush: 4.84ms [1.19s (8.28ms/blk)]
102022-01-31T14:21:38Z   - Writing chainstate: 0.04ms [0.58s (4.00ms/blk)]
112022-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)
122022-01-31T14:21:38Z   - Connect postprocess: 0.16ms [0.17s (1.16ms/blk)]
  2. DrahtBot added the label Validation on Jan 31, 2022
  3. in src/validation.cpp:1896 in 7ccde3737f outdated 
    1892@@ -1893,6 +1893,7 @@ static int64_t nTimeCheck = 0;
1893 static int64_t nTimeForks = 0;
1894 static int64_t nTimeVerify = 0;
1895 static int64_t nTimeConnect = 0;
1896+static int64_t nTimeUndo = 0;
    jonatack commented at 2:59 pm on January 31, 2022:

    suggestion while here (order of use), if you retouch

    0@@ -1891,8 +1891,8 @@ static unsigned int GetBlockScriptFlags(const CBlockIndex* pindex, const Consens
1 
2 static int64_t nTimeCheck = 0;
3 static int64_t nTimeForks = 0;
4-static int64_t nTimeVerify = 0;
5 static int64_t nTimeConnect = 0;
6+static int64_t nTimeVerify = 0;
7 static int64_t nTimeUndo = 0;
8 static int64_t nTimeIndex = 0;
9 static int64_t nTimeTotal = 0;
  4. jonatack commented at 3:00 pm on January 31, 2022: member
    Code review ACK 7ccde3737fc48e114b19e78fb1d511459dd63dea
  5. Sjors force-pushed on Jan 31, 2022
  6. jonatack commented at 3:36 pm on January 31, 2022: member
    Review ACK cfb027dd1becbc8b3b93504f67eaf76696d65fe8
  7. validation: improve connect bench logging 304ef73c83
  8. Sjors force-pushed on Feb 1, 2022
  9. Sjors commented at 11:00 am on February 1, 2022: member
    OCD rebase now that CI works again, but that seems justified when touching validation.cpp. I mean, when did a log related change ever cause a global meltdown? :-)
  10. fanquake deleted a comment on Feb 26, 2022
  11. theStack approved
  12. theStack commented at 11:01 am on March 1, 2022: member

    Concept and code-review ACK 304ef73c83900a5439cdf8e6f0519471f59444d3

    Note that these two consecutive log messages are contradictary to each other:

    0- Using cached block
1- Load block from disk: ...

    ~In theory one could just suppress the “Load block” message in the cache case since it doesn’t contain any valuable information (measuring the time it takes for merely setting a pointer will always yield a result close to zero). OTOH I don’t know if it’s worth it to make further changes here. The PR is a clear improvement in any case.~ (EDIT) Oh, nevermind, the message also contains the total time spent on loading blocks, so it would be a rather bad idea to not show it in some cases.

  13. Sjors commented at 12:20 pm on March 1, 2022: member
    @theStack I agree the messages are contradictory, but I didn’t want to drop the second message, since others might rely on it.
  14. MarcoFalke added this to the milestone 24.0 on Mar 2, 2022
  15. in src/validation.cpp:2200 in 304ef73c83 
    2195@@ -2192,8 +2196,8 @@ bool CChainState::ConnectBlock(const CBlock& block, BlockValidationState& state,
2196     // add this block to the view's block chain
2197     view.SetBestBlock(pindex->GetBlockHash());
2198 
2199-    int64_t nTime5 = GetTimeMicros(); nTimeIndex += nTime5 - nTime4;
2200-    LogPrint(BCLog::BENCH, "    - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime5 - nTime4), nTimeIndex * MICRO, nTimeIndex * MILLI / nBlocksTotal);
2201+    int64_t nTime6 = GetTimeMicros(); nTimeIndex += nTime6 - nTime5;
2202+    LogPrint(BCLog::BENCH, "    - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime6 - nTime5), nTimeIndex * MICRO, nTimeIndex * MILLI / nBlocksTotal);
    laanwj commented at 1:14 pm on April 5, 2022:

    Can a divide by zero ever occur here?

    Edit: looks like not, nBlocksTotal’s increased in the same function before this. Also the same construction is used in other log lines so we already rely on this.

  16. laanwj commented at 1:20 pm on April 5, 2022: member
    Code review ACK 304ef73c83900a5439cdf8e6f0519471f59444d3
  17. jonatack approved
  18. jonatack commented at 1:32 pm on April 5, 2022: member
    re-ACK 304ef73c83900a5439cdf8e6f0519471f59444d3 per git range-diff 4faf7a1d8 cfb027d 304ef7 rebase only since my last review
  19. laanwj merged this on Apr 5, 2022
  20. laanwj closed this on Apr 5, 2022
  21. sidhujag referenced this in commit f46549fa50 on Apr 5, 2022
  22. Sjors deleted the branch on Apr 5, 2022
  23. DrahtBot locked this on Apr 5, 2023


Sjors jonatack theStack laanwj

Labels
Validation

Milestone
24.0

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-07-01 10:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me