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.

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

fix: eth1 provider error logging #6863

Merged
merged 1 commit into from
Jul 5, 2024
Merged

Conversation

nflaig
Copy link
Member

@nflaig nflaig commented Jun 7, 2024

Motivation

Currently, we will only log the error once if the eth1 provider throws continuous errors with a frequency of < 1min while the intended behavior should be to log at most an error every minute to not be silent about the issue but also not flood the logs with errors.

Description

Update elapsedTimeTracker to not reset timer if there are intermediate calls before time has passed

Part of #6469

@nflaig nflaig requested a review from a team as a code owner June 7, 2024 17:18
Copy link

codecov bot commented Jun 7, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 62.19%. Comparing base (966f3ac) to head (c339c6c).
Report is 2 commits behind head on unstable.

Additional details and impacted files
@@             Coverage Diff              @@
##           unstable    #6863      +/-   ##
============================================
- Coverage     62.20%   62.19%   -0.01%     
============================================
  Files           571      571              
  Lines         60021    60103      +82     
  Branches       1976     1976              
============================================
+ Hits          37334    37380      +46     
- Misses        22644    22680      +36     
  Partials         43       43              

@nflaig nflaig force-pushed the nflaig/eth1-error-logging2 branch from d0f0428 to 2a2aeee Compare June 7, 2024 17:55
Copy link
Contributor

