tracking block exec and node sync performance

[jchappelow]

This discussion can serve as a place to track node performance, particular w.r.t. block sync.

In blocksync (catchup of sentry, for example), here's a reference data point for block execution speed:

2025-01-13 14:08:04.504 [INF] CONS: Requesting block from network(replay mode) {height=1}
2025-01-13 14:08:04.504 [INF] NODE: requesting block number 1 from 16Uiu2HAkx2kfP117VnYnaQGprgXBoMpjfxGXCpizju3cX7ZUzRhv
2025-01-13 14:08:04.505 [INF] NODE: obtained block contents {height=1 elapsed=685.065µs}
2025-01-13 14:08:04.505 [INF] CONS: Processing committed block {height=1 hash=294ab59348e32fa3f5ab93cfd4739259373e3bd26f49288553c2f84c297b5467 appHash=2d8f3ceeff2c836527da823d7b654d33d3e44b6159b172235c160001e0c9b4db}
2025-01-13 14:08:04.534 [INF] BP: Consensus updates {hash=df3f619804a92fdb4057192dc43dd748ea778adc52bc498ce80524c014b81119 updates=null}
2025-01-13 14:08:04.534 [INF] BP: AppState updates:  {prevAppHash=0000000000000000000000000000000000000000000000000000000000000000 changesetsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 valUpdatesHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 accountsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 txResultsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 paramUpdatesHash=df3f619804a92fdb4057192dc43dd748ea778adc52bc498ce80524c014b81119}
2025-01-13 14:08:04.534 [INF] BP: Executed Block {height=1 blkHash=294ab59348e32fa3f5ab93cfd4739259373e3bd26f49288553c2f84c297b5467 appHash=2d8f3ceeff2c836527da823d7b654d33d3e44b6159b172235c160001e0c9b4db}
2025-01-13 14:08:04.534 [INF] BP: network param updates: null
2025-01-13 14:08:04.534 [INF] CONS: Executed block {height=1 hash=294ab59348e32fa3f5ab93cfd4739259373e3bd26f49288553c2f84c297b5467 numTxs=0 appHash=2d8f3ceeff2c836527da823d7b654d33d3e44b6159b172235c160001e0c9b4db}
2025-01-13 14:08:04.544 [INF] BP: Committed Block {height=1 appHash=2d8f3ceeff2c836527da823d7b654d33d3e44b6159b172235c160001e0c9b4db}
2025-01-13 14:08:04.544 [INF] CONS: Committed Block {height=1 hash=294ab59348e32fa3f5ab93cfd4739259373e3bd26f49288553c2f84c297b5467 appHash=2d8f3ceeff2c836527da823d7b654d33d3e44b6159b172235c160001e0c9b4db updates=null}
2025-01-13 14:08:04.544 [INF] CONS: Requesting block from network(replay mode) {height=2}
2025-01-13 14:08:04.544 [INF] NODE: requesting block number 2 from 16Uiu2HAkx2kfP117VnYnaQGprgXBoMpjfxGXCpizju3cX7ZUzRhv
2025-01-13 14:08:04.545 [INF] NODE: obtained block contents {height=2 elapsed=331.235µs}
2025-01-13 14:08:04.545 [INF] CONS: Processing committed block {height=2 hash=4e7f16cc53d6587ac9fd21935c8a5b4227fbb22e118fca308a67364d5430c896 appHash=326f3c3c09f467125e3a346805f2f8434c71fd0f14336d8b9cffd1e40f1069a2}
2025-01-13 14:08:04.564 [INF] BP: Consensus updates {hash=df3f619804a92fdb4057192dc43dd748ea778adc52bc498ce80524c014b81119 updates={}}
2025-01-13 14:08:04.564 [INF] BP: AppState updates:  {prevAppHash=2d8f3ceeff2c836527da823d7b654d33d3e44b6159b172235c160001e0c9b4db changesetsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 valUpdatesHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 accountsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 txResultsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 paramUpdatesHash=df3f619804a92fdb4057192dc43dd748ea778adc52bc498ce80524c014b81119}
2025-01-13 14:08:04.564 [INF] BP: Executed Block {height=2 blkHash=4e7f16cc53d6587ac9fd21935c8a5b4227fbb22e118fca308a67364d5430c896 appHash=326f3c3c09f467125e3a346805f2f8434c71fd0f14336d8b9cffd1e40f1069a2}
2025-01-13 14:08:04.564 [INF] BP: network param updates: {}
2025-01-13 14:08:04.564 [INF] CONS: Executed block {height=2 hash=4e7f16cc53d6587ac9fd21935c8a5b4227fbb22e118fca308a67364d5430c896 numTxs=0 appHash=326f3c3c09f467125e3a346805f2f8434c71fd0f14336d8b9cffd1e40f1069a2}
2025-01-13 14:08:04.573 [INF] BP: Committed Block {height=2 appHash=326f3c3c09f467125e3a346805f2f8434c71fd0f14336d8b9cffd1e40f1069a2}
2025-01-13 14:08:04.573 [INF] CONS: Committed Block {height=2 hash=4e7f16cc53d6587ac9fd21935c8a5b4227fbb22e118fca308a67364d5430c896 appHash=326f3c3c09f467125e3a346805f2f8434c71fd0f14336d8b9cffd1e40f1069a2 updates={}}
2025-01-13 14:08:04.573 [INF] CONS: Requesting block from network(replay mode) {height=3}
2025-01-13 14:08:04.573 [INF] NODE: requesting block number 3 from 16Uiu2HAm8iRUsTzYepLP8pdJL3645ACP7VBfZQ7yFbLfdb7WvkL7
2025-01-13 14:08:04.574 [INF] NODE: obtained block contents {height=3 elapsed=640.719µs}

