Add benchmark-block command

[ggwpez]

Deja vu! The code that I originally wanted to use for #10977 is now put to better use.

This command helps in gauging the precision or our benchmarking.
It compares the time that it takes to execute a block to its consumed weight. Ideally they are the same.

Example with a CPU intensive hand-crafted block where our benchmarking worked well:

Block 2 with     2 tx used 102.39% of its weight ( 1,281,193,264 of 1,251,309,762  ns) - OVER WEIGHT!

Or some empty blocks where we over-estimate:

Block 1 with     1 tx used  65.03% of its weight (     4,464,209 of      6,864,645 ns)    
Block 2 with     1 tx used  65.15% of its weight (     4,472,344 of      6,864,645 ns)    
Block 3 with     1 tx used  64.27% of its weight (     4,492,493 of      6,989,645 ns)

There are rust docs on the BlockCmd type with an example on how to invoke it.
In the future this could be used to setup some live monitoring where each day we re-execute the blocks of the past 24h to see which ones are over weight (bad).

Follow ups moved here: paritytech/polkadot-sdk#391

[shawntabrizi]

this is way better than i hoped!

[kianenigma]

LGTM, but a minor existential question I have is that why is this not part of the same check-block command that we have that is capable of re-importing old blocks? if you run with -lruntime=debug, you already get the consumed weight that was recorded onchain, and you can time and compare it with the check-block command again.

I can see some benefit in having a custom command be easier to deal with and extend, but was the alternative considered?

[ggwpez]

Very good question! I initially had a look at that code, but did not think about extending it.

Analyzing again; check-block uses the import queue, and that has a fast path, just returning with Block already in chain.
Visible with -lsync=trace:

substrate --dev -d /tmp/dev
substrate check-block 1 --dev -d /tmp/dev --pruning archive -lsync=trace

# prints
Scheduling 1 blocks for import    
Starting import of 1 blocks  (1)    
Header 0x7e5d…ca03 has 3 logs    
Block already in chain 1: 0x7e5d3a...
Block imported successfully Some(1) (0x7e5d…ca03) 

So it does not actually re-execute the block, but returns quickly since the block is already known-good.

[ggwpez]

bot rebase

[paritytech-processbot]

Rebasing

[ggwpez]

bot rebase

[paritytech-processbot]

Rebasing

[ggwpez]

bot merge