github-actions bot commented Jun 7, 2024

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 857949f Previous: f6d3bce Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 539.43 us/op 437.23 us/op 1.23
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 45.853 us/op 45.598 us/op 1.01
BLS verify - blst-native 1.2221 ms/op 1.2364 ms/op 0.99
BLS verifyMultipleSignatures 3 - blst-native 2.5994 ms/op 2.6262 ms/op 0.99
BLS verifyMultipleSignatures 8 - blst-native 5.7874 ms/op 5.7950 ms/op 1.00
BLS verifyMultipleSignatures 32 - blst-native 21.274 ms/op 21.259 ms/op 1.00
BLS verifyMultipleSignatures 64 - blst-native 41.164 ms/op 41.856 ms/op 0.98
BLS verifyMultipleSignatures 128 - blst-native 82.043 ms/op 83.166 ms/op 0.99
BLS deserializing 10000 signatures 855.46 ms/op 865.99 ms/op 0.99
BLS deserializing 100000 signatures 8.4899 s/op 8.6819 s/op 0.98
BLS verifyMultipleSignatures - same message - 3 - blst-native 1.2024 ms/op 1.2617 ms/op 0.95
BLS verifyMultipleSignatures - same message - 8 - blst-native 1.4650 ms/op 1.4281 ms/op 1.03
BLS verifyMultipleSignatures - same message - 32 - blst-native 2.1890 ms/op 2.3466 ms/op 0.93
BLS verifyMultipleSignatures - same message - 64 - blst-native 3.3590 ms/op 3.3842 ms/op 0.99
BLS verifyMultipleSignatures - same message - 128 - blst-native 5.4579 ms/op 6.3080 ms/op 0.87
BLS aggregatePubkeys 32 - blst-native 24.628 us/op 25.600 us/op 0.96
BLS aggregatePubkeys 128 - blst-native 96.474 us/op 98.296 us/op 0.98
notSeenSlots=1 numMissedVotes=1 numBadVotes=10 58.362 ms/op 52.524 ms/op 1.11
notSeenSlots=1 numMissedVotes=0 numBadVotes=4 44.017 ms/op 49.313 ms/op 0.89
notSeenSlots=2 numMissedVotes=1 numBadVotes=10 29.475 ms/op 30.841 ms/op 0.96
getSlashingsAndExits - default max 91.101 us/op 86.798 us/op 1.05
getSlashingsAndExits - 2k 251.35 us/op 262.42 us/op 0.96
proposeBlockBody type=full, size=empty 5.1212 ms/op 5.3879 ms/op 0.95
isKnown best case - 1 super set check 276.00 ns/op 296.00 ns/op 0.93
isKnown normal case - 2 super set checks 265.00 ns/op 283.00 ns/op 0.94
isKnown worse case - 16 super set checks 268.00 ns/op 288.00 ns/op 0.93
InMemoryCheckpointStateCache - add get delete 4.1590 us/op 4.5270 us/op 0.92
validate api signedAggregateAndProof - struct 2.5274 ms/op 2.6922 ms/op 0.94
validate gossip signedAggregateAndProof - struct 2.5321 ms/op 2.6615 ms/op 0.95
validate gossip attestation - vc 640000 1.2012 ms/op 1.2730 ms/op 0.94
batch validate gossip attestation - vc 640000 - chunk 32 137.96 us/op 148.92 us/op 0.93
batch validate gossip attestation - vc 640000 - chunk 64 122.95 us/op 131.35 us/op 0.94
batch validate gossip attestation - vc 640000 - chunk 128 115.54 us/op 121.28 us/op 0.95
batch validate gossip attestation - vc 640000 - chunk 256 112.41 us/op 117.85 us/op 0.95
pickEth1Vote - no votes 987.45 us/op 1.0410 ms/op 0.95
pickEth1Vote - max votes 7.9423 ms/op 7.5142 ms/op 1.06
pickEth1Vote - Eth1Data hashTreeRoot value x2048 14.614 ms/op 15.522 ms/op 0.94
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 19.383 ms/op 18.609 ms/op 1.04
pickEth1Vote - Eth1Data fastSerialize value x2048 460.72 us/op 507.22 us/op 0.91
pickEth1Vote - Eth1Data fastSerialize tree x2048 5.0743 ms/op 5.4166 ms/op 0.94
bytes32 toHexString 396.00 ns/op 428.00 ns/op 0.93
bytes32 Buffer.toString(hex) 232.00 ns/op 248.00 ns/op 0.94
bytes32 Buffer.toString(hex) from Uint8Array 344.00 ns/op 347.00 ns/op 0.99
bytes32 Buffer.toString(hex) + 0x 235.00 ns/op 247.00 ns/op 0.95
Object access 1 prop 0.12300 ns/op 0.14200 ns/op 0.87
Map access 1 prop 0.12500 ns/op 0.13600 ns/op 0.92
Object get x1000 5.5340 ns/op 5.9290 ns/op 0.93
Map get x1000 6.1950 ns/op 6.7710 ns/op 0.91
Object set x1000 30.238 ns/op 32.003 ns/op 0.94
Map set x1000 21.089 ns/op 21.918 ns/op 0.96
Return object 10000 times 0.27550 ns/op 0.28940 ns/op 0.95
Throw Error 10000 times 3.1725 us/op 3.3436 us/op 0.95
fastMsgIdFn sha256 / 200 bytes 2.0660 us/op 2.1720 us/op 0.95
fastMsgIdFn h32 xxhash / 200 bytes 211.00 ns/op 229.00 ns/op 0.92
fastMsgIdFn h64 xxhash / 200 bytes 265.00 ns/op 270.00 ns/op 0.98
fastMsgIdFn sha256 / 1000 bytes 6.8580 us/op 7.2060 us/op 0.95
fastMsgIdFn h32 xxhash / 1000 bytes 334.00 ns/op 359.00 ns/op 0.93
fastMsgIdFn h64 xxhash / 1000 bytes 334.00 ns/op 346.00 ns/op 0.97
fastMsgIdFn sha256 / 10000 bytes 61.293 us/op 63.989 us/op 0.96
fastMsgIdFn h32 xxhash / 10000 bytes 1.7200 us/op 1.7950 us/op 0.96
fastMsgIdFn h64 xxhash / 10000 bytes 1.1360 us/op 1.1890 us/op 0.96
send data - 1000 256B messages 11.273 ms/op 12.076 ms/op 0.93
send data - 1000 512B messages 15.070 ms/op 16.345 ms/op 0.92
send data - 1000 1024B messages 23.941 ms/op 25.663 ms/op 0.93
send data - 1000 1200B messages 25.407 ms/op 26.256 ms/op 0.97
send data - 1000 2048B messages 31.161 ms/op 31.082 ms/op 1.00
send data - 1000 4096B messages 30.666 ms/op 31.245 ms/op 0.98
send data - 1000 16384B messages 68.544 ms/op 68.924 ms/op 0.99
send data - 1000 65536B messages 201.94 ms/op 209.24 ms/op 0.97
enrSubnets - fastDeserialize 64 bits 1.0610 us/op 1.0990 us/op 0.97
enrSubnets - ssz BitVector 64 bits 339.00 ns/op 356.00 ns/op 0.95
enrSubnets - fastDeserialize 4 bits 147.00 ns/op 149.00 ns/op 0.99
enrSubnets - ssz BitVector 4 bits 342.00 ns/op 356.00 ns/op 0.96
prioritizePeers score -10:0 att 32-0.1 sync 2-0 143.38 us/op 145.26 us/op 0.99
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 152.48 us/op 161.54 us/op 0.94
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 234.76 us/op 263.32 us/op 0.89
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 383.92 us/op 388.34 us/op 0.99
prioritizePeers score 0:0 att 64-1 sync 4-1 589.38 us/op 573.15 us/op 1.03
array of 16000 items push then shift 1.5632 us/op 1.6185 us/op 0.97
LinkedList of 16000 items push then shift 6.8040 ns/op 7.1390 ns/op 0.95
array of 16000 items push then pop 100.45 ns/op 105.99 ns/op 0.95
LinkedList of 16000 items push then pop 6.6680 ns/op 6.9530 ns/op 0.96
array of 24000 items push then shift 2.2903 us/op 2.3856 us/op 0.96
LinkedList of 24000 items push then shift 6.8000 ns/op 7.1220 ns/op 0.95
array of 24000 items push then pop 126.02 ns/op 130.44 ns/op 0.97
LinkedList of 24000 items push then pop 6.6430 ns/op 6.9330 ns/op 0.96
intersect bitArray bitLen 8 6.1030 ns/op 6.4760 ns/op 0.94
intersect array and set length 8 45.729 ns/op 46.424 ns/op 0.99
intersect bitArray bitLen 128 28.398 ns/op 30.410 ns/op 0.93
intersect array and set length 128 752.81 ns/op 674.88 ns/op 1.12
bitArray.getTrueBitIndexes() bitLen 128 1.8130 us/op 1.8290 us/op 0.99
bitArray.getTrueBitIndexes() bitLen 248 3.2070 us/op 3.4320 us/op 0.93
bitArray.getTrueBitIndexes() bitLen 512 5.6650 us/op 6.3250 us/op 0.90
Buffer.concat 32 items 844.00 ns/op 1.0040 us/op 0.84
Uint8Array.set 32 items 1.2150 us/op 1.6220 us/op 0.75
Buffer.copy 1.3830 us/op 1.8650 us/op 0.74
Uint8Array.set - with subarray 2.2490 us/op 2.5360 us/op 0.89
Uint8Array.set - without subarray 1.4640 us/op 1.5370 us/op 0.95
Set add up to 64 items then delete first 2.0890 us/op 2.2738 us/op 0.92
OrderedSet add up to 64 items then delete first 3.1635 us/op 3.2732 us/op 0.97
Set add up to 64 items then delete last 2.3756 us/op 2.4468 us/op 0.97
OrderedSet add up to 64 items then delete last 3.5254 us/op 3.7159 us/op 0.95
Set add up to 64 items then delete middle 2.4522 us/op 2.6005 us/op 0.94
OrderedSet add up to 64 items then delete middle 5.0272 us/op 5.2622 us/op 0.96
Set add up to 128 items then delete first 4.9234 us/op 5.3942 us/op 0.91
OrderedSet add up to 128 items then delete first 7.7026 us/op 8.4613 us/op 0.91
Set add up to 128 items then delete last 4.7876 us/op 5.1035 us/op 0.94
OrderedSet add up to 128 items then delete last 7.0702 us/op 7.4257 us/op 0.95
Set add up to 128 items then delete middle 4.8377 us/op 4.8495 us/op 1.00
OrderedSet add up to 128 items then delete middle 13.394 us/op 13.555 us/op 0.99
Set add up to 256 items then delete first 10.031 us/op 10.311 us/op 0.97
OrderedSet add up to 256 items then delete first 15.794 us/op 16.243 us/op 0.97
Set add up to 256 items then delete last 9.3665 us/op 9.9024 us/op 0.95
OrderedSet add up to 256 items then delete last 14.122 us/op 15.398 us/op 0.92
Set add up to 256 items then delete middle 9.3523 us/op 9.4761 us/op 0.99
OrderedSet add up to 256 items then delete middle 39.871 us/op 40.874 us/op 0.98
transfer serialized Status (84 B) 1.3330 us/op 1.3200 us/op 1.01
copy serialized Status (84 B) 1.0730 us/op 1.0670 us/op 1.01
transfer serialized SignedVoluntaryExit (112 B) 1.4340 us/op 1.4100 us/op 1.02
copy serialized SignedVoluntaryExit (112 B) 1.1170 us/op 1.1360 us/op 0.98
transfer serialized ProposerSlashing (416 B) 1.9900 us/op 1.8180 us/op 1.09
copy serialized ProposerSlashing (416 B) 1.6180 us/op 1.7270 us/op 0.94
transfer serialized Attestation (485 B) 2.1630 us/op 2.0400 us/op 1.06
copy serialized Attestation (485 B) 1.6440 us/op 1.5100 us/op 1.09
transfer serialized AttesterSlashing (33232 B) 2.3750 us/op 2.0600 us/op 1.15
copy serialized AttesterSlashing (33232 B) 4.9320 us/op 4.7460 us/op 1.04
transfer serialized Small SignedBeaconBlock (128000 B) 2.8990 us/op 2.3990 us/op 1.21
copy serialized Small SignedBeaconBlock (128000 B) 14.577 us/op 14.611 us/op 1.00
transfer serialized Avg SignedBeaconBlock (200000 B) 3.4760 us/op 2.5990 us/op 1.34
copy serialized Avg SignedBeaconBlock (200000 B) 20.811 us/op 19.612 us/op 1.06
transfer serialized BlobsSidecar (524380 B) 2.9980 us/op 2.7050 us/op 1.11
copy serialized BlobsSidecar (524380 B) 76.048 us/op 195.29 us/op 0.39
transfer serialized Big SignedBeaconBlock (1000000 B) 3.2390 us/op 2.5690 us/op 1.26
copy serialized Big SignedBeaconBlock (1000000 B) 206.98 us/op 133.33 us/op 1.55
pass gossip attestations to forkchoice per slot 3.0604 ms/op 3.0969 ms/op 0.99
forkChoice updateHead vc 100000 bc 64 eq 0 589.64 us/op 503.51 us/op 1.17
forkChoice updateHead vc 600000 bc 64 eq 0 2.9561 ms/op 3.0522 ms/op 0.97
forkChoice updateHead vc 1000000 bc 64 eq 0 5.2590 ms/op 5.1607 ms/op 1.02
forkChoice updateHead vc 600000 bc 320 eq 0 3.0532 ms/op 3.0994 ms/op 0.99
forkChoice updateHead vc 600000 bc 1200 eq 0 3.2348 ms/op 3.1527 ms/op 1.03
forkChoice updateHead vc 600000 bc 7200 eq 0 3.6587 ms/op 3.5698 ms/op 1.02
forkChoice updateHead vc 600000 bc 64 eq 1000 10.746 ms/op 11.294 ms/op 0.95
forkChoice updateHead vc 600000 bc 64 eq 10000 10.461 ms/op 11.405 ms/op 0.92
forkChoice updateHead vc 600000 bc 64 eq 300000 14.450 ms/op 14.888 ms/op 0.97
computeDeltas 500000 validators 300 proto nodes 3.4197 ms/op 3.4913 ms/op 0.98
computeDeltas 500000 validators 1200 proto nodes 3.4095 ms/op 3.5217 ms/op 0.97
computeDeltas 500000 validators 7200 proto nodes 3.4258 ms/op 3.4650 ms/op 0.99
computeDeltas 750000 validators 300 proto nodes 5.0431 ms/op 5.1907 ms/op 0.97
computeDeltas 750000 validators 1200 proto nodes 5.0921 ms/op 5.0985 ms/op 1.00
computeDeltas 750000 validators 7200 proto nodes 5.0612 ms/op 5.1138 ms/op 0.99
computeDeltas 1400000 validators 300 proto nodes 9.4098 ms/op 9.6697 ms/op 0.97
computeDeltas 1400000 validators 1200 proto nodes 9.3521 ms/op 9.5734 ms/op 0.98
computeDeltas 1400000 validators 7200 proto nodes 9.4638 ms/op 9.5305 ms/op 0.99
computeDeltas 2100000 validators 300 proto nodes 14.068 ms/op 14.375 ms/op 0.98
computeDeltas 2100000 validators 1200 proto nodes 14.145 ms/op 14.643 ms/op 0.97
computeDeltas 2100000 validators 7200 proto nodes 14.034 ms/op 14.482 ms/op 0.97
altair processAttestation - 250000 vs - 7PWei normalcase 1.5396 ms/op 1.6363 ms/op 0.94
altair processAttestation - 250000 vs - 7PWei worstcase 2.3574 ms/op 2.4593 ms/op 0.96
altair processAttestation - setStatus - 1/6 committees join 86.418 us/op 84.204 us/op 1.03
altair processAttestation - setStatus - 1/3 committees join 167.57 us/op 169.63 us/op 0.99
altair processAttestation - setStatus - 1/2 committees join 237.77 us/op 240.32 us/op 0.99
altair processAttestation - setStatus - 2/3 committees join 310.48 us/op 317.10 us/op 0.98
altair processAttestation - setStatus - 4/5 committees join 451.27 us/op 459.19 us/op 0.98
altair processAttestation - setStatus - 100% committees join 537.56 us/op 551.53 us/op 0.97
altair processBlock - 250000 vs - 7PWei normalcase 3.4385 ms/op 3.3260 ms/op 1.03
altair processBlock - 250000 vs - 7PWei normalcase hashState 28.345 ms/op 25.603 ms/op 1.11
altair processBlock - 250000 vs - 7PWei worstcase 41.016 ms/op 38.902 ms/op 1.05
altair processBlock - 250000 vs - 7PWei worstcase hashState 74.866 ms/op 77.824 ms/op 0.96
phase0 processBlock - 250000 vs - 7PWei normalcase 1.6705 ms/op 1.7408 ms/op 0.96
phase0 processBlock - 250000 vs - 7PWei worstcase 25.815 ms/op 26.447 ms/op 0.98
altair processEth1Data - 250000 vs - 7PWei normalcase 290.73 us/op 285.63 us/op 1.02
getExpectedWithdrawals 250000 eb:1,eth1:1,we:0,wn:0,smpl:15 4.6210 us/op 5.1000 us/op 0.91
getExpectedWithdrawals 250000 eb:0.95,eth1:0.1,we:0.05,wn:0,smpl:219 21.306 us/op 17.372 us/op 1.23
getExpectedWithdrawals 250000 eb:0.95,eth1:0.3,we:0.05,wn:0,smpl:42 8.6580 us/op 7.3090 us/op 1.18
getExpectedWithdrawals 250000 eb:0.95,eth1:0.7,we:0.05,wn:0,smpl:18 5.1490 us/op 5.2740 us/op 0.98
getExpectedWithdrawals 250000 eb:0.1,eth1:0.1,we:0,wn:0,smpl:1020 79.287 us/op 71.142 us/op 1.11
getExpectedWithdrawals 250000 eb:0.03,eth1:0.03,we:0,wn:0,smpl:11777 648.99 us/op 659.50 us/op 0.98
getExpectedWithdrawals 250000 eb:0.01,eth1:0.01,we:0,wn:0,smpl:16384 883.26 us/op 919.78 us/op 0.96
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,smpl:16384 883.24 us/op 882.51 us/op 1.00
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,nocache,smpl:16384 2.1322 ms/op 2.0678 ms/op 1.03
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,smpl:16384 1.6165 ms/op 1.5872 ms/op 1.02
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,nocache,smpl:16384 3.5696 ms/op 3.4745 ms/op 1.03
Tree 40 250000 create 226.62 ms/op 226.08 ms/op 1.00
Tree 40 250000 get(125000) 139.15 ns/op 142.21 ns/op 0.98
Tree 40 250000 set(125000) 612.24 ns/op 626.82 ns/op 0.98
Tree 40 250000 toArray() 14.614 ms/op 14.612 ms/op 1.00
Tree 40 250000 iterate all - toArray() + loop 14.638 ms/op 14.818 ms/op 0.99
Tree 40 250000 iterate all - get(i) 48.461 ms/op 50.057 ms/op 0.97
MutableVector 250000 create 7.8949 ms/op 8.8068 ms/op 0.90
MutableVector 250000 get(125000) 7.0000 ns/op 6.1020 ns/op 1.15
MutableVector 250000 set(125000) 180.27 ns/op 200.48 ns/op 0.90
MutableVector 250000 toArray() 3.3986 ms/op 3.5648 ms/op 0.95
MutableVector 250000 iterate all - toArray() + loop 3.5254 ms/op 3.7118 ms/op 0.95
MutableVector 250000 iterate all - get(i) 1.6658 ms/op 1.6437 ms/op 1.01
Array 250000 create 2.9331 ms/op 3.0178 ms/op 0.97
Array 250000 clone - spread 1.3370 ms/op 1.5576 ms/op 0.86
Array 250000 get(125000) 0.40100 ns/op 0.41100 ns/op 0.98
Array 250000 set(125000) 0.42500 ns/op 0.42900 ns/op 0.99
Array 250000 iterate all - loop 96.996 us/op 107.26 us/op 0.90
effectiveBalanceIncrements clone Uint8Array 300000 25.468 us/op 29.851 us/op 0.85
effectiveBalanceIncrements clone MutableVector 300000 120.00 ns/op 127.00 ns/op 0.94
effectiveBalanceIncrements rw all Uint8Array 300000 195.97 us/op 198.73 us/op 0.99
effectiveBalanceIncrements rw all MutableVector 300000 59.734 ms/op 68.041 ms/op 0.88
phase0 afterProcessEpoch - 250000 vs - 7PWei 87.065 ms/op 83.048 ms/op 1.05
phase0 beforeProcessEpoch - 250000 vs - 7PWei 39.029 ms/op 31.003 ms/op 1.26
altair processEpoch - mainnet_e81889 369.49 ms/op 366.70 ms/op 1.01
mainnet_e81889 - altair beforeProcessEpoch 63.795 ms/op 63.927 ms/op 1.00
mainnet_e81889 - altair processJustificationAndFinalization 12.125 us/op 12.420 us/op 0.98
mainnet_e81889 - altair processInactivityUpdates 5.3080 ms/op 5.3669 ms/op 0.99
mainnet_e81889 - altair processRewardsAndPenalties 44.175 ms/op 43.752 ms/op 1.01
mainnet_e81889 - altair processRegistryUpdates 1.8680 us/op 1.9120 us/op 0.98
mainnet_e81889 - altair processSlashings 419.00 ns/op 357.00 ns/op 1.17
mainnet_e81889 - altair processEth1DataReset 337.00 ns/op 323.00 ns/op 1.04
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.0771 ms/op 1.0533 ms/op 1.02
mainnet_e81889 - altair processSlashingsReset 4.9450 us/op 3.9660 us/op 1.25
mainnet_e81889 - altair processRandaoMixesReset 4.5100 us/op 4.0530 us/op 1.11
mainnet_e81889 - altair processHistoricalRootsUpdate 482.00 ns/op 500.00 ns/op 0.96
mainnet_e81889 - altair processParticipationFlagUpdates 2.4500 us/op 1.7700 us/op 1.38
mainnet_e81889 - altair processSyncCommitteeUpdates 441.00 ns/op 385.00 ns/op 1.15
mainnet_e81889 - altair afterProcessEpoch 91.439 ms/op 91.269 ms/op 1.00
capella processEpoch - mainnet_e217614 1.2346 s/op 1.2545 s/op 0.98
mainnet_e217614 - capella beforeProcessEpoch 237.39 ms/op 236.64 ms/op 1.00
mainnet_e217614 - capella processJustificationAndFinalization 13.605 us/op 13.504 us/op 1.01
mainnet_e217614 - capella processInactivityUpdates 15.569 ms/op 15.848 ms/op 0.98
mainnet_e217614 - capella processRewardsAndPenalties 228.34 ms/op 237.27 ms/op 0.96
mainnet_e217614 - capella processRegistryUpdates 12.004 us/op 12.729 us/op 0.94
mainnet_e217614 - capella processSlashings 444.00 ns/op 336.00 ns/op 1.32
mainnet_e217614 - capella processEth1DataReset 280.00 ns/op 352.00 ns/op 0.80
mainnet_e217614 - capella processEffectiveBalanceUpdates 9.9675 ms/op 4.8556 ms/op 2.05
mainnet_e217614 - capella processSlashingsReset 3.2930 us/op 2.8540 us/op 1.15
mainnet_e217614 - capella processRandaoMixesReset 7.0280 us/op 4.3130 us/op 1.63
mainnet_e217614 - capella processHistoricalRootsUpdate 466.00 ns/op 374.00 ns/op 1.25
mainnet_e217614 - capella processParticipationFlagUpdates 1.7990 us/op 2.7090 us/op 0.66
mainnet_e217614 - capella afterProcessEpoch 233.27 ms/op 227.19 ms/op 1.03
phase0 processEpoch - mainnet_e58758 361.19 ms/op 363.08 ms/op 0.99
mainnet_e58758 - phase0 beforeProcessEpoch 105.17 ms/op 110.05 ms/op 0.96
mainnet_e58758 - phase0 processJustificationAndFinalization 12.604 us/op 13.711 us/op 0.92
mainnet_e58758 - phase0 processRewardsAndPenalties 22.199 ms/op 30.215 ms/op 0.73
mainnet_e58758 - phase0 processRegistryUpdates 7.2930 us/op 7.5050 us/op 0.97
mainnet_e58758 - phase0 processSlashings 439.00 ns/op 292.00 ns/op 1.50
mainnet_e58758 - phase0 processEth1DataReset 298.00 ns/op 295.00 ns/op 1.01
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 939.70 us/op 936.03 us/op 1.00
mainnet_e58758 - phase0 processSlashingsReset 3.2910 us/op 2.8560 us/op 1.15
mainnet_e58758 - phase0 processRandaoMixesReset 3.7710 us/op 3.3800 us/op 1.12
mainnet_e58758 - phase0 processHistoricalRootsUpdate 348.00 ns/op 339.00 ns/op 1.03
mainnet_e58758 - phase0 processParticipationRecordUpdates 2.5690 us/op 2.5390 us/op 1.01
mainnet_e58758 - phase0 afterProcessEpoch 75.402 ms/op 76.070 ms/op 0.99
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.1973 ms/op 1.5165 ms/op 0.79
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.8249 ms/op 2.0190 ms/op 0.90
altair processInactivityUpdates - 250000 normalcase 16.002 ms/op 16.041 ms/op 1.00
altair processInactivityUpdates - 250000 worstcase 14.734 ms/op 16.713 ms/op 0.88
phase0 processRegistryUpdates - 250000 normalcase 5.9260 us/op 5.7490 us/op 1.03
phase0 processRegistryUpdates - 250000 badcase_full_deposits 218.08 us/op 228.62 us/op 0.95
phase0 processRegistryUpdates - 250000 worstcase 0.5 115.39 ms/op 100.61 ms/op 1.15
altair processRewardsAndPenalties - 250000 normalcase 37.368 ms/op 39.287 ms/op 0.95
altair processRewardsAndPenalties - 250000 worstcase 36.754 ms/op 35.754 ms/op 1.03
phase0 getAttestationDeltas - 250000 normalcase 6.7223 ms/op 7.1623 ms/op 0.94
phase0 getAttestationDeltas - 250000 worstcase 6.9728 ms/op 6.8960 ms/op 1.01
phase0 processSlashings - 250000 worstcase 73.454 us/op 77.847 us/op 0.94
altair processSyncCommitteeUpdates - 250000 130.95 ms/op 121.35 ms/op 1.08
BeaconState.hashTreeRoot - No change 258.00 ns/op 278.00 ns/op 0.93
BeaconState.hashTreeRoot - 1 full validator 121.78 us/op 126.72 us/op 0.96
BeaconState.hashTreeRoot - 32 full validator 1.3146 ms/op 1.3585 ms/op 0.97
BeaconState.hashTreeRoot - 512 full validator 12.023 ms/op 14.307 ms/op 0.84
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 126.15 us/op 121.69 us/op 1.04
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 1.7257 ms/op 1.6098 ms/op 1.07
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 24.231 ms/op 22.730 ms/op 1.07
BeaconState.hashTreeRoot - 1 balances 109.39 us/op 112.80 us/op 0.97
BeaconState.hashTreeRoot - 32 balances 934.04 us/op 1.1711 ms/op 0.80
BeaconState.hashTreeRoot - 512 balances 9.0960 ms/op 10.947 ms/op 0.83
BeaconState.hashTreeRoot - 250000 balances 179.43 ms/op 181.47 ms/op 0.99
aggregationBits - 2048 els - zipIndexesInBitList 22.105 us/op 22.387 us/op 0.99
byteArrayEquals 32 51.508 ns/op 51.585 ns/op 1.00
Buffer.compare 32 45.622 ns/op 43.624 ns/op 1.05
byteArrayEquals 1024 1.5199 us/op 1.5263 us/op 1.00
Buffer.compare 1024 50.789 ns/op 50.653 ns/op 1.00
byteArrayEquals 16384 24.201 us/op 24.305 us/op 1.00
Buffer.compare 16384 239.37 ns/op 237.79 ns/op 1.01
byteArrayEquals 123687377 181.84 ms/op 183.50 ms/op 0.99
Buffer.compare 123687377 6.0155 ms/op 6.0234 ms/op 1.00
byteArrayEquals 32 - diff last byte 50.423 ns/op 50.493 ns/op 1.00
Buffer.compare 32 - diff last byte 44.411 ns/op 47.045 ns/op 0.94
byteArrayEquals 1024 - diff last byte 1.5182 us/op 1.5264 us/op 0.99
Buffer.compare 1024 - diff last byte 54.261 ns/op 52.418 ns/op 1.04
byteArrayEquals 16384 - diff last byte 24.147 us/op 24.291 us/op 0.99
Buffer.compare 16384 - diff last byte 234.37 ns/op 232.56 ns/op 1.01
byteArrayEquals 123687377 - diff last byte 181.80 ms/op 188.41 ms/op 0.96
Buffer.compare 123687377 - diff last byte 6.0415 ms/op 6.0995 ms/op 0.99
byteArrayEquals 32 - random bytes 4.9190 ns/op 5.1090 ns/op 0.96
Buffer.compare 32 - random bytes 46.364 ns/op 47.362 ns/op 0.98
byteArrayEquals 1024 - random bytes 4.9230 ns/op 5.0890 ns/op 0.97
Buffer.compare 1024 - random bytes 44.045 ns/op 45.510 ns/op 0.97
byteArrayEquals 16384 - random bytes 5.0680 ns/op 5.0910 ns/op 1.00
Buffer.compare 16384 - random bytes 44.307 ns/op 45.615 ns/op 0.97
byteArrayEquals 123687377 - random bytes 6.1100 ns/op 6.4800 ns/op 0.94
Buffer.compare 123687377 - random bytes 45.460 ns/op 47.040 ns/op 0.97
regular array get 100000 times 32.014 us/op 43.336 us/op 0.74
wrappedArray get 100000 times 31.260 us/op 32.542 us/op 0.96
arrayWithProxy get 100000 times 12.195 ms/op 13.244 ms/op 0.92
ssz.Root.equals 44.169 ns/op 45.598 ns/op 0.97
byteArrayEquals 43.346 ns/op 45.036 ns/op 0.96
Buffer.compare 9.9280 ns/op 10.231 ns/op 0.97
shuffle list - 16384 els 6.2356 ms/op 6.2584 ms/op 1.00
shuffle list - 250000 els 90.710 ms/op 91.626 ms/op 0.99
processSlot - 1 slots 13.864 us/op 12.946 us/op 1.07
processSlot - 32 slots 2.7177 ms/op 3.1327 ms/op 0.87
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 37.299 ms/op 37.518 ms/op 0.99
getCommitteeAssignments - req 1 vs - 250000 vc 2.1347 ms/op 2.1545 ms/op 0.99
getCommitteeAssignments - req 100 vs - 250000 vc 4.0990 ms/op 4.1512 ms/op 0.99
getCommitteeAssignments - req 1000 vs - 250000 vc 4.3421 ms/op 4.4712 ms/op 0.97
findModifiedValidators - 10000 modified validators 238.25 ms/op 239.38 ms/op 1.00
findModifiedValidators - 1000 modified validators 160.27 ms/op 175.03 ms/op 0.92
findModifiedValidators - 100 modified validators 170.96 ms/op 160.00 ms/op 1.07
findModifiedValidators - 10 modified validators 154.30 ms/op 157.60 ms/op 0.98
findModifiedValidators - 1 modified validators 153.11 ms/op 149.14 ms/op 1.03
findModifiedValidators - no difference 148.87 ms/op 154.94 ms/op 0.96
compare ViewDUs 2.9492 s/op 2.9386 s/op 1.00
compare each validator Uint8Array 1.3070 s/op 1.5263 s/op 0.86
compare ViewDU to Uint8Array 1.0509 s/op 1.0231 s/op 1.03
migrate state 1000000 validators, 24 modified, 0 new 585.37 ms/op 586.24 ms/op 1.00
migrate state 1000000 validators, 1700 modified, 1000 new 788.30 ms/op 825.28 ms/op 0.96
migrate state 1000000 validators, 3400 modified, 2000 new 1.0020 s/op 1.0262 s/op 0.98
migrate state 1500000 validators, 24 modified, 0 new 569.87 ms/op 590.49 ms/op 0.97
migrate state 1500000 validators, 1700 modified, 1000 new 806.17 ms/op 838.99 ms/op 0.96
migrate state 1500000 validators, 3400 modified, 2000 new 1.0134 s/op 1.0279 s/op 0.99
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.1100 ns/op 4.4100 ns/op 0.93
state getBlockRootAtSlot - 250000 vs - 7PWei 679.06 ns/op 700.08 ns/op 0.97
computeProposers - vc 250000 7.2191 ms/op 7.5503 ms/op 0.96
computeEpochShuffling - vc 250000 90.801 ms/op 90.922 ms/op 1.00
getNextSyncCommittee - vc 250000 118.60 ms/op 128.01 ms/op 0.93
computeSigningRoot for AttestationData 21.263 us/op 22.777 us/op 0.93
hash AttestationData serialized data then Buffer.toString(base64) 1.4286 us/op 1.4687 us/op 0.97
toHexString serialized data 835.04 ns/op 860.22 ns/op 0.97
Buffer.toString(base64) 163.56 ns/op 169.29 ns/op 0.97