...

2025-01-13 14:08:06.974 [INF] CONS: Requesting block from network(replay mode) {height=100}
2025-01-13 14:08:06.975 [INF] NODE: requesting block number 100 from 16Uiu2HAkx2kfP117VnYnaQGprgXBoMpjfxGXCpizju3cX7ZUzRhv
2025-01-13 14:08:06.975 [INF] NODE: obtained block contents {height=100 elapsed=454.965µs}
2025-01-13 14:08:06.975 [INF] CONS: Processing committed block {height=100 hash=2928403ae2e06560c1dd7a9d6af35dd7fa28b3f2b2bdafa4ef5dee77ad267789 appHash=a4fa9cc158bbc1ffea766b93ce85382c70d51c7682434a0177d5045918a27b62}
2025-01-13 14:08:06.989 [INF] BP: Consensus updates {hash=df3f619804a92fdb4057192dc43dd748ea778adc52bc498ce80524c014b81119 updates={}}
2025-01-13 14:08:06.989 [INF] BP: AppState updates:  {prevAppHash=245b378667405d297f876f839b72d87c3cb74daaf2bd3bf4b2b889e59c33c3f6 changesetsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 valUpdatesHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 accountsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 txResultsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 paramUpdatesHash=df3f619804a92fdb4057192dc43dd748ea778adc52bc498ce80524c014b81119}
2025-01-13 14:08:06.989 [INF] BP: Executed Block {height=100 blkHash=2928403ae2e06560c1dd7a9d6af35dd7fa28b3f2b2bdafa4ef5dee77ad267789 appHash=a4fa9cc158bbc1ffea766b93ce85382c70d51c7682434a0177d5045918a27b62}
2025-01-13 14:08:06.989 [INF] BP: network param updates: {}
2025-01-13 14:08:06.989 [INF] CONS: Executed block {height=100 hash=2928403ae2e06560c1dd7a9d6af35dd7fa28b3f2b2bdafa4ef5dee77ad267789 numTxs=0 appHash=a4fa9cc158bbc1ffea766b93ce85382c70d51c7682434a0177d5045918a27b62}
2025-01-13 14:08:06.999 [INF] BP: Committed Block {height=100 appHash=a4fa9cc158bbc1ffea766b93ce85382c70d51c7682434a0177d5045918a27b62}
2025-01-13 14:08:06.999 [INF] CONS: Committed Block {height=100 hash=2928403ae2e06560c1dd7a9d6af35dd7fa28b3f2b2bdafa4ef5dee77ad267789 appHash=a4fa9cc158bbc1ffea766b93ce85382c70d51c7682434a0177d5045918a27b62 updates={}}

From request to commit of a block it varies from 25 ms to 70 ms. This isn't too bad, but it we should still look at ways to improve this, or at least keep an eye on performance.

The above result is on the paramupdates branch, based on main at a412e1b

[charithabandi]

Block sync completed {startHeight=1 endHeight=66 duration=831.392709ms}

with #1251 I am seeing roughly 12ms per block

025-01-21 17:56:48.161 [INF] CONS: Requesting block from network (replay mode) {height=418}
2025-01-21 17:56:48.161 [INF] NODE: requesting block number 418 from 16Uiu2HAm8iRUsTzYepLP8pdJL3645ACP7VBfZQ7yFbLfdb7WvkL7
2025-01-21 17:56:48.161 [INF] NODE: obtained block contents {height=418 elapsed=192.083µs}
2025-01-21 17:56:48.161 [INF] CONS: Processing committed block {height=418 hash=a7480acdc58fd4b490a7f085e82dbdcf6037d8842d8c27ae3e0653b1ea8624f0 appHash=0e379926b80b3ca1e7504fb71b29542acceaaf0047d3a9ea9331ad34b7de16eb}
2025-01-21 17:56:48.168 [INF] BP: Consensus updates {hash=df3f619804a92fdb4057192dc43dd748ea778adc52bc498ce80524c014b81119 updates={}}
2025-01-21 17:56:48.168 [INF] BP: AppState updates:  {prevAppHash=b7c0c205baa370a7ba2ec38485e4180878fd87f57c34b307ad595eb9efc2440d changesetsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 valUpdatesHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 accountsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 txResultsHash=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 paramUpdatesHash=df3f619804a92fdb4057192dc43dd748ea778adc52bc498ce80524c014b81119}
2025-01-21 17:56:48.168 [INF] BP: Executed Block {height=418 blkHash=a7480acdc58fd4b490a7f085e82dbdcf6037d8842d8c27ae3e0653b1ea8624f0 appHash=0e379926b80b3ca1e7504fb71b29542acceaaf0047d3a9ea9331ad34b7de16eb}
2025-01-21 17:56:48.168 [INF] BP: network param updates: {}
2025-01-21 17:56:48.168 [INF] CONS: Executed block {height=418 blkID=a7480acdc58fd4b490a7f085e82dbdcf6037d8842d8c27ae3e0653b1ea8624f0 numTxs=0 appHash=0e379926b80b3ca1e7504fb71b29542acceaaf0047d3a9ea9331ad34b7de16eb}
2025-01-21 17:56:48.170 [INF] BP: Committed Block {height=418 appHash=0e379926b80b3ca1e7504fb71b29542acceaaf0047d3a9ea9331ad34b7de16eb}
2025-01-21 17:56:48.170 [INF] CONS: Committed Block {height=418 hash=a7480acdc58fd4b490a7f085e82dbdcf6037d8842d8c27ae3e0653b1ea8624f0 appHash=0e379926b80b3ca1e7504fb71b29542acceaaf0047d3a9ea9331ad34b7de16eb updates={}}