Skip to content

Log index if attestations are published per committee - #5307

Merged
twoeths merged 1 commit into
unstablefrom
nflaig/log-committee-index
Mar 28, 2023
Merged

Log index if attestations are published per committee#5307
twoeths merged 1 commit into
unstablefrom
nflaig/log-committee-index

Conversation

@nflaig

@nflaig nflaig commented Mar 27, 2023 •
edited
Loading

Copy link
Copy Markdown
Member

Motivation

If attestation grouping optimization is disabled via disableAttestationGrouping then attestations are published per committee. Not including the committee index in the log makes it hard to debug and is bit confusing in the logs as there are a lot of duplicate logs for the same slot.

Current log

info: Published attestations slot=5286297, count=1
info: Published attestations slot=5286297, count=1
info: Published attestations slot=5286297, count=1
info: Published attestations slot=5286297, count=1

Expected log

info: Published attestations slot=5286334, index=42, count=1
info: Published attestations slot=5286334, index=52, count=1
info: Published attestations slot=5286334, index=21, count=1
info: Published attestations slot=5286334, index=48, count=1

Description

Includes index in publish attestations log if disableAttestationGrouping is set to true.

@nflaig
nflaig requested a review from a team as a code owner March 27, 2023 19:07
@github-actions

github-actions Bot commented Mar 27, 2023

Copy link
Copy Markdown
Contributor

Performance Report

鉁旓笍 no performance regression detected

