Skip to content

Add execution blockNumber to the notifier log - #5297

Merged
g11tech merged 6 commits into
unstablefrom
g11tech/notify-execution-blocknum
Apr 20, 2023
Merged

Add execution blockNumber to the notifier log#5297
g11tech merged 6 commits into
unstablefrom
g11tech/notify-execution-blocknum

Conversation

@g11tech

@g11tech g11tech commented Mar 22, 2023

Copy link
Copy Markdown
Contributor

Add execution blockNumber to the notifier log

We only display execution head's blockHash while execution block number is also an important info that people from EL land (ethereumjs specifically) have asked for in the log.

result:
image

@g11tech
g11tech requested a review from a team as a code owner March 22, 2023 20:52
@github-actions

github-actions Bot commented Mar 22, 2023

Copy link
Copy Markdown
Contributor

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 9b60ed4 Previous: ffc0d16 Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 595.05 us/op 621.61 us/op 0.96
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 57.627 us/op 52.033 us/op 1.11
BLS verify - blst-native 1.2780 ms/op 1.2766 ms/op 1.00
BLS verifyMultipleSignatures 3 - blst-native 2.5821 ms/op 2.6005 ms/op 0.99
BLS verifyMultipleSignatures 8 - blst-native 5.5609 ms/op 5.6132 ms/op 0.99
BLS verifyMultipleSignatures 32 - blst-native 20.647 ms/op 20.237 ms/op 1.02
BLS aggregatePubkeys 32 - blst-native 27.130 us/op 26.915 us/op 1.01
BLS aggregatePubkeys 128 - blst-native 105.16 us/op 105.61 us/op 1.00
getAttestationsForBlock 65.317 ms/op 61.561 ms/op 1.06
isKnown best case - 1 super set check 277.00 ns/op 284.00 ns/op 0.98
isKnown normal case - 2 super set checks 269.00 ns/op 280.00 ns/op 0.96
isKnown worse case - 16 super set checks 305.00 ns/op 276.00 ns/op 1.11
CheckpointStateCache - add get delete 6.1740 us/op 5.8420 us/op 1.06
validate gossip signedAggregateAndProof - struct 3.0320 ms/op 2.9373 ms/op 1.03
validate gossip attestation - struct 1.4546 ms/op 1.4044 ms/op 1.04
pickEth1Vote - no votes 1.4809 ms/op 1.4880 ms/op 1.00
pickEth1Vote - max votes 13.166 ms/op 12.433 ms/op 1.06
pickEth1Vote - Eth1Data hashTreeRoot value x2048 10.722 ms/op 11.510 ms/op 0.93
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 20.529 ms/op 16.697 ms/op 1.23
pickEth1Vote - Eth1Data fastSerialize value x2048 962.02 us/op 848.58 us/op 1.13
pickEth1Vote - Eth1Data fastSerialize tree x2048 8.9067 ms/op 8.3099 ms/op 1.07
bytes32 toHexString 870.00 ns/op 771.00 ns/op 1.13
bytes32 Buffer.toString(hex) 502.00 ns/op 468.00 ns/op 1.07
bytes32 Buffer.toString(hex) from Uint8Array 700.00 ns/op 655.00 ns/op 1.07
bytes32 Buffer.toString(hex) + 0x 502.00 ns/op 448.00 ns/op 1.12
Object access 1 prop 0.21500 ns/op 0.22300 ns/op 0.96
Map access 1 prop 0.18300 ns/op 0.18600 ns/op 0.98
Object get x1000 7.7600 ns/op 7.3650 ns/op 1.05
Map get x1000 0.71100 ns/op 0.71600 ns/op 0.99
Object set x1000 79.038 ns/op 74.434 ns/op 1.06
Map set x1000 60.197 ns/op 59.002 ns/op 1.02
Return object 10000 times 0.26610 ns/op 0.25910 ns/op 1.03
Throw Error 10000 times 4.9140 us/op 4.4429 us/op 1.11
fastMsgIdFn sha256 / 200 bytes 3.7930 us/op 3.7290 us/op 1.02
fastMsgIdFn h32 xxhash / 200 bytes 333.00 ns/op 329.00 ns/op 1.01
fastMsgIdFn h64 xxhash / 200 bytes 512.00 ns/op 520.00 ns/op 0.98
fastMsgIdFn sha256 / 1000 bytes 12.550 us/op 12.719 us/op 0.99
fastMsgIdFn h32 xxhash / 1000 bytes 468.00 ns/op 469.00 ns/op 1.00
fastMsgIdFn h64 xxhash / 1000 bytes 584.00 ns/op 614.00 ns/op 0.95
fastMsgIdFn sha256 / 10000 bytes 112.18 us/op 111.36 us/op 1.01
fastMsgIdFn h32 xxhash / 10000 bytes 2.0730 us/op 2.2170 us/op 0.94
fastMsgIdFn h64 xxhash / 10000 bytes 1.5820 us/op 1.7560 us/op 0.90
enrSubnets - fastDeserialize 64 bits 2.0000 us/op 2.2590 us/op 0.89
enrSubnets - ssz BitVector 64 bits 647.00 ns/op 988.00 ns/op 0.65
enrSubnets - fastDeserialize 4 bits 256.00 ns/op 254.00 ns/op 1.01
enrSubnets - ssz BitVector 4 bits 713.00 ns/op 689.00 ns/op 1.03
prioritizePeers score -10:0 att 32-0.1 sync 2-0 131.47 us/op 155.26 us/op 0.85
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 177.95 us/op 199.12 us/op 0.89
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 214.64 us/op 229.43 us/op 0.94
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 403.40 us/op 389.41 us/op 1.04
prioritizePeers score 0:0 att 64-1 sync 4-1 503.66 us/op 509.73 us/op 0.99
array of 16000 items push then shift 1.8198 us/op 1.8291 us/op 0.99
LinkedList of 16000 items push then shift 9.4910 ns/op 11.407 ns/op 0.83
array of 16000 items push then pop 123.04 ns/op 148.29 ns/op 0.83
LinkedList of 16000 items push then pop 9.4010 ns/op 12.846 ns/op 0.73
array of 24000 items push then shift 2.5633 us/op 2.8568 us/op 0.90
LinkedList of 24000 items push then shift 9.5680 ns/op 14.594 ns/op 0.66
array of 24000 items push then pop 95.019 ns/op 113.89 ns/op 0.83
LinkedList of 24000 items push then pop 9.5510 ns/op 12.112 ns/op 0.79
intersect bitArray bitLen 8 14.430 ns/op 19.042 ns/op 0.76
intersect array and set length 8 111.84 ns/op 146.20 ns/op 0.77
intersect bitArray bitLen 128 48.218 ns/op 60.474 ns/op 0.80
intersect array and set length 128 1.2647 us/op 1.6974 us/op 0.75
Buffer.concat 32 items 3.1870 us/op 4.1900 us/op 0.76
Uint8Array.set 32 items 2.8040 us/op 3.6950 us/op 0.76
pass gossip attestations to forkchoice per slot 3.2759 ms/op 4.5964 ms/op 0.71
computeDeltas 3.3722 ms/op 4.5529 ms/op 0.74
computeProposerBoostScoreFromBalances 1.9172 ms/op 2.2569 ms/op 0.85
altair processAttestation - 250000 vs - 7PWei normalcase 3.6547 ms/op 5.3130 ms/op 0.69
altair processAttestation - 250000 vs - 7PWei worstcase 5.1952 ms/op 6.4966 ms/op 0.80
altair processAttestation - setStatus - 1/6 committees join 147.04 us/op 174.29 us/op 0.84
altair processAttestation - setStatus - 1/3 committees join 285.81 us/op 351.80 us/op 0.81
altair processAttestation - setStatus - 1/2 committees join 380.56 us/op 444.99 us/op 0.86
altair processAttestation - setStatus - 2/3 committees join 477.76 us/op 574.22 us/op 0.83
altair processAttestation - setStatus - 4/5 committees join 675.71 us/op 787.11 us/op 0.86
altair processAttestation - setStatus - 100% committees join 786.99 us/op 991.29 us/op 0.79
altair processBlock - 250000 vs - 7PWei normalcase 21.705 ms/op 26.198 ms/op 0.83
altair processBlock - 250000 vs - 7PWei normalcase hashState 28.428 ms/op 36.285 ms/op 0.78
altair processBlock - 250000 vs - 7PWei worstcase 55.257 ms/op 65.441 ms/op 0.84
altair processBlock - 250000 vs - 7PWei worstcase hashState 73.344 ms/op 92.304 ms/op 0.79
phase0 processBlock - 250000 vs - 7PWei normalcase 2.5263 ms/op 4.2222 ms/op 0.60
phase0 processBlock - 250000 vs - 7PWei worstcase 32.085 ms/op 38.662 ms/op 0.83
altair processEth1Data - 250000 vs - 7PWei normalcase 716.86 us/op 960.19 us/op 0.75
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 9.6730 us/op 18.305 us/op 0.53
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 32.814 us/op 45.423 us/op 0.72
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 16.420 us/op 20.938 us/op 0.78
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 10.150 us/op 19.897 us/op 0.51
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 105.09 us/op 155.98 us/op 0.67
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 695.03 us/op 1.1579 ms/op 0.60
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 929.95 us/op 1.2378 ms/op 0.75
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 910.64 us/op 1.5872 ms/op 0.57
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.7782 ms/op 4.3918 ms/op 0.63
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.5507 ms/op 2.4981 ms/op 0.62
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 4.9064 ms/op 8.0592 ms/op 0.61
Tree 40 250000 create 510.92 ms/op 885.83 ms/op 0.58
Tree 40 250000 get(125000) 199.79 ns/op 221.03 ns/op 0.90
Tree 40 250000 set(125000) 1.2875 us/op 3.1860 us/op 0.40
Tree 40 250000 toArray() 23.991 ms/op 31.296 ms/op 0.77
Tree 40 250000 iterate all - toArray() + loop 23.885 ms/op 30.786 ms/op 0.78
Tree 40 250000 iterate all - get(i) 78.576 ms/op 97.018 ms/op 0.81
MutableVector 250000 create 12.241 ms/op 14.351 ms/op 0.85
MutableVector 250000 get(125000) 6.5310 ns/op 7.8160 ns/op 0.84
MutableVector 250000 set(125000) 397.53 ns/op 825.33 ns/op 0.48
MutableVector 250000 toArray() 4.1019 ms/op 6.0445 ms/op 0.68
MutableVector 250000 iterate all - toArray() + loop 4.2823 ms/op 6.1140 ms/op 0.70
MutableVector 250000 iterate all - get(i) 1.5869 ms/op 1.7554 ms/op 0.90
Array 250000 create 4.0673 ms/op 5.8748 ms/op 0.69
Array 250000 clone - spread 1.6071 ms/op 1.7434 ms/op 0.92
Array 250000 get(125000) 1.1400 ns/op 1.3610 ns/op 0.84
Array 250000 set(125000) 0.88500 ns/op 1.8050 ns/op 0.49
Array 250000 iterate all - loop 93.804 us/op 94.717 us/op 0.99
effectiveBalanceIncrements clone Uint8Array 300000 62.476 us/op 76.149 us/op 0.82
effectiveBalanceIncrements clone MutableVector 300000 459.00 ns/op 469.00 ns/op 0.98
effectiveBalanceIncrements rw all Uint8Array 300000 185.04 us/op 192.13 us/op 0.96
effectiveBalanceIncrements rw all MutableVector 300000 149.33 ms/op 185.90 ms/op 0.80
phase0 afterProcessEpoch - 250000 vs - 7PWei 122.00 ms/op 134.25 ms/op 0.91
phase0 beforeProcessEpoch - 250000 vs - 7PWei 52.592 ms/op 60.901 ms/op 0.86
altair processEpoch - mainnet_e81889 353.06 ms/op 455.50 ms/op 0.78
mainnet_e81889 - altair beforeProcessEpoch 81.891 ms/op 114.26 ms/op 0.72
mainnet_e81889 - altair processJustificationAndFinalization 22.651 us/op 38.106 us/op 0.59
mainnet_e81889 - altair processInactivityUpdates 6.9054 ms/op 7.7818 ms/op 0.89
mainnet_e81889 - altair processRewardsAndPenalties 53.902 ms/op 97.147 ms/op 0.55
mainnet_e81889 - altair processRegistryUpdates 4.4540 us/op 6.8210 us/op 0.65
mainnet_e81889 - altair processSlashings 1.0200 us/op 1.9150 us/op 0.53
mainnet_e81889 - altair processEth1DataReset 954.00 ns/op 911.00 ns/op 1.05
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.3554 ms/op 6.7803 ms/op 0.20
mainnet_e81889 - altair processSlashingsReset 5.2580 us/op 11.350 us/op 0.46
mainnet_e81889 - altair processRandaoMixesReset 8.0140 us/op 13.602 us/op 0.59
mainnet_e81889 - altair processHistoricalRootsUpdate 2.0210 us/op 2.0830 us/op 0.97
mainnet_e81889 - altair processParticipationFlagUpdates 3.6440 us/op 7.2000 us/op 0.51
mainnet_e81889 - altair processSyncCommitteeUpdates 716.00 ns/op 1.5310 us/op 0.47
mainnet_e81889 - altair afterProcessEpoch 191.36 ms/op 142.09 ms/op 1.35
phase0 processEpoch - mainnet_e58758 915.80 ms/op 438.70 ms/op 2.09
mainnet_e58758 - phase0 beforeProcessEpoch 352.84 ms/op 200.86 ms/op 1.76
mainnet_e58758 - phase0 processJustificationAndFinalization 20.522 us/op 34.675 us/op 0.59
mainnet_e58758 - phase0 processRewardsAndPenalties 70.521 ms/op 81.879 ms/op 0.86
mainnet_e58758 - phase0 processRegistryUpdates 9.9990 us/op 16.755 us/op 0.60
mainnet_e58758 - phase0 processSlashings 628.00 ns/op 1.2660 us/op 0.50
mainnet_e58758 - phase0 processEth1DataReset 579.00 ns/op 1.2180 us/op 0.48
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 1.2373 ms/op 1.3882 ms/op 0.89
mainnet_e58758 - phase0 processSlashingsReset 4.1660 us/op 5.5810 us/op 0.75
mainnet_e58758 - phase0 processRandaoMixesReset 6.2070 us/op 7.9410 us/op 0.78
mainnet_e58758 - phase0 processHistoricalRootsUpdate 1.1960 us/op 1.0650 us/op 1.12
mainnet_e58758 - phase0 processParticipationRecordUpdates 6.3960 us/op 7.2310 us/op 0.88
mainnet_e58758 - phase0 afterProcessEpoch 104.07 ms/op 105.80 ms/op 0.98
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.3148 ms/op 1.4721 ms/op 0.89
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.5943 ms/op 1.5108 ms/op 1.06
altair processInactivityUpdates - 250000 normalcase 26.031 ms/op 27.381 ms/op 0.95
altair processInactivityUpdates - 250000 worstcase 26.969 ms/op 28.742 ms/op 0.94
phase0 processRegistryUpdates - 250000 normalcase 8.1040 us/op 9.8300 us/op 0.82
phase0 processRegistryUpdates - 250000 badcase_full_deposits 285.94 us/op 298.63 us/op 0.96
phase0 processRegistryUpdates - 250000 worstcase 0.5 151.81 ms/op 125.58 ms/op 1.21
altair processRewardsAndPenalties - 250000 normalcase 70.877 ms/op 49.876 ms/op 1.42
altair processRewardsAndPenalties - 250000 worstcase 73.855 ms/op 70.610 ms/op 1.05
phase0 getAttestationDeltas - 250000 normalcase 8.8392 ms/op 14.609 ms/op 0.61
phase0 getAttestationDeltas - 250000 worstcase 7.2617 ms/op 12.408 ms/op 0.59
phase0 processSlashings - 250000 worstcase 3.5764 ms/op 3.9605 ms/op 0.90
altair processSyncCommitteeUpdates - 250000 184.80 ms/op 197.75 ms/op 0.93
BeaconState.hashTreeRoot - No change 321.00 ns/op 283.00 ns/op 1.13
BeaconState.hashTreeRoot - 1 full validator 55.845 us/op 55.984 us/op 1.00
BeaconState.hashTreeRoot - 32 full validator 559.39 us/op 586.61 us/op 0.95
BeaconState.hashTreeRoot - 512 full validator 6.5836 ms/op 5.8983 ms/op 1.12
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 66.930 us/op 67.624 us/op 0.99
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 1.0195 ms/op 989.62 us/op 1.03
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 14.060 ms/op 13.213 ms/op 1.06
BeaconState.hashTreeRoot - 1 balances 54.913 us/op 56.047 us/op 0.98
BeaconState.hashTreeRoot - 32 balances 509.28 us/op 521.13 us/op 0.98
BeaconState.hashTreeRoot - 512 balances 4.8762 ms/op 4.8307 ms/op 1.01
BeaconState.hashTreeRoot - 250000 balances 80.409 ms/op 84.327 ms/op 0.95
aggregationBits - 2048 els - zipIndexesInBitList 20.134 us/op 21.868 us/op 0.92
regular array get 100000 times 34.162 us/op 37.260 us/op 0.92
wrappedArray get 100000 times 41.821 us/op 36.003 us/op 1.16
arrayWithProxy get 100000 times 16.571 ms/op 16.852 ms/op 0.98
ssz.Root.equals 601.00 ns/op 605.00 ns/op 0.99
byteArrayEquals 576.00 ns/op 644.00 ns/op 0.89
shuffle list - 16384 els 7.3090 ms/op 7.3598 ms/op 0.99
shuffle list - 250000 els 105.05 ms/op 108.77 ms/op 0.97
processSlot - 1 slots 9.5880 us/op 12.043 us/op 0.80
processSlot - 32 slots 1.4576 ms/op 1.7792 ms/op 0.82
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 42.685 ms/op 41.761 ms/op 1.02
getCommitteeAssignments - req 1 vs - 250000 vc 2.9995 ms/op 3.8157 ms/op 0.79
getCommitteeAssignments - req 100 vs - 250000 vc 4.4549 ms/op 5.2657 ms/op 0.85
getCommitteeAssignments - req 1000 vs - 250000 vc 4.8895 ms/op 5.2554 ms/op 0.93
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.8800 ns/op 6.2800 ns/op 0.78
state getBlockRootAtSlot - 250000 vs - 7PWei 634.40 ns/op 1.0849 us/op 0.58
computeProposers - vc 250000 11.079 ms/op 12.798 ms/op 0.87
computeEpochShuffling - vc 250000 109.16 ms/op 115.81 ms/op 0.94
getNextSyncCommittee - vc 250000 188.98 ms/op 214.52 ms/op 0.88
computeSigningRoot for AttestationData 15.746 us/op 17.607 us/op 0.89
hash AttestationData serialized data then Buffer.toString(base64) 2.6284 us/op 2.7388 us/op 0.96
toHexString serialized data 1.4729 us/op 2.4300 us/op 0.61
Buffer.toString(base64) 397.61 ns/op 459.67 ns/op 0.87