by benchmarkbot/action

@nflaig nflaig force-pushed the nflaig/eth1-error-logging2 branch from 2a2aeee to 09819d8 Compare June 8, 2024 14:10
@nflaig nflaig force-pushed the nflaig/eth1-error-logging2 branch from 09819d8 to c339c6c Compare June 8, 2024 14:41

return msSinceLastCall > minElapsedTime;
if (msSinceLastCall > minElapsedTime) {
Copy link
Contributor

Choose a reason for hiding this comment

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

I am not in favor of this change in createElapsedTimeTracker as it's just to track the total elapsed time without any frequency.

If there is no other usage then we can rename this to createTimeFrequencyTracker or similar to make it clear.

Or I would better suggest to use the rateLimiter here. We have few implementation that we can move to utils and reuse here.

Copy link
Member Author

@nflaig nflaig Jun 10, 2024

Choose a reason for hiding this comment

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

It's really unintuitive based on current usage of createElapsedTimeTracker that is would reset that timer if there are intermediate calls.

In the test cases, the function is even called callIfTimePassed which suggests call code if time passed, e.g. like this

if (callIfTimePassed()) {
  // run this code after time passed
}

The usage in eth1Provider is the same, the name of the function is isOneMinutePassed which suggest log the error if one minute is passed, irrespective of how many times it called isOneMinutePassed in-between.

My suggestion is to either fix createElapsedTimeTracker, or to remove it altogether has the only use case right now is in eth1Provider.ts and it does not what it is supposed to do there.

Copy link
Member

@wemeetagain wemeetagain left a comment

Choose a reason for hiding this comment

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

This is an improvement wrt the logging behavior.

no opinion on the naming

@nflaig nflaig requested a review from nazarhussain June 27, 2024 08:42
@nflaig nflaig mentioned this pull request Jun 28, 2024
2 tasks
@wemeetagain wemeetagain merged commit 29d1c22 into unstable Jul 5, 2024
20 checks passed
@wemeetagain wemeetagain deleted the nflaig/eth1-error-logging2 branch July 5, 2024 14:16
@wemeetagain
Copy link
Member

🎉 This PR is included in v1.20.0 🎉

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants