Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fix: deduplicate notifier log #5545

Merged
merged 2 commits into from
May 30, 2023
Merged

fix: deduplicate notifier log #5545

merged 2 commits into from
May 30, 2023

Conversation

twoeths
Copy link
Contributor

@twoeths twoeths commented May 26, 2023

Motivation

Duplicate Synced log per slot, almost at the same time

May-23 21:36:28.999[]                 info: Synced - slot: 6504480 - head: 0xbf13…d6c8 - exec-block: valid(17324638 0x87bf…) - finalized: 0xfd48…a00d:203263 - peers: 60
May-23 21:36:29.000[]                 info: Synced - slot: 6504480 - head: 0xbf13…d6c8 - exec-block: valid(17324638 0x87bf…) - finalized: 0xfd48…a00d:203263 - peers: 60

Description

  • In timeToNextHalfSlot function, it checks which middle slot of current or next clock slot is closer and wait until that time. It happens that it does not pass middle of the current clock slot, the runNodeNotifier runs so fast and it still does not pass middle of the current clock slot so it runs again
  • The fix is to always wait for middle of next clock slot, except for the 1st time

Closes #5532

@twoeths twoeths requested a review from a team as a code owner May 26, 2023 02:03
@github-actions
Copy link
Contributor

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: db758c3 Previous: cacb99b Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 912.52 us/op 495.64 us/op 1.84
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 44.360 us/op 45.618 us/op 0.97
BLS verify - blst-native 1.2039 ms/op 1.2247 ms/op 0.98
BLS verifyMultipleSignatures 3 - blst-native 2.4482 ms/op 2.4909 ms/op 0.98
BLS verifyMultipleSignatures 8 - blst-native 5.2898 ms/op 5.3485 ms/op 0.99
BLS verifyMultipleSignatures 32 - blst-native 19.003 ms/op 19.350 ms/op 0.98
BLS aggregatePubkeys 32 - blst-native 25.020 us/op 25.953 us/op 0.96
BLS aggregatePubkeys 128 - blst-native 97.235 us/op 101.96 us/op 0.95
getAttestationsForBlock 50.552 ms/op 52.292 ms/op 0.97
isKnown best case - 1 super set check 267.00 ns/op 253.00 ns/op 1.06
isKnown normal case - 2 super set checks 259.00 ns/op 245.00 ns/op 1.06
isKnown worse case - 16 super set checks 256.00 ns/op 244.00 ns/op 1.05
CheckpointStateCache - add get delete 4.8300 us/op 5.0310 us/op 0.96
validate gossip signedAggregateAndProof - struct 2.7131 ms/op 2.7607 ms/op 0.98
validate gossip attestation - struct 1.2943 ms/op 1.3313 ms/op 0.97
pickEth1Vote - no votes 1.2050 ms/op 1.3388 ms/op 0.90
pickEth1Vote - max votes 10.773 ms/op 9.5922 ms/op 1.12
pickEth1Vote - Eth1Data hashTreeRoot value x2048 8.8061 ms/op 8.7171 ms/op 1.01
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 14.093 ms/op 13.754 ms/op 1.02
pickEth1Vote - Eth1Data fastSerialize value x2048 625.78 us/op 631.99 us/op 0.99
pickEth1Vote - Eth1Data fastSerialize tree x2048 7.8165 ms/op 4.8747 ms/op 1.60
bytes32 toHexString 475.00 ns/op 515.00 ns/op 0.92
bytes32 Buffer.toString(hex) 340.00 ns/op 350.00 ns/op 0.97
bytes32 Buffer.toString(hex) from Uint8Array 537.00 ns/op 569.00 ns/op 0.94
bytes32 Buffer.toString(hex) + 0x 341.00 ns/op 349.00 ns/op 0.98
Object access 1 prop 0.15800 ns/op 0.17100 ns/op 0.92
Map access 1 prop 0.14900 ns/op 0.15200 ns/op 0.98
Object get x1000 6.5030 ns/op 6.5040 ns/op 1.00
Map get x1000 0.58700 ns/op 0.64500 ns/op 0.91
Object set x1000 50.569 ns/op 56.873 ns/op 0.89
Map set x1000 41.818 ns/op 47.664 ns/op 0.88
Return object 10000 times 0.23020 ns/op 0.24370 ns/op 0.94
Throw Error 10000 times 4.1379 us/op 4.3378 us/op 0.95
fastMsgIdFn sha256 / 200 bytes 3.3380 us/op 3.5200 us/op 0.95
fastMsgIdFn h32 xxhash / 200 bytes 272.00 ns/op 289.00 ns/op 0.94
fastMsgIdFn h64 xxhash / 200 bytes 384.00 ns/op 412.00 ns/op 0.93
fastMsgIdFn sha256 / 1000 bytes 11.374 us/op 11.689 us/op 0.97
fastMsgIdFn h32 xxhash / 1000 bytes 395.00 ns/op 421.00 ns/op 0.94
fastMsgIdFn h64 xxhash / 1000 bytes 457.00 ns/op 481.00 ns/op 0.95
fastMsgIdFn sha256 / 10000 bytes 101.71 us/op 104.98 us/op 0.97
fastMsgIdFn h32 xxhash / 10000 bytes 1.8830 us/op 1.9460 us/op 0.97
fastMsgIdFn h64 xxhash / 10000 bytes 1.3400 us/op 1.4170 us/op 0.95
enrSubnets - fastDeserialize 64 bits 1.2410 us/op 1.3310 us/op 0.93
enrSubnets - ssz BitVector 64 bits 493.00 ns/op 494.00 ns/op 1.00
enrSubnets - fastDeserialize 4 bits 164.00 ns/op 175.00 ns/op 0.94
enrSubnets - ssz BitVector 4 bits 485.00 ns/op 510.00 ns/op 0.95
prioritizePeers score -10:0 att 32-0.1 sync 2-0 97.649 us/op 100.65 us/op 0.97
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 128.97 us/op 145.66 us/op 0.89
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 164.56 us/op 181.60 us/op 0.91
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 287.65 us/op 357.35 us/op 0.80
prioritizePeers score 0:0 att 64-1 sync 4-1 352.24 us/op 401.48 us/op 0.88
array of 16000 items push then shift 1.5839 us/op 1.6631 us/op 0.95
LinkedList of 16000 items push then shift 8.6010 ns/op 8.9390 ns/op 0.96
array of 16000 items push then pop 80.114 ns/op 101.51 ns/op 0.79
LinkedList of 16000 items push then pop 8.3190 ns/op 8.7700 ns/op 0.95
array of 24000 items push then shift 2.2972 us/op 2.3988 us/op 0.96
LinkedList of 24000 items push then shift 8.5640 ns/op 8.9710 ns/op 0.95
array of 24000 items push then pop 73.947 ns/op 80.916 ns/op 0.91
LinkedList of 24000 items push then pop 8.2520 ns/op 8.8020 ns/op 0.94
intersect bitArray bitLen 8 12.989 ns/op 13.556 ns/op 0.96
intersect array and set length 8 75.121 ns/op 83.808 ns/op 0.90
intersect bitArray bitLen 128 42.850 ns/op 44.095 ns/op 0.97
intersect array and set length 128 1.0247 us/op 1.1083 us/op 0.92
Buffer.concat 32 items 2.8330 us/op 2.9240 us/op 0.97
Uint8Array.set 32 items 2.7220 us/op 2.5100 us/op 1.08
pass gossip attestations to forkchoice per slot 2.6751 ms/op 2.7116 ms/op 0.99
computeDeltas 2.8434 ms/op 2.9779 ms/op 0.95
computeProposerBoostScoreFromBalances 1.7206 ms/op 1.8060 ms/op 0.95
altair processAttestation - 250000 vs - 7PWei normalcase 2.1301 ms/op 2.1854 ms/op 0.97
altair processAttestation - 250000 vs - 7PWei worstcase 3.2092 ms/op 3.3300 ms/op 0.96
altair processAttestation - setStatus - 1/6 committees join 138.33 us/op 141.30 us/op 0.98
altair processAttestation - setStatus - 1/3 committees join 274.12 us/op 276.52 us/op 0.99
altair processAttestation - setStatus - 1/2 committees join 365.87 us/op 369.82 us/op 0.99
altair processAttestation - setStatus - 2/3 committees join 451.07 us/op 480.65 us/op 0.94
altair processAttestation - setStatus - 4/5 committees join 641.58 us/op 667.46 us/op 0.96
altair processAttestation - setStatus - 100% committees join 756.32 us/op 761.62 us/op 0.99
altair processBlock - 250000 vs - 7PWei normalcase 17.132 ms/op 17.864 ms/op 0.96
altair processBlock - 250000 vs - 7PWei normalcase hashState 26.876 ms/op 26.593 ms/op 1.01
altair processBlock - 250000 vs - 7PWei worstcase 46.733 ms/op 49.305 ms/op 0.95
altair processBlock - 250000 vs - 7PWei worstcase hashState 67.133 ms/op 70.934 ms/op 0.95
phase0 processBlock - 250000 vs - 7PWei normalcase 2.0208 ms/op 2.0909 ms/op 0.97
phase0 processBlock - 250000 vs - 7PWei worstcase 27.324 ms/op 28.789 ms/op 0.95
altair processEth1Data - 250000 vs - 7PWei normalcase 449.97 us/op 472.39 us/op 0.95
getExpectedWithdrawals 250000 eb:1,eth1:1,we:0,wn:0,smpl:15 6.6840 us/op 7.2960 us/op 0.92
getExpectedWithdrawals 250000 eb:0.95,eth1:0.1,we:0.05,wn:0,smpl:219 19.344 us/op 21.105 us/op 0.92
getExpectedWithdrawals 250000 eb:0.95,eth1:0.3,we:0.05,wn:0,smpl:42 8.4270 us/op 8.8840 us/op 0.95
getExpectedWithdrawals 250000 eb:0.95,eth1:0.7,we:0.05,wn:0,smpl:18 6.4450 us/op 7.1020 us/op 0.91
getExpectedWithdrawals 250000 eb:0.1,eth1:0.1,we:0,wn:0,smpl:1020 74.594 us/op 83.801 us/op 0.89
getExpectedWithdrawals 250000 eb:0.03,eth1:0.03,we:0,wn:0,smpl:11777 607.68 us/op 635.63 us/op 0.96
getExpectedWithdrawals 250000 eb:0.01,eth1:0.01,we:0,wn:0,smpl:16384 898.59 us/op 896.53 us/op 1.00
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,smpl:16384 887.28 us/op 859.53 us/op 1.03
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,nocache,smpl:16384 2.2099 ms/op 2.3312 ms/op 0.95
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,smpl:16384 1.5197 ms/op 1.5254 ms/op 1.00
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,nocache,smpl:16384 3.8536 ms/op 3.8137 ms/op 1.01
Tree 40 250000 create 286.62 ms/op 302.73 ms/op 0.95
Tree 40 250000 get(125000) 176.25 ns/op 184.25 ns/op 0.96
Tree 40 250000 set(125000) 879.69 ns/op 962.09 ns/op 0.91
Tree 40 250000 toArray() 17.611 ms/op 17.731 ms/op 0.99
Tree 40 250000 iterate all - toArray() + loop 17.657 ms/op 17.648 ms/op 1.00
Tree 40 250000 iterate all - get(i) 66.950 ms/op 68.709 ms/op 0.97
MutableVector 250000 create 9.9612 ms/op 10.771 ms/op 0.92
MutableVector 250000 get(125000) 6.2290 ns/op 6.4220 ns/op 0.97
MutableVector 250000 set(125000) 255.91 ns/op 260.69 ns/op 0.98
MutableVector 250000 toArray() 2.7331 ms/op 2.6652 ms/op 1.03
MutableVector 250000 iterate all - toArray() + loop 3.0697 ms/op 2.7824 ms/op 1.10
MutableVector 250000 iterate all - get(i) 1.5054 ms/op 1.4936 ms/op 1.01
Array 250000 create 2.4842 ms/op 2.3559 ms/op 1.05
Array 250000 clone - spread 1.0741 ms/op 1.1624 ms/op 0.92
Array 250000 get(125000) 0.52400 ns/op 0.56300 ns/op 0.93
Array 250000 set(125000) 0.59900 ns/op 0.63500 ns/op 0.94
Array 250000 iterate all - loop 102.04 us/op 104.87 us/op 0.97
effectiveBalanceIncrements clone Uint8Array 300000 22.280 us/op 28.430 us/op 0.78
effectiveBalanceIncrements clone MutableVector 300000 321.00 ns/op 372.00 ns/op 0.86
effectiveBalanceIncrements rw all Uint8Array 300000 164.55 us/op 168.61 us/op 0.98
effectiveBalanceIncrements rw all MutableVector 300000 75.475 ms/op 80.506 ms/op 0.94
phase0 afterProcessEpoch - 250000 vs - 7PWei 109.57 ms/op 110.62 ms/op 0.99
phase0 beforeProcessEpoch - 250000 vs - 7PWei 39.437 ms/op 32.338 ms/op 1.22
altair processEpoch - mainnet_e81889 305.35 ms/op 298.39 ms/op 1.02
mainnet_e81889 - altair beforeProcessEpoch 62.258 ms/op 62.752 ms/op 0.99
mainnet_e81889 - altair processJustificationAndFinalization 18.101 us/op 16.045 us/op 1.13
mainnet_e81889 - altair processInactivityUpdates 5.5991 ms/op 5.2687 ms/op 1.06
mainnet_e81889 - altair processRewardsAndPenalties 47.753 ms/op 63.688 ms/op 0.75
mainnet_e81889 - altair processRegistryUpdates 2.6340 us/op 2.8170 us/op 0.94
mainnet_e81889 - altair processSlashings 502.00 ns/op 540.00 ns/op 0.93
mainnet_e81889 - altair processEth1DataReset 557.00 ns/op 510.00 ns/op 1.09
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.1932 ms/op 1.2166 ms/op 0.98
mainnet_e81889 - altair processSlashingsReset 4.5450 us/op 4.8720 us/op 0.93
mainnet_e81889 - altair processRandaoMixesReset 4.4790 us/op 4.3500 us/op 1.03
mainnet_e81889 - altair processHistoricalRootsUpdate 613.00 ns/op 615.00 ns/op 1.00
mainnet_e81889 - altair processParticipationFlagUpdates 2.2700 us/op 2.3030 us/op 0.99
mainnet_e81889 - altair processSyncCommitteeUpdates 595.00 ns/op 584.00 ns/op 1.02
mainnet_e81889 - altair afterProcessEpoch 113.38 ms/op 112.53 ms/op 1.01
phase0 processEpoch - mainnet_e58758 318.23 ms/op 317.38 ms/op 1.00
mainnet_e58758 - phase0 beforeProcessEpoch 122.50 ms/op 122.53 ms/op 1.00
mainnet_e58758 - phase0 processJustificationAndFinalization 16.647 us/op 15.448 us/op 1.08
mainnet_e58758 - phase0 processRewardsAndPenalties 53.017 ms/op 55.994 ms/op 0.95
mainnet_e58758 - phase0 processRegistryUpdates 8.3470 us/op 7.6370 us/op 1.09
mainnet_e58758 - phase0 processSlashings 465.00 ns/op 519.00 ns/op 0.90
mainnet_e58758 - phase0 processEth1DataReset 505.00 ns/op 537.00 ns/op 0.94
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 978.37 us/op 940.69 us/op 1.04
mainnet_e58758 - phase0 processSlashingsReset 3.2480 us/op 2.8930 us/op 1.12
mainnet_e58758 - phase0 processRandaoMixesReset 4.5350 us/op 4.1010 us/op 1.11
mainnet_e58758 - phase0 processHistoricalRootsUpdate 582.00 ns/op 600.00 ns/op 0.97
mainnet_e58758 - phase0 processParticipationRecordUpdates 3.8450 us/op 3.9040 us/op 0.98
mainnet_e58758 - phase0 afterProcessEpoch 97.158 ms/op 92.755 ms/op 1.05
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.2357 ms/op 1.1495 ms/op 1.08
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.4500 ms/op 1.4323 ms/op 1.01
altair processInactivityUpdates - 250000 normalcase 23.181 ms/op 22.182 ms/op 1.05
altair processInactivityUpdates - 250000 worstcase 23.353 ms/op 20.154 ms/op 1.16
phase0 processRegistryUpdates - 250000 normalcase 5.9830 us/op 6.1930 us/op 0.97
phase0 processRegistryUpdates - 250000 badcase_full_deposits 238.10 us/op 227.10 us/op 1.05
phase0 processRegistryUpdates - 250000 worstcase 0.5 110.78 ms/op 111.10 ms/op 1.00
altair processRewardsAndPenalties - 250000 normalcase 50.369 ms/op 48.821 ms/op 1.03
altair processRewardsAndPenalties - 250000 worstcase 54.769 ms/op 59.168 ms/op 0.93
phase0 getAttestationDeltas - 250000 normalcase 6.8669 ms/op 6.4317 ms/op 1.07
phase0 getAttestationDeltas - 250000 worstcase 6.8419 ms/op 6.5027 ms/op 1.05
phase0 processSlashings - 250000 worstcase 3.7073 ms/op 3.3905 ms/op 1.09
altair processSyncCommitteeUpdates - 250000 179.81 ms/op 169.48 ms/op 1.06
BeaconState.hashTreeRoot - No change 269.00 ns/op 255.00 ns/op 1.05
BeaconState.hashTreeRoot - 1 full validator 52.934 us/op 50.584 us/op 1.05
BeaconState.hashTreeRoot - 32 full validator 558.11 us/op 503.63 us/op 1.11
BeaconState.hashTreeRoot - 512 full validator 5.1189 ms/op 5.1127 ms/op 1.00
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 66.962 us/op 62.600 us/op 1.07
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 900.95 us/op 912.29 us/op 0.99
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 11.366 ms/op 11.287 ms/op 1.01
BeaconState.hashTreeRoot - 1 balances 48.658 us/op 47.757 us/op 1.02
BeaconState.hashTreeRoot - 32 balances 454.56 us/op 441.85 us/op 1.03
BeaconState.hashTreeRoot - 512 balances 4.4144 ms/op 4.6319 ms/op 0.95
BeaconState.hashTreeRoot - 250000 balances 77.960 ms/op 72.032 ms/op 1.08
aggregationBits - 2048 els - zipIndexesInBitList 17.537 us/op 15.599 us/op 1.12
regular array get 100000 times 43.472 us/op 32.907 us/op 1.32
wrappedArray get 100000 times 33.492 us/op 42.194 us/op 0.79
arrayWithProxy get 100000 times 16.636 ms/op 16.025 ms/op 1.04
ssz.Root.equals 548.00 ns/op 543.00 ns/op 1.01
byteArrayEquals 552.00 ns/op 537.00 ns/op 1.03
shuffle list - 16384 els 7.0899 ms/op 6.5877 ms/op 1.08
shuffle list - 250000 els 101.55 ms/op 96.562 ms/op 1.05
processSlot - 1 slots 8.6160 us/op 8.2260 us/op 1.05
processSlot - 32 slots 1.3431 ms/op 1.2791 ms/op 1.05
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 31.977 ms/op 33.263 ms/op 0.96
getCommitteeAssignments - req 1 vs - 250000 vc 2.9518 ms/op 2.8876 ms/op 1.02
getCommitteeAssignments - req 100 vs - 250000 vc 4.2014 ms/op 4.1146 ms/op 1.02
getCommitteeAssignments - req 1000 vs - 250000 vc 4.5540 ms/op 4.4739 ms/op 1.02
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.6000 ns/op 4.5700 ns/op 1.01
state getBlockRootAtSlot - 250000 vs - 7PWei 597.08 ns/op 774.57 ns/op 0.77
computeProposers - vc 250000 10.905 ms/op 10.093 ms/op 1.08
computeEpochShuffling - vc 250000 104.88 ms/op 96.130 ms/op 1.09
getNextSyncCommittee - vc 250000 182.71 ms/op 171.73 ms/op 1.06
computeSigningRoot for AttestationData 13.623 us/op 13.126 us/op 1.04
hash AttestationData serialized data then Buffer.toString(base64) 2.5455 us/op 2.3226 us/op 1.10
toHexString serialized data 1.1450 us/op 1.0075 us/op 1.14
Buffer.toString(base64) 336.98 ns/op 300.76 ns/op 1.12

by benchmarkbot/action

nflaig
nflaig approved these changes May 29, 2023
View reviewed changes
Copy link
Member

@nflaig nflaig left a comment

Choose a reason for hiding this comment

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

LGTM! I have not seen any duplicate logs when running this branch for a while, it might just be a coincidence, although unlikely as those logs were not that rare.

Command to check for duplicate logs

grep 'slot:' <filename>.log | awk -F'slot: ' '{print $2}' | awk '{print $1}' | sort | uniq -d

@twoeths twoeths merged commit f408a30 into unstable May 30, 2023
@twoeths twoeths deleted the tuyen/deduplicate_notifier_log branch May 30, 2023 01:03
@wemeetagain
Copy link
Member

🎉 This PR is included in v1.9.0 🎉

@nflaig nflaig mentioned this pull request Dec 1, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@g11tech g11tech g11tech approved these changes

@nflaig nflaig nflaig approved these changes

@dapplion dapplion dapplion approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Duplicate sync log for slot
5 participants
@twoeths @wemeetagain @dapplion @nflaig @g11tech