by benchmarkbot/action

@dapplion dapplion left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Not strongly opposed to this but the status log is already pretty long. Maybe we should add some guidelines so the status log does not grow forever. i.e. let's try to formalize a bit the purpose of this log and what information makes it in, and what does not. I can imagine that with new forks more and more data would be appealing to be displayed here

const protoNodeSszType = new ContainerType(
{
executionPayloadBlockHash: stringType,
executionPayloadNumber: ssz.UintNum64,

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Is this API standardized?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

ummm ... i don't think so, double checked

@g11tech

g11tech commented Mar 23, 2023

Copy link
Copy Markdown
Contributor Author

Not strongly opposed to this but the status log is already pretty long. Maybe we should add some guidelines so the status log does not grow forever. i.e. let's try to formalize a bit the purpose of this log and what information makes it in, and what does not. I can imagine that with new forks more and more data would be appealing to be displayed here

right!, may be we can further truncate the hash of head exec-block since number + first 4 hash bytes are good enough to identify where execution head is: so like exec-block: valid(16885600 0x2013…)
the log would look like:

Mar-22 20:47:17.001[] info: Synced - slot: 6057834 - head: 6057834 0xff7e…d00c exec-block: valid(16885600 0x2013…) - finalized: 0xce5a…bdac:189305 (exec-block: 16885526) - peers: 17

We can also apply same principal for beacon head so: head: 6057834 0xff7e… exec-block: valid(16885600 0x2013…)

May be we can also drop exec-block bit from finalized and let it remain unchanged, so final log could look like:
Mar-22 20:47:17.001[] info: Synced - slot: 6057834 - head: 6057834 0xff7e… exec-block: valid(16885600 0x2013…) - finalized: 0xce5a…bdac:189305 - peers: 17

@dapplion

Copy link
Copy Markdown
Contributor

Yes definitely better not to add in the finalized, so this log looks good

May be we can also drop exec-block bit from finalized and let it remain unchanged, so final log could look like:
Mar-22 20:47:17.001[] info: Synced - slot: 6057834 - head: 6057834 0xff7e… exec-block: valid(16885600 0x2013…) - finalized: 0xce5a…bdac:189305 - peers: 17

@g11tech

g11tech commented Mar 24, 2023

Copy link
Copy Markdown
Contributor Author

Yes definitely better not to add in the finalized, so this log looks good

May be we can also drop exec-block bit from finalized and let it remain unchanged, so final log could look like:
Mar-22 20:47:17.001[] info: Synced - slot: 6057834 - head: 6057834 0xff7e… exec-block: valid(16885600 0x2013…) - finalized: 0xce5a…bdac:189305 - peers: 17

how about this:

Mar-24 11:09:05.434[]                 info: Syncing - 10 minutes left - 6.32 slots/s - head: 6065535 (clock: 6069343) 0x6c82…486d exec-block: valid(16893200 0xadfe) - finalized: 0x14bd…d8d6:189545 - peers: 7
Mar-24 11:09:17.473[]                 info: Syncing - 9.8 minutes left - 6.35 slots/s - head: 6065599 (clock: 6069344) 0xb659…7109 exec-block: valid(16893264 0xf32f) - finalized: 0xb551…b203:189548 - peers: 9
Mar-24 11:16:29.187[]                 info: Syncing - 3.4 minutes left - 4.77 slots/s - head: 6068415 (clock-965) 0xeddf…e97b exec-block: valid(16896048 0x5d16) - finalized: 0xd7ba…8386:189636 - peers: 9
valid(16896681 0xc9a6…9b3a) - finalized: 0x495d…f884:189656 - peers: 10
Mar-24 11:18:53.033[]                 info: Syncing - 42 seconds left - 5.77 slots/s - head: 6069151 (clock-241) 0xdb52…77b7 exec-block: valid(16896777 0x0c24) - finalized: 0x6777…d015:189659 - peers: 17
Mar-24 11:19:17.031[]                 info: Syncing - 18 seconds left - 6.55 slots/s - head: 6069279 (clock-115) 0xd6bb…4ecd exec-block: valid(16896905 0x6599) - finalized: 0x4658…51b6:189663 - peers: 11
Mar-24 11:19:29.047[]                 info: Syncing - 7.8 seconds left - 6.67 slots/s - head: 6069343 (clock-52) 0xf111…4552 exec-block: valid(16896968 0x6a16) - finalized: 0x4e1e…3499:189665 - peers: 14
Mar-24 11:19:35.675[network]          info: Subscribed gossip core topics
Mar-24 11:37:29.001[]                 info: Synced - head: 6069482 0xa9fd…ddab exec-block: valid(16897109 0x4951) - finalized: 0xec9e…9cc1:189669 - peers: 27
Mar-24 11:37:17.000[]                 info: Synced - head: 6069482 (clock-1) 0x88b2…fb8c exec-block: valid(16897108 0x90c9) - finalized: 0xec9e…9cc1:189669 - peers: 31
Mar-24 11:37:29.001[]                 info: Synced - head: 6069484 0xa9fd…ddab exec-block: valid(16897109 0x4951) - finalized: 0xec9e…9cc1:189669 - peers: 27

Explanation:
explanation :

  1. if clock -head > 1000:
    head: 6065535 (clock: 6069343) 0x6c82…486d exec-block: valid(16896873 0x029b…)
  2. if clock - head < 1000:
    head: 6069247 (clock - 146) 0x824f…7bbd exec-block: valid(16896873 0x029b…)
  3. if clock === head
    head: 6069485 0xa9fd…ddab exec-block: valid(16897109 0x4951…)
  4. again if skipped slot
    head: 6069482 (clock - 1) 0x88b2…fb8c exec-block: valid(16897108 0x90c9…)

@philknows

Copy link
Copy Markdown
Member

I think it no matter what the format is, we should include in our docs what each thing in the log means. I was used to the skipped 1 previously which made sense instantly, but clock-1 is fine too as long as we explain somewhere that means 1 skipped block (usually from missed proposals).

@g11tech

g11tech commented Mar 24, 2023

Copy link
Copy Markdown
Contributor Author

I think it no matter what the format is, we should include in our docs what each thing in the log means. I was used to the skipped 1 previously which made sense instantly, but clock-1 is fine too as long as we explain somewhere that means 1 skipped block (usually from missed proposals).

added

@g11tech
g11tech enabled auto-merge (squash) March 24, 2023 18:27
@dapplion
dapplion disabled auto-merge March 28, 2023 01:43
dapplion
dapplion previously approved these changes Mar 28, 2023

@dapplion dapplion left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Disabled auto-merging to allow others to 👍 before merging

@philknows

Copy link
Copy Markdown
Member

I had a chat with @wemeetagain yesterday about this PR, specifically about the logging which can be further shortened in our opinion to reduce any redundancy of information. If we can find the most concise way to explain something that is very clear without additional context and definitions in docs, we've hit the jackpot.

At least for the slot numbers and identifying where the head is, it could be shortened to:

// synced and the head is at the latest slot. Reduces repeating the slot number twice if at the head.
Synced - slot: N - head: 0xabcd...dcba - ...

// synced and the head is one slot behind. We think this makes more sense comparatively to `clock-x` which was more confusing than `skipped 1`
Synced - slot: M - head: (slot -1) 0xabcd...dcba - ...

@g11tech

g11tech commented Mar 30, 2023

Copy link
Copy Markdown
Contributor Author

hmmm this looks good as well, will update

Problem with slot as clock in the front is that when syncing from far away, this is confusing to others:
Syncing .... - slot: 6069482 - head: 6065535 ...

as slot and head are both very generic , also clock slot info as the first thing isn't the concern of the users:

What is relevant to them are:

  1. Am i synced or syncing
  2. Where my local head is and if i am missing any latest blocks

current clock info is only relevant w.r.t. the local head

@philknows

philknows commented Mar 31, 2023

Copy link
Copy Markdown
Member

What is relevant to them are:

  1. Am i synced or syncing
  2. Where my local head is and if i am missing any latest blocks

So for syncing, you're right and that a lot of this information may not even be required. Maybe we can rethink something for Syncing

We currently see something like:

info: Syncing - 2.8 hours left - 3.19 slots/s - slot: 5314216 (skipped 32552) - head: 5281664 0x14d0…8776
info: Syncing - 2.8 hours left - 3.22 slots/s - slot: 5314217 (skipped 32490) - head: 5281727 0x1d24…d906
info: Syncing - 2.7 hours left - 3.32 slots/s - slot: 5314218 (skipped 32459) - head: 5281759 0x0646…8590

And with the above idea we will see:

info: Syncing - 2.8 hours left - 3.19 slots/s - slot: 5314216 - head: (slot -32552) 0x14d0…8776
info: Syncing - 2.8 hours left - 3.22 slots/s - slot: 5314217 - head: (slot -32490) 0x1d24…d906
info: Syncing - 2.7 hours left - 3.32 slots/s - slot: 5314218 - head: (slot -32459) 0x0646…8590
  1. As the user, we know that the node is still syncing, so much of this information is not really even necessary. Users know it's syncing. But now, how do we answer Q2?

  2. Perhaps while syncing only, the easiest way to solve this is to have something different that shows where we are locally instead of where the chain is currently at. An idea here is just to omit the clock/slot.

info: Syncing - 2.8 hours left - 3.19 slots/s - head: 5281664 0x14d0…8776
info: Syncing - 2.8 hours left - 3.22 slots/s - head: 5281727 0x1d24…d906
info: Syncing - 2.7 hours left - 3.32 slots/s - head: 5281759 0x0646…8590

@wemeetagain wemeetagain added the meta-discussion Indicates a topic that requires input from various developers. label Apr 3, 2023
@g11tech
g11tech force-pushed the g11tech/notify-execution-blocknum branch from 166fc52 to 80eeb95 Compare April 20, 2023 15:42
@g11tech

g11tech commented Apr 20, 2023

Copy link
Copy Markdown
Contributor Author

Ok this is how the sync logs will look r.n.
I guess we should just merge this and relook at it separately as the main aim of the PR was to add exec block number/hash info of head

Apr-20 15:24:08.034[]                 info: Searching peers - peers: 0 - slot: 6265018 - head: 6264018 0xed93…7b0a - exec-block: syncing(17088476 0x9649…) - finalized: 0xbf30…7e7c:195777
Apr-20 15:24:17.000[]                 info: Searching peers - peers: 0 - slot: 6265019 - head: 6264018 0xed93…7b0a - exec-block: syncing(17088476 0x9649…) - finalized: 0xbf30…7e7c:195777

Apr-20 15:13:41.298[]                 info: Syncing - 2.5 minutes left - 2.78 slots/s - slot: 6264966 - head: 6262966 0x5cec…f5b8 - exec-block: valid(17088105 0x6f74…) - finalized: 0x5cc0…3874:195764 - peers: 1
Apr-20 15:13:41.298[]                 info: Syncing - 2 minutes left - 2.78 slots/s - slot: 6264967 - head: 6263965 0x5cec…f5b8 - exec-block: valid(17088105 0x6f74…) - finalized: 0x5cc0…3874:195764 - peers: 1

Apr-20 15:13:53.151[]                 info: Syncing - 1.6 minutes left - 3.82 slots/s - slot: 6264967 - head: (slot -360) 0xe0cf…9f3c - exec-block: valid(17088167 0x2d6a…) - finalized: 0x8f3f…2f81:195766 - peers: 5
Apr-20 15:14:05.425[]                 info: Syncing - 1.1 minutes left - 4.33 slots/s - slot: 6264968 - head: (slot -297) 0x3655…1658 - exec-block: valid(17088231 0xdafd…) - finalized: 0x9475…425a:195769 - peers: 2
Apr-20 15:14:53.001[]                 info: Syncing - 9 seconds left - 5.00 slots/s - slot: 6264972 - head: (slot -45) 0x44e4…20a4 - exec-block: valid(17088475 0xca61…) - finalized: 0x9cbd…ba83:195776 - peers: 8

Apr-20 15:15:01.443[network]          info: Subscribed gossip core topics
Apr-20 15:15:01.446[sync]             info: Subscribed gossip core topics
Apr-20 15:15:05.000[]                 info: Synced - slot: 6264973 - head: 0x90ea…c655 - exec-block: valid(17088521 0xca9b…) - finalized: 0x6981…682f:195778 - peers: 6
Apr-20 15:15:17.003[]                 info: Synced - slot: 6264974 - head: 0x4f7e…0e3a - exec-block: valid(17088522 0x08b1…) - finalized: 0x6981…682f:195778 - peers: 6

Apr-20 15:15:41.001[]                 info: Synced - slot: 6264976 - head: (slot -1) 0x17c6…71a7 - exec-block: valid(17088524 0x5bc1…) - finalized: 0x6981…682f:195778 - peers: 8
Apr-20 15:15:53.001[]                 info: Synced - slot: 6264977 - head: (slot -2) 0x17c6…71a7 - exec-block: valid(17088524 0x5bc1…) - finalized: 0x6981…682f:195778 - peers: 8

Apr-20 15:16:05.000[]                 info: Synced - slot: 6264978 - head: 0xc9fd…28c5 - exec-block: valid(17088526 0xb5bf…) - finalized: 0x6981…682f:195778 - peers: 8
Apr-20 15:16:17.017[]                 info: Synced - slot: 6264979 - head: 0xde91…d4cb - exec-block: valid(17088527 0xa488…) - finalized: 0x6981…682f:195778 - peers: 7

@g11tech
g11tech enabled auto-merge (squash) April 20, 2023 15:53
@g11tech
g11tech merged commit fb192bf into unstable Apr 20, 2023
@g11tech
g11tech deleted the g11tech/notify-execution-blocknum branch April 20, 2023 16:03
g11tech added a commit that referenced this pull request Apr 24, 2023
g11tech added a commit that referenced this pull request Apr 24, 2023
@wemeetagain

Copy link
Copy Markdown
Member

🎉 This PR is included in v1.8.0 🎉

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

meta-discussion Indicates a topic that requires input from various developers.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants