Skip to content

validation: improve connect bench logging #24216

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Merged
laanwj merged 1 commit into from
Apr 5, 2022
Merged

validation: improve connect bench logging #24216

laanwj merged 1 commit into from
Apr 5, 2022
+11 −6

Conversation

@Sjors
Copy link
Member

@Sjors Sjors commented Jan 31, 2022

  • 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)]

jonatack
jonatack reviewed Jan 31, 2022
View reviewed changes
Copy link
Member

@jonatack jonatack left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code review ACK 7ccde3737fc48e114b19e78fb1d511459dd63dea

@Sjors Sjors force-pushed the 2022/01/bench_log branch from 7ccde37 to cfb027d Compare January 31, 2022 15:09
@jonatack
Copy link
Member

jonatack commented Jan 31, 2022

Review ACK cfb027dd1becbc8b3b93504f67eaf76696d65fe8

@Sjors Sjors force-pushed the 2022/01/bench_log branch from cfb027d to 304ef73 Compare February 1, 2022 10:58
@Sjors
Copy link
Member Author

Sjors commented Feb 1, 2022 •
edited
Loading

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? :-)

@bitcoin bitcoin deleted a comment from calbearox Feb 26, 2022
theStack
theStack approved these changes Mar 1, 2022
View reviewed changes
Copy link
Contributor

@theStack theStack left a comment •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Concept and code-review ACK 304ef73

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

- Using cached block
- 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.

@Sjors
Copy link
Member Author

Sjors commented Mar 1, 2022

@theStack I agree the messages are contradictory, but I didn't want to drop the second message, since others might rely on it.

@maflcko maflcko added this to the 24.0 milestone Mar 2, 2022
laanwj
laanwj reviewed Apr 5, 2022
View reviewed changes
@laanwj
Copy link
Member

laanwj commented Apr 5, 2022 •
edited
Loading

Code review ACK 304ef73

jonatack
jonatack approved these changes Apr 5, 2022
View reviewed changes
Copy link
Member

@jonatack jonatack left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

re-ACK 304ef73 per git range-diff 4faf7a1d8 cfb027d 304ef7 rebase only since my last review

@laanwj laanwj merged commit 9ce1c50 into bitcoin:master Apr 5, 2022
sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Apr 5, 2022
@laanwj
Merge bitcoin#24216: validation: improve connect bench logging
f46549f
@Sjors Sjors deleted the 2022/01/bench_log branch April 5, 2022 19:13
@bitcoin bitcoin locked and limited conversation to collaborators Apr 5, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Reviewers

@laanwj laanwj laanwj left review comments

+2 more reviewers

@theStack theStack theStack approved these changes

@jonatack jonatack jonatack approved these changes

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

Validation

Projects

None yet

Milestone

24.0

Development

Successfully merging this pull request may close these issues.

6 participants

@Sjors @jonatack @laanwj @theStack @maflcko @DrahtBot