Full benchmark results
Benchmark suite Current: ec97c24 Previous: b861ab8 Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 713.32 us/op 902.87 us/op 0.79
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 81.591 us/op 46.746 us/op 1.75
BLS verify - blst-native 1.4904 ms/op 1.2268 ms/op 1.21
BLS verifyMultipleSignatures 3 - blst-native 2.7243 ms/op 2.4862 ms/op 1.10
BLS verifyMultipleSignatures 8 - blst-native 6.2016 ms/op 5.3377 ms/op 1.16
BLS verifyMultipleSignatures 32 - blst-native 22.742 ms/op 19.364 ms/op 1.17
BLS aggregatePubkeys 32 - blst-native 29.506 us/op 26.459 us/op 1.12
BLS aggregatePubkeys 128 - blst-native 115.20 us/op 101.51 us/op 1.13
getAttestationsForBlock 78.445 ms/op 52.723 ms/op 1.49
isKnown best case - 1 super set check 291.00 ns/op 246.00 ns/op 1.18
isKnown normal case - 2 super set checks 290.00 ns/op 240.00 ns/op 1.21
isKnown worse case - 16 super set checks 282.00 ns/op 244.00 ns/op 1.16
CheckpointStateCache - add get delete 6.6830 us/op 4.8540 us/op 1.38
validate gossip signedAggregateAndProof - struct 3.1588 ms/op 2.7776 ms/op 1.14
validate gossip attestation - struct 1.5634 ms/op 1.3290 ms/op 1.18
pickEth1Vote - no votes 1.4647 ms/op 1.2548 ms/op 1.17
pickEth1Vote - max votes 13.369 ms/op 11.555 ms/op 1.16
pickEth1Vote - Eth1Data hashTreeRoot value x2048 11.946 ms/op 9.1310 ms/op 1.31
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 18.145 ms/op 14.489 ms/op 1.25
pickEth1Vote - Eth1Data fastSerialize value x2048 934.05 us/op 648.69 us/op 1.44
pickEth1Vote - Eth1Data fastSerialize tree x2048 8.6713 ms/op 7.7747 ms/op 1.12
bytes32 toHexString 802.00 ns/op 478.00 ns/op 1.68
bytes32 Buffer.toString(hex) 483.00 ns/op 343.00 ns/op 1.41
bytes32 Buffer.toString(hex) from Uint8Array 733.00 ns/op 531.00 ns/op 1.38
bytes32 Buffer.toString(hex) + 0x 527.00 ns/op 333.00 ns/op 1.58
Object access 1 prop 0.22800 ns/op 0.16400 ns/op 1.39
Map access 1 prop 0.21500 ns/op 0.15600 ns/op 1.38
Object get x1000 7.3250 ns/op 6.4860 ns/op 1.13
Map get x1000 0.70200 ns/op 0.56000 ns/op 1.25
Object set x1000 84.631 ns/op 49.833 ns/op 1.70
Map set x1000 63.689 ns/op 41.887 ns/op 1.52
Return object 10000 times 0.28880 ns/op 0.22860 ns/op 1.26
Throw Error 10000 times 4.7796 us/op 4.0222 us/op 1.19
fastMsgIdFn sha256 / 200 bytes 3.9180 us/op 3.3280 us/op 1.18
fastMsgIdFn h32 xxhash / 200 bytes 364.00 ns/op 270.00 ns/op 1.35
fastMsgIdFn h64 xxhash / 200 bytes 549.00 ns/op 378.00 ns/op 1.45
fastMsgIdFn sha256 / 1000 bytes 13.052 us/op 11.310 us/op 1.15
fastMsgIdFn h32 xxhash / 1000 bytes 486.00 ns/op 396.00 ns/op 1.23
fastMsgIdFn h64 xxhash / 1000 bytes 610.00 ns/op 448.00 ns/op 1.36
fastMsgIdFn sha256 / 10000 bytes 115.66 us/op 100.95 us/op 1.15
fastMsgIdFn h32 xxhash / 10000 bytes 2.1540 us/op 1.8620 us/op 1.16
fastMsgIdFn h64 xxhash / 10000 bytes 1.6030 us/op 1.3250 us/op 1.21
enrSubnets - fastDeserialize 64 bits 1.9060 us/op 1.2530 us/op 1.52
enrSubnets - ssz BitVector 64 bits 653.00 ns/op 462.00 ns/op 1.41
enrSubnets - fastDeserialize 4 bits 235.00 ns/op 165.00 ns/op 1.42
enrSubnets - ssz BitVector 4 bits 727.00 ns/op 468.00 ns/op 1.55
prioritizePeers score -10:0 att 32-0.1 sync 2-0 120.92 us/op 104.63 us/op 1.16
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 174.96 us/op 129.97 us/op 1.35
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 208.19 us/op 171.67 us/op 1.21
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 424.58 us/op 302.50 us/op 1.40
prioritizePeers score 0:0 att 64-1 sync 4-1 478.92 us/op 364.82 us/op 1.31
array of 16000 items push then shift 1.8791 us/op 1.6274 us/op 1.15
LinkedList of 16000 items push then shift 10.026 ns/op 8.8590 ns/op 1.13
array of 16000 items push then pop 134.59 ns/op 78.641 ns/op 1.71
LinkedList of 16000 items push then pop 10.655 ns/op 8.6300 ns/op 1.23
array of 24000 items push then shift 2.5987 us/op 2.3913 us/op 1.09
LinkedList of 24000 items push then shift 10.397 ns/op 8.8530 ns/op 1.17
array of 24000 items push then pop 96.114 ns/op 74.127 ns/op 1.30
LinkedList of 24000 items push then pop 9.6540 ns/op 8.3720 ns/op 1.15
intersect bitArray bitLen 8 14.901 ns/op 13.167 ns/op 1.13
intersect array and set length 8 116.50 ns/op 76.914 ns/op 1.51
intersect bitArray bitLen 128 48.207 ns/op 43.571 ns/op 1.11
intersect array and set length 128 1.3778 us/op 1.0424 us/op 1.32
Buffer.concat 32 items 2.9900 us/op 2.5760 us/op 1.16
Uint8Array.set 32 items 2.4830 us/op 2.9030 us/op 0.86
pass gossip attestations to forkchoice per slot 4.0631 ms/op 3.1369 ms/op 1.30
computeDeltas 3.3630 ms/op 3.3523 ms/op 1.00
computeProposerBoostScoreFromBalances 1.8670 ms/op 1.7936 ms/op 1.04
altair processAttestation - 250000 vs - 7PWei normalcase 2.7516 ms/op 2.1321 ms/op 1.29
altair processAttestation - 250000 vs - 7PWei worstcase 4.2272 ms/op 3.3587 ms/op 1.26
altair processAttestation - setStatus - 1/6 committees join 142.74 us/op 142.07 us/op 1.00
altair processAttestation - setStatus - 1/3 committees join 286.10 us/op 279.48 us/op 1.02
altair processAttestation - setStatus - 1/2 committees join 391.72 us/op 358.46 us/op 1.09
altair processAttestation - setStatus - 2/3 committees join 482.90 us/op 446.96 us/op 1.08
altair processAttestation - setStatus - 4/5 committees join 676.41 us/op 636.80 us/op 1.06
altair processAttestation - setStatus - 100% committees join 804.50 us/op 752.99 us/op 1.07
altair processBlock - 250000 vs - 7PWei normalcase 21.290 ms/op 18.435 ms/op 1.15
altair processBlock - 250000 vs - 7PWei normalcase hashState 31.098 ms/op 28.389 ms/op 1.10
altair processBlock - 250000 vs - 7PWei worstcase 51.851 ms/op 47.485 ms/op 1.09
altair processBlock - 250000 vs - 7PWei worstcase hashState 71.737 ms/op 65.453 ms/op 1.10
phase0 processBlock - 250000 vs - 7PWei normalcase 2.4900 ms/op 1.9827 ms/op 1.26
phase0 processBlock - 250000 vs - 7PWei worstcase 33.623 ms/op 26.991 ms/op 1.25
altair processEth1Data - 250000 vs - 7PWei normalcase 669.71 us/op 451.59 us/op 1.48
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 11.645 us/op 6.7240 us/op 1.73
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 35.064 us/op 19.591 us/op 1.79
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 15.883 us/op 8.2370 us/op 1.93
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 12.026 us/op 6.1490 us/op 1.96
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 114.99 us/op 74.511 us/op 1.54
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 685.58 us/op 627.01 us/op 1.09
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 1.0752 ms/op 910.46 us/op 1.18
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 934.57 us/op 854.80 us/op 1.09
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.8680 ms/op 2.2624 ms/op 1.27
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.5784 ms/op 1.4799 ms/op 1.07
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 4.0363 ms/op 3.7144 ms/op 1.09
Tree 40 250000 create 345.47 ms/op 294.90 ms/op 1.17
Tree 40 250000 get(125000) 198.57 ns/op 177.52 ns/op 1.12
Tree 40 250000 set(125000) 1.0917 us/op 841.54 ns/op 1.30
Tree 40 250000 toArray() 23.019 ms/op 16.070 ms/op 1.43
Tree 40 250000 iterate all - toArray() + loop 22.377 ms/op 16.193 ms/op 1.38
Tree 40 250000 iterate all - get(i) 80.190 ms/op 63.605 ms/op 1.26
MutableVector 250000 create 12.521 ms/op 9.9340 ms/op 1.26
MutableVector 250000 get(125000) 6.7300 ns/op 6.0540 ns/op 1.11
MutableVector 250000 set(125000) 290.69 ns/op 248.56 ns/op 1.17
MutableVector 250000 toArray() 3.6463 ms/op 2.7310 ms/op 1.34
MutableVector 250000 iterate all - toArray() + loop 4.1806 ms/op 2.8652 ms/op 1.46
MutableVector 250000 iterate all - get(i) 1.6215 ms/op 1.4489 ms/op 1.12
Array 250000 create 3.8749 ms/op 2.4904 ms/op 1.56
Array 250000 clone - spread 1.3468 ms/op 1.2991 ms/op 1.04
Array 250000 get(125000) 0.67900 ns/op 0.60300 ns/op 1.13
Array 250000 set(125000) 0.80300 ns/op 0.67100 ns/op 1.20
Array 250000 iterate all - loop 87.448 us/op 82.726 us/op 1.06
effectiveBalanceIncrements clone Uint8Array 300000 46.241 us/op 27.322 us/op 1.69
effectiveBalanceIncrements clone MutableVector 300000 447.00 ns/op 404.00 ns/op 1.11
effectiveBalanceIncrements rw all Uint8Array 300000 177.38 us/op 168.43 us/op 1.05
effectiveBalanceIncrements rw all MutableVector 300000 92.679 ms/op 82.996 ms/op 1.12
phase0 afterProcessEpoch - 250000 vs - 7PWei 121.26 ms/op 113.59 ms/op 1.07
phase0 beforeProcessEpoch - 250000 vs - 7PWei 40.054 ms/op 42.867 ms/op 0.93
altair processEpoch - mainnet_e81889 367.84 ms/op 305.02 ms/op 1.21
mainnet_e81889 - altair beforeProcessEpoch 83.242 ms/op 63.387 ms/op 1.31
mainnet_e81889 - altair processJustificationAndFinalization 31.628 us/op 17.679 us/op 1.79
mainnet_e81889 - altair processInactivityUpdates 7.5942 ms/op 5.3227 ms/op 1.43
mainnet_e81889 - altair processRewardsAndPenalties 79.467 ms/op 53.641 ms/op 1.48
mainnet_e81889 - altair processRegistryUpdates 6.6210 us/op 2.6770 us/op 2.47
mainnet_e81889 - altair processSlashings 1.4640 us/op 612.00 ns/op 2.39
mainnet_e81889 - altair processEth1DataReset 1.2110 us/op 786.00 ns/op 1.54
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.4902 ms/op 1.3085 ms/op 1.14
mainnet_e81889 - altair processSlashingsReset 5.2150 us/op 5.5330 us/op 0.94
mainnet_e81889 - altair processRandaoMixesReset 8.9990 us/op 4.8890 us/op 1.84
mainnet_e81889 - altair processHistoricalRootsUpdate 2.2530 us/op 665.00 ns/op 3.39
mainnet_e81889 - altair processParticipationFlagUpdates 5.0340 us/op 2.3090 us/op 2.18
mainnet_e81889 - altair processSyncCommitteeUpdates 775.00 ns/op 612.00 ns/op 1.27
mainnet_e81889 - altair afterProcessEpoch 144.07 ms/op 123.92 ms/op 1.16
phase0 processEpoch - mainnet_e58758 408.40 ms/op 319.33 ms/op 1.28
mainnet_e58758 - phase0 beforeProcessEpoch 163.96 ms/op 124.57 ms/op 1.32
mainnet_e58758 - phase0 processJustificationAndFinalization 20.920 us/op 15.435 us/op 1.36
mainnet_e58758 - phase0 processRewardsAndPenalties 67.156 ms/op 55.397 ms/op 1.21
mainnet_e58758 - phase0 processRegistryUpdates 11.670 us/op 8.9250 us/op 1.31
mainnet_e58758 - phase0 processSlashings 651.00 ns/op 535.00 ns/op 1.22
mainnet_e58758 - phase0 processEth1DataReset 919.00 ns/op 599.00 ns/op 1.53
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 1.0894 ms/op 994.36 us/op 1.10
mainnet_e58758 - phase0 processSlashingsReset 4.0480 us/op 3.3820 us/op 1.20
mainnet_e58758 - phase0 processRandaoMixesReset 6.7880 us/op 4.5490 us/op 1.49
mainnet_e58758 - phase0 processHistoricalRootsUpdate 1.0500 us/op 883.00 ns/op 1.19
mainnet_e58758 - phase0 processParticipationRecordUpdates 4.4780 us/op 5.6430 us/op 0.79
mainnet_e58758 - phase0 afterProcessEpoch 104.72 ms/op 96.639 ms/op 1.08
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.2842 ms/op 1.2713 ms/op 1.01
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.5563 ms/op 1.5035 ms/op 1.04
altair processInactivityUpdates - 250000 normalcase 27.904 ms/op 26.604 ms/op 1.05
altair processInactivityUpdates - 250000 worstcase 30.094 ms/op 37.941 ms/op 0.79
phase0 processRegistryUpdates - 250000 normalcase 9.6100 us/op 20.655 us/op 0.47
phase0 processRegistryUpdates - 250000 badcase_full_deposits 320.02 us/op 538.22 us/op 0.59
phase0 processRegistryUpdates - 250000 worstcase 0.5 158.08 ms/op 208.78 ms/op 0.76
altair processRewardsAndPenalties - 250000 normalcase 72.638 ms/op 100.51 ms/op 0.72
altair processRewardsAndPenalties - 250000 worstcase 74.616 ms/op 105.94 ms/op 0.70
phase0 getAttestationDeltas - 250000 normalcase 7.2099 ms/op 12.856 ms/op 0.56
phase0 getAttestationDeltas - 250000 worstcase 8.8742 ms/op 13.070 ms/op 0.68
phase0 processSlashings - 250000 worstcase 3.8192 ms/op 7.5046 ms/op 0.51
altair processSyncCommitteeUpdates - 250000 200.34 ms/op 220.84 ms/op 0.91
BeaconState.hashTreeRoot - No change 288.00 ns/op 354.00 ns/op 0.81
BeaconState.hashTreeRoot - 1 full validator 54.555 us/op 71.761 us/op 0.76
BeaconState.hashTreeRoot - 32 full validator 581.95 us/op 678.42 us/op 0.86
BeaconState.hashTreeRoot - 512 full validator 5.7922 ms/op 7.1447 ms/op 0.81
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 70.645 us/op 66.046 us/op 1.07
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 953.11 us/op 1.0266 ms/op 0.93
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 12.100 ms/op 14.820 ms/op 0.82
BeaconState.hashTreeRoot - 1 balances 53.138 us/op 54.563 us/op 0.97
BeaconState.hashTreeRoot - 32 balances 467.43 us/op 580.07 us/op 0.81
BeaconState.hashTreeRoot - 512 balances 4.8548 ms/op 5.9385 ms/op 0.82
BeaconState.hashTreeRoot - 250000 balances 86.054 ms/op 105.57 ms/op 0.82
aggregationBits - 2048 els - zipIndexesInBitList 29.223 us/op 39.111 us/op 0.75
regular array get 100000 times 38.179 us/op 41.625 us/op 0.92
wrappedArray get 100000 times 37.228 us/op 36.893 us/op 1.01
arrayWithProxy get 100000 times 17.385 ms/op 16.780 ms/op 1.04
ssz.Root.equals 628.00 ns/op 720.00 ns/op 0.87
byteArrayEquals 615.00 ns/op 810.00 ns/op 0.76
shuffle list - 16384 els 8.0717 ms/op 7.7617 ms/op 1.04
shuffle list - 250000 els 111.47 ms/op 126.50 ms/op 0.88
processSlot - 1 slots 11.483 us/op 13.581 us/op 0.85
processSlot - 32 slots 1.6105 ms/op 1.6638 ms/op 0.97
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 44.209 ms/op 39.744 ms/op 1.11
getCommitteeAssignments - req 1 vs - 250000 vc 3.4092 ms/op 2.9538 ms/op 1.15
getCommitteeAssignments - req 100 vs - 250000 vc 4.6898 ms/op 4.1995 ms/op 1.12
getCommitteeAssignments - req 1000 vs - 250000 vc 5.3256 ms/op 4.4752 ms/op 1.19
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 6.4900 ns/op 4.7400 ns/op 1.37
state getBlockRootAtSlot - 250000 vs - 7PWei 1.1224 us/op 1.0465 us/op 1.07
computeProposers - vc 250000 15.302 ms/op 12.489 ms/op 1.23
computeEpochShuffling - vc 250000 129.23 ms/op 111.58 ms/op 1.16
getNextSyncCommittee - vc 250000 222.49 ms/op 200.11 ms/op 1.11

by benchmarkbot/action

@twoeths
twoeths merged commit f136f95 into unstable Mar 28, 2023
@twoeths
twoeths deleted the nflaig/log-committee-index branch March 28, 2023 02:36
@wemeetagain

wemeetagain commented May 4, 2023

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

Reviewers

@twoeths twoeths twoeths approved these changes
+1 more reviewer
@dapplion dapplion dapplion approved these changes
Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@nflaig @wemeetagain @twoeths @dapplion