More logs when forkchoice reorg

[twoeths]

Motivation

Forkchoice reorg rarely happens so we'd like to be as detailed as we can. An example log from lighthouse:

Beacon chain re-org                    
reorg_distance: 8,
new_slot: 3887074, 
new_head: 0x9c2a567eee0491b7d72e6dc4121f5425c3555553af0d3edcbb2978351cf8c441, 
new_head_parent: 0x1468af1a109a1bad928d4c9fab48bba66320afa4d7fd50533c4b637b15ed50e8, 
previous_slot: 3887081, 
previous_head: 0x2fb24231bf49c8dfa636615971c898f27a11a89c057814ce3ca8d0861fc78d9d,

Description

Add more infor to "Chain reorg" log

[github-actions]

Performance Report

✔️ no performance regression detected

Full benchmark results

Benchmark suite	Current: 192563f	Previous: 76f0d0d	Ratio
BeaconState.hashTreeRoot - No change	500.00 ns/op	524.00 ns/op	0.95
BeaconState.hashTreeRoot - 1 full validator	70.212 us/op	63.286 us/op	1.11
BeaconState.hashTreeRoot - 32 full validator	693.25 us/op	640.04 us/op	1.08
BeaconState.hashTreeRoot - 512 full validator	7.1785 ms/op	6.9359 ms/op	1.03
BeaconState.hashTreeRoot - 1 validator.effectiveBalance	92.875 us/op	80.365 us/op	1.16
BeaconState.hashTreeRoot - 32 validator.effectiveBalance	1.2412 ms/op	1.1349 ms/op	1.09
BeaconState.hashTreeRoot - 512 validator.effectiveBalance	16.216 ms/op	14.546 ms/op	1.11
BeaconState.hashTreeRoot - 1 balances	66.910 us/op	62.671 us/op	1.07
BeaconState.hashTreeRoot - 32 balances	608.36 us/op	542.13 us/op	1.12
BeaconState.hashTreeRoot - 512 balances	5.6485 ms/op	5.3034 ms/op	1.07
BeaconState.hashTreeRoot - 250000 balances	122.90 ms/op	114.22 ms/op	1.08
processSlot - 1 slots	14.820 us/op	12.667 us/op	1.17
processSlot - 32 slots	2.0482 ms/op	1.9053 ms/op	1.07
getCommitteeAssignments - req 1 vs - 250000 vc	5.2649 ms/op	6.6082 ms/op	0.80
getCommitteeAssignments - req 100 vs - 250000 vc	7.6313 ms/op	8.8049 ms/op	0.87
getCommitteeAssignments - req 1000 vs - 250000 vc	8.1437 ms/op	9.2918 ms/op	0.88
computeProposers - vc 250000	18.757 ms/op	18.682 ms/op	1.00
computeEpochShuffling - vc 250000	170.78 ms/op	196.34 ms/op	0.87
getNextSyncCommittee - vc 250000	316.49 ms/op	320.19 ms/op	0.99
altair processAttestation - 250000 vs - 7PWei normalcase	4.1636 ms/op	4.0027 ms/op	1.04
altair processAttestation - 250000 vs - 7PWei worstcase	6.0629 ms/op	6.3647 ms/op	0.95
altair processAttestation - setStatus - 1/6 committees join	231.38 us/op	214.96 us/op	1.08
altair processAttestation - setStatus - 1/3 committees join	412.45 us/op	453.73 us/op	0.91
altair processAttestation - setStatus - 1/2 committees join	604.28 us/op	602.84 us/op	1.00
altair processAttestation - setStatus - 2/3 committees join	782.71 us/op	789.30 us/op	0.99
altair processAttestation - setStatus - 4/5 committees join	1.0458 ms/op	965.93 us/op	1.08
altair processAttestation - setStatus - 100% committees join	1.3877 ms/op	1.2828 ms/op	1.08
altair processBlock - 250000 vs - 7PWei normalcase	30.272 ms/op	30.340 ms/op	1.00
altair processBlock - 250000 vs - 7PWei normalcase hashState	41.245 ms/op	43.108 ms/op	0.96
altair processBlock - 250000 vs - 7PWei worstcase	84.698 ms/op	93.830 ms/op	0.90
altair processBlock - 250000 vs - 7PWei worstcase hashState	112.76 ms/op	115.15 ms/op	0.98
altair processEth1Data - 250000 vs - 7PWei normalcase	1.1187 ms/op	1.0395 ms/op	1.08
altair processEpoch - mainnet_e81889	615.76 ms/op	649.93 ms/op	0.95
mainnet_e81889 - altair beforeProcessEpoch	168.79 ms/op	154.77 ms/op	1.09
mainnet_e81889 - altair processJustificationAndFinalization	64.784 us/op	46.586 us/op	1.39
mainnet_e81889 - altair processInactivityUpdates	11.009 ms/op	11.581 ms/op	0.95
mainnet_e81889 - altair processRewardsAndPenalties	97.132 ms/op	155.30 ms/op	0.63
mainnet_e81889 - altair processRegistryUpdates	15.046 us/op	7.4610 us/op	2.02
mainnet_e81889 - altair processSlashings	4.6180 us/op	2.3370 us/op	1.98
mainnet_e81889 - altair processEth1DataReset	4.3130 us/op	2.2970 us/op	1.88
mainnet_e81889 - altair processEffectiveBalanceUpdates	2.4365 ms/op	2.8447 ms/op	0.86
mainnet_e81889 - altair processSlashingsReset	19.676 us/op	10.228 us/op	1.92
mainnet_e81889 - altair processRandaoMixesReset	25.148 us/op	14.774 us/op	1.70
mainnet_e81889 - altair processHistoricalRootsUpdate	4.1600 us/op	2.4290 us/op	1.71
mainnet_e81889 - altair processParticipationFlagUpdates	15.277 us/op	10.345 us/op	1.48
mainnet_e81889 - altair processSyncCommitteeUpdates	3.9640 us/op	2.1170 us/op	1.87
mainnet_e81889 - altair afterProcessEpoch	203.58 ms/op	221.74 ms/op	0.92
altair processInactivityUpdates - 250000 normalcase	51.068 ms/op	34.477 ms/op	1.48
altair processInactivityUpdates - 250000 worstcase	39.271 ms/op	27.764 ms/op	1.41
altair processRewardsAndPenalties - 250000 normalcase	90.759 ms/op	148.37 ms/op	0.61
altair processRewardsAndPenalties - 250000 worstcase	154.66 ms/op	93.415 ms/op	1.66
altair processSyncCommitteeUpdates - 250000	319.02 ms/op	312.95 ms/op	1.02
Tree 40 250000 create	811.16 ms/op	859.85 ms/op	0.94
Tree 40 250000 get(125000)	312.00 ns/op	308.72 ns/op	1.01
Tree 40 250000 set(125000)	2.7200 us/op	2.8052 us/op	0.97
Tree 40 250000 toArray()	34.218 ms/op	36.810 ms/op	0.93
Tree 40 250000 iterate all - toArray() + loop	35.533 ms/op	35.272 ms/op	1.01
Tree 40 250000 iterate all - get(i)	129.17 ms/op	129.99 ms/op	0.99
MutableVector 250000 create	16.364 ms/op	20.864 ms/op	0.78
MutableVector 250000 get(125000)	13.625 ns/op	15.425 ns/op	0.88
MutableVector 250000 set(125000)	745.45 ns/op	687.64 ns/op	1.08
MutableVector 250000 toArray()	6.9993 ms/op	7.7767 ms/op	0.90
MutableVector 250000 iterate all - toArray() + loop	6.4626 ms/op	7.9411 ms/op	0.81
MutableVector 250000 iterate all - get(i)	3.4002 ms/op	3.8211 ms/op	0.89
Array 250000 create	6.0279 ms/op	6.5031 ms/op	0.93
Array 250000 clone - spread	3.8094 ms/op	3.6094 ms/op	1.06
Array 250000 get(125000)	1.7020 ns/op	1.6450 ns/op	1.03
Array 250000 set(125000)	1.6650 ns/op	1.6690 ns/op	1.00
Array 250000 iterate all - loop	140.19 us/op	191.31 us/op	0.73
effectiveBalanceIncrements clone Uint8Array 300000	85.549 us/op	87.638 us/op	0.98
effectiveBalanceIncrements clone MutableVector 300000	1.2390 us/op	1.2020 us/op	1.03
effectiveBalanceIncrements rw all Uint8Array 300000	287.63 us/op	285.63 us/op	1.01
effectiveBalanceIncrements rw all MutableVector 300000	240.65 ms/op	217.38 ms/op	1.11
aggregationBits - 2048 els - zipIndexesInBitList	33.464 us/op	35.008 us/op	0.96
regular array get 100000 times	56.299 us/op	76.589 us/op	0.74
wrappedArray get 100000 times	56.404 us/op	76.304 us/op	0.74
arrayWithProxy get 100000 times	34.426 ms/op	33.207 ms/op	1.04
ssz.Root.equals	604.00 ns/op	517.00 ns/op	1.17
byteArrayEquals	589.00 ns/op	564.00 ns/op	1.04
phase0 processBlock - 250000 vs - 7PWei normalcase	4.2462 ms/op	3.9442 ms/op	1.08
phase0 processBlock - 250000 vs - 7PWei worstcase	53.437 ms/op	53.090 ms/op	1.01
phase0 afterProcessEpoch - 250000 vs - 7PWei	190.04 ms/op	214.61 ms/op	0.89
phase0 beforeProcessEpoch - 250000 vs - 7PWei	77.563 ms/op	80.956 ms/op	0.96
phase0 processEpoch - mainnet_e58758	657.22 ms/op	581.17 ms/op	1.13
mainnet_e58758 - phase0 beforeProcessEpoch	264.20 ms/op	250.96 ms/op	1.05
mainnet_e58758 - phase0 processJustificationAndFinalization	65.018 us/op	44.276 us/op	1.47
mainnet_e58758 - phase0 processRewardsAndPenalties	141.64 ms/op	138.73 ms/op	1.02
mainnet_e58758 - phase0 processRegistryUpdates	30.446 us/op	16.738 us/op	1.82
mainnet_e58758 - phase0 processSlashings	4.0760 us/op	2.5400 us/op	1.60
mainnet_e58758 - phase0 processEth1DataReset	3.6950 us/op	2.3130 us/op	1.60
mainnet_e58758 - phase0 processEffectiveBalanceUpdates	2.4599 ms/op	2.4741 ms/op	0.99
mainnet_e58758 - phase0 processSlashingsReset	20.483 us/op	12.594 us/op	1.63
mainnet_e58758 - phase0 processRandaoMixesReset	24.738 us/op	17.273 us/op	1.43
mainnet_e58758 - phase0 processHistoricalRootsUpdate	4.0570 us/op	2.3060 us/op	1.76
mainnet_e58758 - phase0 processParticipationRecordUpdates	22.577 us/op	14.787 us/op	1.53
mainnet_e58758 - phase0 afterProcessEpoch	160.90 ms/op	179.39 ms/op	0.90
phase0 processEffectiveBalanceUpdates - 250000 normalcase	2.3837 ms/op	3.3702 ms/op	0.71
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5	2.7704 ms/op	3.5936 ms/op	0.77
phase0 processRegistryUpdates - 250000 normalcase	26.595 us/op	18.149 us/op	1.47
phase0 processRegistryUpdates - 250000 badcase_full_deposits	484.35 us/op	518.58 us/op	0.93
phase0 processRegistryUpdates - 250000 worstcase 0.5	236.49 ms/op	243.71 ms/op	0.97
phase0 getAttestationDeltas - 250000 normalcase	14.082 ms/op	16.666 ms/op	0.84
phase0 getAttestationDeltas - 250000 worstcase	14.051 ms/op	16.538 ms/op	0.85
phase0 processSlashings - 250000 worstcase	6.7442 ms/op	6.4324 ms/op	1.05
shuffle list - 16384 els	11.581 ms/op	13.137 ms/op	0.88
shuffle list - 250000 els	165.50 ms/op	195.94 ms/op	0.84
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei	468.41 us/op	396.49 us/op	1.18
pass gossip attestations to forkchoice per slot	3.6694 ms/op	3.7797 ms/op	0.97
computeDeltas	4.0802 ms/op	3.8159 ms/op	1.07
computeProposerBoostScoreFromBalances	867.78 us/op	1.0591 ms/op	0.82
getPubkeys - index2pubkey - req 1000 vs - 250000 vc	2.4546 ms/op	2.4141 ms/op	1.02
getPubkeys - validatorsArr - req 1000 vs - 250000 vc	80.006 us/op	88.342 us/op	0.91
BLS verify - blst-native	2.2750 ms/op	2.1893 ms/op	1.04
BLS verifyMultipleSignatures 3 - blst-native	4.4276 ms/op	4.4099 ms/op	1.00
BLS verifyMultipleSignatures 8 - blst-native	9.9451 ms/op	9.8312 ms/op	1.01
BLS verifyMultipleSignatures 32 - blst-native	35.697 ms/op	34.932 ms/op	1.02
BLS aggregatePubkeys 32 - blst-native	47.398 us/op	46.215 us/op	1.03
BLS aggregatePubkeys 128 - blst-native	183.94 us/op	175.45 us/op	1.05
getAttestationsForBlock	61.466 ms/op	74.353 ms/op	0.83
isKnown best case - 1 super set check	497.00 ns/op	511.00 ns/op	0.97
isKnown normal case - 2 super set checks	492.00 ns/op	502.00 ns/op	0.98
isKnown worse case - 16 super set checks	487.00 ns/op	503.00 ns/op	0.97
CheckpointStateCache - add get delete	12.939 us/op	12.449 us/op	1.04
validate gossip signedAggregateAndProof - struct	5.0090 ms/op	4.9214 ms/op	1.02
validate gossip attestation - struct	2.3827 ms/op	2.3278 ms/op	1.02
altair verifyImport mainnet_s3766816:31	7.1861 s/op	7.3074 s/op	0.98
pickEth1Vote - no votes	2.4016 ms/op	2.5162 ms/op	0.95
pickEth1Vote - max votes	28.387 ms/op	31.378 ms/op	0.90
pickEth1Vote - Eth1Data hashTreeRoot value x2048	14.255 ms/op	13.877 ms/op	1.03
pickEth1Vote - Eth1Data hashTreeRoot tree x2048	24.935 ms/op	27.401 ms/op	0.91
pickEth1Vote - Eth1Data fastSerialize value x2048	1.6550 ms/op	1.8826 ms/op	0.88
pickEth1Vote - Eth1Data fastSerialize tree x2048	19.852 ms/op	22.163 ms/op	0.90
bytes32 toHexString	1.2200 us/op	1.2080 us/op	1.01
bytes32 Buffer.toString(hex)	786.00 ns/op	838.00 ns/op	0.94
bytes32 Buffer.toString(hex) from Uint8Array	1.0450 us/op	1.1480 us/op	0.91
bytes32 Buffer.toString(hex) + 0x	794.00 ns/op	788.00 ns/op	1.01
Object access 1 prop	0.40900 ns/op	0.43400 ns/op	0.94
Map access 1 prop	0.33400 ns/op	0.33600 ns/op	0.99
Object get x1000	16.129 ns/op	20.373 ns/op	0.79
Map get x1000	0.96300 ns/op	1.1570 ns/op	0.83
Object set x1000	104.21 ns/op	134.08 ns/op	0.78
Map set x1000	70.890 ns/op	79.738 ns/op	0.89
Return object 10000 times	0.40660 ns/op	0.42740 ns/op	0.95
Throw Error 10000 times	6.9698 us/op	6.5733 us/op	1.06
enrSubnets - fastDeserialize 64 bits	3.0820 us/op	3.0370 us/op	1.01
enrSubnets - ssz BitVector 64 bits	838.00 ns/op	957.00 ns/op	0.88
enrSubnets - fastDeserialize 4 bits	391.00 ns/op	462.00 ns/op	0.85
enrSubnets - ssz BitVector 4 bits	840.00 ns/op	952.00 ns/op	0.88
prioritizePeers score -10:0 att 32-0.1 sync 2-0	106.98 us/op	114.62 us/op	0.93
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25	148.36 us/op	173.43 us/op	0.86
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5	262.14 us/op	276.50 us/op	0.95
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75	582.44 us/op	458.27 us/op	1.27
prioritizePeers score 0:0 att 64-1 sync 4-1	542.25 us/op	536.59 us/op	1.01
RateTracker 1000000 limit, 1 obj count per request	198.17 ns/op	244.24 ns/op	0.81
RateTracker 1000000 limit, 2 obj count per request	159.53 ns/op	177.72 ns/op	0.90
RateTracker 1000000 limit, 4 obj count per request	126.73 ns/op	145.77 ns/op	0.87
RateTracker 1000000 limit, 8 obj count per request	113.84 ns/op	125.28 ns/op	0.91
RateTracker with prune	4.8930 us/op	5.2390 us/op	0.93
array of 16000 items push then shift	5.2080 us/op	3.7437 us/op	1.39
LinkedList of 16000 items push then shift	27.221 ns/op	27.575 ns/op	0.99
array of 16000 items push then pop	257.95 ns/op	277.35 ns/op	0.93
LinkedList of 16000 items push then pop	21.549 ns/op	23.579 ns/op	0.91
array of 24000 items push then shift	7.7412 us/op	5.3495 us/op	1.45
LinkedList of 24000 items push then shift	28.247 ns/op	28.180 ns/op	1.00
array of 24000 items push then pop	214.88 ns/op	251.48 ns/op	0.85
LinkedList of 24000 items push then pop	23.122 ns/op	24.747 ns/op	0.93
intersect bitArray bitLen 8	12.497 ns/op	13.825 ns/op	0.90
intersect array and set length 8	193.85 ns/op	211.38 ns/op	0.92
intersect bitArray bitLen 128	70.342 ns/op	88.852 ns/op	0.79
intersect array and set length 128	2.1718 us/op	2.8722 us/op	0.76

by benchmarkbot/action