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

feat(logger): remove unused trace log level #5861

Merged
merged 6 commits into from
Oct 2, 2023

Conversation

matthewkeil
Copy link
Member

@matthewkeil matthewkeil commented Aug 8, 2023

Motivation

trace does not follow our logging policy and it is broken as well. Found an error and instead of fixing we decided to remove it.

Closes #5809

Description

  • Ensured no usage of the log.trace()
  • Update Logger interface to remove trace method
  • Kept LogLevel.trace so that it can be passed into the CLI without throwing an error but will be handled similar to debug logging level
  • Remove trace method from WinstonLogger, getLoggerVc and getEmptyLogger

@matthewkeil matthewkeil requested a review from a team as a code owner August 8, 2023 07:55
@nflaig
Copy link
Member

nflaig commented Aug 8, 2023

What happens if you pass trace as log level now from the CLI? See requirement mentioned in #4536.

@github-actions
Copy link
Contributor

github-actions bot commented Aug 8, 2023

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 52c8cd2 Previous: 9cd65cc Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 359.01 us/op 495.22 us/op 0.72
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 55.277 us/op 78.816 us/op 0.70
BLS verify - blst-native 1.1594 ms/op 1.3569 ms/op 0.85
BLS verifyMultipleSignatures 3 - blst-native 2.4443 ms/op 2.8361 ms/op 0.86
BLS verifyMultipleSignatures 8 - blst-native 5.4207 ms/op 6.2244 ms/op 0.87
BLS verifyMultipleSignatures 32 - blst-native 19.884 ms/op 22.677 ms/op 0.88
BLS verifyMultipleSignatures 64 - blst-native 40.333 ms/op 44.893 ms/op 0.90
BLS verifyMultipleSignatures 128 - blst-native 78.627 ms/op 89.447 ms/op 0.88
BLS deserializing 10000 signatures 832.90 ms/op 919.65 ms/op 0.91
BLS deserializing 100000 signatures 8.2610 s/op 9.2274 s/op 0.90
BLS verifyMultipleSignatures - same message - 3 - blst-native 1.1734 ms/op 1.3928 ms/op 0.84
BLS verifyMultipleSignatures - same message - 8 - blst-native 1.2886 ms/op 1.5662 ms/op 0.82
BLS verifyMultipleSignatures - same message - 32 - blst-native 2.2557 ms/op 2.5912 ms/op 0.87
BLS verifyMultipleSignatures - same message - 64 - blst-native 3.2941 ms/op 3.9789 ms/op 0.83
BLS verifyMultipleSignatures - same message - 128 - blst-native 4.9544 ms/op 5.7253 ms/op 0.87
BLS aggregatePubkeys 32 - blst-native 22.632 us/op 26.151 us/op 0.87
BLS aggregatePubkeys 128 - blst-native 87.944 us/op 102.68 us/op 0.86
getAttestationsForBlock 32.820 ms/op 39.841 ms/op 0.82
isKnown best case - 1 super set check 327.00 ns/op 297.00 ns/op 1.10
isKnown normal case - 2 super set checks 329.00 ns/op 286.00 ns/op 1.15
isKnown worse case - 16 super set checks 318.00 ns/op 282.00 ns/op 1.13
CheckpointStateCache - add get delete 4.1310 us/op 5.2000 us/op 0.79
validate api signedAggregateAndProof - struct 2.4629 ms/op 2.8743 ms/op 0.86
validate gossip signedAggregateAndProof - struct 2.4096 ms/op 2.8781 ms/op 0.84
validate gossip attestation - vc 640000 1.1666 ms/op 1.4212 ms/op 0.82
batch validate gossip attestation - vc 640000 - chunk 32 144.36 us/op 175.30 us/op 0.82
batch validate gossip attestation - vc 640000 - chunk 64 128.39 us/op 153.49 us/op 0.84
batch validate gossip attestation - vc 640000 - chunk 128 122.79 us/op 142.82 us/op 0.86
batch validate gossip attestation - vc 640000 - chunk 256 112.57 us/op 136.63 us/op 0.82
pickEth1Vote - no votes 876.35 us/op 1.3638 ms/op 0.64
pickEth1Vote - max votes 7.9007 ms/op 12.618 ms/op 0.63
pickEth1Vote - Eth1Data hashTreeRoot value x2048 18.002 ms/op 19.099 ms/op 0.94
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 23.741 ms/op 27.088 ms/op 0.88
pickEth1Vote - Eth1Data fastSerialize value x2048 403.96 us/op 677.79 us/op 0.60
pickEth1Vote - Eth1Data fastSerialize tree x2048 7.1502 ms/op 6.9498 ms/op 1.03
bytes32 toHexString 418.00 ns/op 511.00 ns/op 0.82
bytes32 Buffer.toString(hex) 307.00 ns/op 333.00 ns/op 0.92
bytes32 Buffer.toString(hex) from Uint8Array 421.00 ns/op 485.00 ns/op 0.87
bytes32 Buffer.toString(hex) + 0x 299.00 ns/op 323.00 ns/op 0.93
Object access 1 prop 0.18300 ns/op 0.16900 ns/op 1.08
Map access 1 prop 0.18100 ns/op 0.16800 ns/op 1.08
Object get x1000 5.2830 ns/op 8.1530 ns/op 0.65
Map get x1000 0.50900 ns/op 0.55600 ns/op 0.92
Object set x1000 26.227 ns/op 51.859 ns/op 0.51
Map set x1000 16.388 ns/op 41.517 ns/op 0.39
Return object 10000 times 0.22280 ns/op 0.26020 ns/op 0.86
Throw Error 10000 times 2.7625 us/op 4.2821 us/op 0.65
fastMsgIdFn sha256 / 200 bytes 2.0070 us/op 3.6120 us/op 0.56
fastMsgIdFn h32 xxhash / 200 bytes 298.00 ns/op 315.00 ns/op 0.95
fastMsgIdFn h64 xxhash / 200 bytes 347.00 ns/op 376.00 ns/op 0.92
fastMsgIdFn sha256 / 1000 bytes 6.1720 us/op 12.060 us/op 0.51
fastMsgIdFn h32 xxhash / 1000 bytes 399.00 ns/op 457.00 ns/op 0.87
fastMsgIdFn h64 xxhash / 1000 bytes 416.00 ns/op 467.00 ns/op 0.89
fastMsgIdFn sha256 / 10000 bytes 53.194 us/op 111.00 us/op 0.48
fastMsgIdFn h32 xxhash / 10000 bytes 1.8340 us/op 2.0800 us/op 0.88
fastMsgIdFn h64 xxhash / 10000 bytes 1.2700 us/op 1.4770 us/op 0.86
send data - 1000 256B messages 10.833 ms/op 20.903 ms/op 0.52
send data - 1000 512B messages 14.262 ms/op 29.622 ms/op 0.48
send data - 1000 1024B messages 20.943 ms/op 45.581 ms/op 0.46
send data - 1000 1200B messages 18.311 ms/op 30.346 ms/op 0.60
send data - 1000 2048B messages 22.146 ms/op 28.092 ms/op 0.79
send data - 1000 4096B messages 25.825 ms/op 34.586 ms/op 0.75
send data - 1000 16384B messages 53.769 ms/op 82.592 ms/op 0.65
send data - 1000 65536B messages 246.81 ms/op 285.82 ms/op 0.86
enrSubnets - fastDeserialize 64 bits 1.0690 us/op 1.4310 us/op 0.75
enrSubnets - ssz BitVector 64 bits 486.00 ns/op 535.00 ns/op 0.91
enrSubnets - fastDeserialize 4 bits 221.00 ns/op 215.00 ns/op 1.03
enrSubnets - ssz BitVector 4 bits 464.00 ns/op 514.00 ns/op 0.90
prioritizePeers score -10:0 att 32-0.1 sync 2-0 75.787 us/op 112.83 us/op 0.67
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 82.558 us/op 156.00 us/op 0.53
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 102.69 us/op 192.24 us/op 0.53
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 171.92 us/op 320.90 us/op 0.54
prioritizePeers score 0:0 att 64-1 sync 4-1 216.15 us/op 361.81 us/op 0.60
array of 16000 items push then shift 1.2349 us/op 1.7834 us/op 0.69
LinkedList of 16000 items push then shift 7.1290 ns/op 9.4590 ns/op 0.75
array of 16000 items push then pop 86.981 ns/op 98.528 ns/op 0.88
LinkedList of 16000 items push then pop 5.8740 ns/op 9.4310 ns/op 0.62
array of 24000 items push then shift 1.8902 us/op 2.5729 us/op 0.73
LinkedList of 24000 items push then shift 5.8200 ns/op 9.5280 ns/op 0.61
array of 24000 items push then pop 85.063 ns/op 134.60 ns/op 0.63
LinkedList of 24000 items push then pop 6.3920 ns/op 9.5450 ns/op 0.67
intersect bitArray bitLen 8 5.3300 ns/op 7.4420 ns/op 0.72
intersect array and set length 8 41.031 ns/op 58.213 ns/op 0.70
intersect bitArray bitLen 128 24.866 ns/op 34.740 ns/op 0.72
intersect array and set length 128 577.17 ns/op 811.38 ns/op 0.71
bitArray.getTrueBitIndexes() bitLen 128 1.4680 us/op 1.6290 us/op 0.90
bitArray.getTrueBitIndexes() bitLen 248 2.3240 us/op 2.7280 us/op 0.85
bitArray.getTrueBitIndexes() bitLen 512 4.5510 us/op 5.2270 us/op 0.87
Buffer.concat 32 items 869.00 ns/op 977.00 ns/op 0.89
Uint8Array.set 32 items 2.0620 us/op 1.7490 us/op 1.18
Set add up to 64 items then delete first 1.6722 us/op 4.7179 us/op 0.35
OrderedSet add up to 64 items then delete first 2.5371 us/op 5.8719 us/op 0.43
Set add up to 64 items then delete last 1.9322 us/op 4.9654 us/op 0.39
OrderedSet add up to 64 items then delete last 2.8960 us/op 5.9686 us/op 0.49
Set add up to 64 items then delete middle 1.9251 us/op 4.8185 us/op 0.40
OrderedSet add up to 64 items then delete middle 4.0588 us/op 7.4027 us/op 0.55
Set add up to 128 items then delete first 3.7728 us/op 10.332 us/op 0.37
OrderedSet add up to 128 items then delete first 5.8532 us/op 13.451 us/op 0.44
Set add up to 128 items then delete last 3.5075 us/op 9.9037 us/op 0.35
OrderedSet add up to 128 items then delete last 5.4107 us/op 13.035 us/op 0.42
Set add up to 128 items then delete middle 3.5533 us/op 10.280 us/op 0.35
OrderedSet add up to 128 items then delete middle 10.548 us/op 19.191 us/op 0.55
Set add up to 256 items then delete first 7.7178 us/op 21.508 us/op 0.36
OrderedSet add up to 256 items then delete first 12.276 us/op 28.632 us/op 0.43
Set add up to 256 items then delete last 7.6749 us/op 20.648 us/op 0.37
OrderedSet add up to 256 items then delete last 11.313 us/op 26.657 us/op 0.42
Set add up to 256 items then delete middle 7.0908 us/op 20.327 us/op 0.35
OrderedSet add up to 256 items then delete middle 31.841 us/op 50.246 us/op 0.63
transfer serialized Status (84 B) 1.3620 us/op 2.0080 us/op 0.68
copy serialized Status (84 B) 1.2400 us/op 1.7770 us/op 0.70
transfer serialized SignedVoluntaryExit (112 B) 1.4340 us/op 2.2010 us/op 0.65
copy serialized SignedVoluntaryExit (112 B) 1.3140 us/op 1.8880 us/op 0.70
transfer serialized ProposerSlashing (416 B) 1.8320 us/op 2.5360 us/op 0.72
copy serialized ProposerSlashing (416 B) 1.8760 us/op 3.3190 us/op 0.57
transfer serialized Attestation (485 B) 1.8470 us/op 3.5220 us/op 0.52
copy serialized Attestation (485 B) 1.9290 us/op 3.2950 us/op 0.59
transfer serialized AttesterSlashing (33232 B) 1.7300 us/op 3.3170 us/op 0.52
copy serialized AttesterSlashing (33232 B) 5.6540 us/op 7.0660 us/op 0.80
transfer serialized Small SignedBeaconBlock (128000 B) 1.8220 us/op 3.5530 us/op 0.51
copy serialized Small SignedBeaconBlock (128000 B) 14.758 us/op 15.559 us/op 0.95
transfer serialized Avg SignedBeaconBlock (200000 B) 1.9260 us/op 3.6440 us/op 0.53
copy serialized Avg SignedBeaconBlock (200000 B) 20.925 us/op 18.510 us/op 1.13
transfer serialized BlobsSidecar (524380 B) 2.1570 us/op 3.6430 us/op 0.59
copy serialized BlobsSidecar (524380 B) 71.571 us/op 106.94 us/op 0.67
transfer serialized Big SignedBeaconBlock (1000000 B) 2.4770 us/op 3.8600 us/op 0.64
copy serialized Big SignedBeaconBlock (1000000 B) 174.36 us/op 169.34 us/op 1.03
pass gossip attestations to forkchoice per slot 2.5484 ms/op 4.0359 ms/op 0.63
forkChoice updateHead vc 100000 bc 64 eq 0 428.75 us/op 718.27 us/op 0.60
forkChoice updateHead vc 600000 bc 64 eq 0 3.2675 ms/op 4.6425 ms/op 0.70
forkChoice updateHead vc 1000000 bc 64 eq 0 4.6680 ms/op 7.9869 ms/op 0.58
forkChoice updateHead vc 600000 bc 320 eq 0 2.7382 ms/op 4.8189 ms/op 0.57
forkChoice updateHead vc 600000 bc 1200 eq 0 2.8935 ms/op 4.7609 ms/op 0.61
forkChoice updateHead vc 600000 bc 7200 eq 0 3.4296 ms/op 5.7311 ms/op 0.60
forkChoice updateHead vc 600000 bc 64 eq 1000 10.075 ms/op 12.690 ms/op 0.79
forkChoice updateHead vc 600000 bc 64 eq 10000 9.8369 ms/op 13.773 ms/op 0.71
forkChoice updateHead vc 600000 bc 64 eq 300000 12.141 ms/op 20.355 ms/op 0.60
computeDeltas 500000 validators 300 proto nodes 3.0993 ms/op 6.9728 ms/op 0.44
computeDeltas 500000 validators 1200 proto nodes 2.9655 ms/op 6.8002 ms/op 0.44
computeDeltas 500000 validators 7200 proto nodes 2.9615 ms/op 6.7534 ms/op 0.44
computeDeltas 750000 validators 300 proto nodes 4.4044 ms/op 10.473 ms/op 0.42
computeDeltas 750000 validators 1200 proto nodes 4.4638 ms/op 10.300 ms/op 0.43
computeDeltas 750000 validators 7200 proto nodes 4.3497 ms/op 10.127 ms/op 0.43
computeDeltas 1400000 validators 300 proto nodes 8.6292 ms/op 19.851 ms/op 0.43
computeDeltas 1400000 validators 1200 proto nodes 8.4046 ms/op 19.739 ms/op 0.43
computeDeltas 1400000 validators 7200 proto nodes 8.5163 ms/op 19.319 ms/op 0.44
computeDeltas 2100000 validators 300 proto nodes 12.715 ms/op 29.367 ms/op 0.43
computeDeltas 2100000 validators 1200 proto nodes 13.102 ms/op 27.760 ms/op 0.47
computeDeltas 2100000 validators 7200 proto nodes 12.847 ms/op 28.390 ms/op 0.45
computeProposerBoostScoreFromBalances 500000 validators 2.8065 ms/op 3.5496 ms/op 0.79
computeProposerBoostScoreFromBalances 750000 validators 2.8257 ms/op 3.5785 ms/op 0.79
computeProposerBoostScoreFromBalances 1400000 validators 2.8056 ms/op 3.5829 ms/op 0.78
computeProposerBoostScoreFromBalances 2100000 validators 2.8090 ms/op 3.7481 ms/op 0.75
altair processAttestation - 250000 vs - 7PWei normalcase 2.1233 ms/op 3.2369 ms/op 0.66
altair processAttestation - 250000 vs - 7PWei worstcase 2.9296 ms/op 4.1296 ms/op 0.71
altair processAttestation - setStatus - 1/6 committees join 84.598 us/op 207.37 us/op 0.41
altair processAttestation - setStatus - 1/3 committees join 167.72 us/op 380.94 us/op 0.44
altair processAttestation - setStatus - 1/2 committees join 230.26 us/op 535.36 us/op 0.43
altair processAttestation - setStatus - 2/3 committees join 312.05 us/op 648.52 us/op 0.48
altair processAttestation - setStatus - 4/5 committees join 418.70 us/op 863.67 us/op 0.48
altair processAttestation - setStatus - 100% committees join 510.24 us/op 991.71 us/op 0.51
altair processBlock - 250000 vs - 7PWei normalcase 7.4465 ms/op 8.0919 ms/op 0.92
altair processBlock - 250000 vs - 7PWei normalcase hashState 28.308 ms/op 33.254 ms/op 0.85
altair processBlock - 250000 vs - 7PWei worstcase 35.717 ms/op 40.476 ms/op 0.88
altair processBlock - 250000 vs - 7PWei worstcase hashState 84.483 ms/op 95.199 ms/op 0.89
phase0 processBlock - 250000 vs - 7PWei normalcase 2.3083 ms/op 3.0086 ms/op 0.77
phase0 processBlock - 250000 vs - 7PWei worstcase 27.478 ms/op 37.157 ms/op 0.74
altair processEth1Data - 250000 vs - 7PWei normalcase 278.64 us/op 645.17 us/op 0.43
getExpectedWithdrawals 250000 eb:1,eth1:1,we:0,wn:0,smpl:15 13.588 us/op 22.922 us/op 0.59
getExpectedWithdrawals 250000 eb:0.95,eth1:0.1,we:0.05,wn:0,smpl:219 58.462 us/op 76.848 us/op 0.76
getExpectedWithdrawals 250000 eb:0.95,eth1:0.3,we:0.05,wn:0,smpl:42 15.221 us/op 31.131 us/op 0.49
getExpectedWithdrawals 250000 eb:0.95,eth1:0.7,we:0.05,wn:0,smpl:18 12.971 us/op 17.947 us/op 0.72
getExpectedWithdrawals 250000 eb:0.1,eth1:0.1,we:0,wn:0,smpl:1020 113.15 us/op 217.99 us/op 0.52
getExpectedWithdrawals 250000 eb:0.03,eth1:0.03,we:0,wn:0,smpl:11777 946.39 us/op 1.5551 ms/op 0.61
getExpectedWithdrawals 250000 eb:0.01,eth1:0.01,we:0,wn:0,smpl:16384 1.1392 ms/op 2.3470 ms/op 0.49
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,smpl:16384 1.3076 ms/op 2.1253 ms/op 0.62
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,nocache,smpl:16384 2.3916 ms/op 4.1557 ms/op 0.58
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,smpl:16384 1.6225 ms/op 3.2391 ms/op 0.50
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,nocache,smpl:16384 4.0436 ms/op 7.0427 ms/op 0.57
Tree 40 250000 create 224.97 ms/op 391.38 ms/op 0.57
Tree 40 250000 get(125000) 121.78 ns/op 240.52 ns/op 0.51
Tree 40 250000 set(125000) 651.18 ns/op 1.1261 us/op 0.58
Tree 40 250000 toArray() 10.443 ms/op 23.501 ms/op 0.44
Tree 40 250000 iterate all - toArray() + loop 11.793 ms/op 23.834 ms/op 0.49
Tree 40 250000 iterate all - get(i) 47.309 ms/op 85.805 ms/op 0.55
MutableVector 250000 create 8.1644 ms/op 18.460 ms/op 0.44
MutableVector 250000 get(125000) 5.7470 ns/op 7.7130 ns/op 0.75
MutableVector 250000 set(125000) 189.63 ns/op 530.05 ns/op 0.36
MutableVector 250000 toArray() 2.3055 ms/op 4.1965 ms/op 0.55
MutableVector 250000 iterate all - toArray() + loop 3.2515 ms/op 4.1544 ms/op 0.78
MutableVector 250000 iterate all - get(i) 1.3119 ms/op 1.8102 ms/op 0.72
Array 250000 create 2.0208 ms/op 3.8459 ms/op 0.53
Array 250000 clone - spread 1.1165 ms/op 1.2929 ms/op 0.86
Array 250000 get(125000) 0.58000 ns/op 0.71800 ns/op 0.81
Array 250000 set(125000) 0.64900 ns/op 1.0780 ns/op 0.60
Array 250000 iterate all - loop 80.798 us/op 104.27 us/op 0.77
effectiveBalanceIncrements clone Uint8Array 300000 12.794 us/op 52.875 us/op 0.24
effectiveBalanceIncrements clone MutableVector 300000 369.00 ns/op 427.00 ns/op 0.86
effectiveBalanceIncrements rw all Uint8Array 300000 171.12 us/op 212.76 us/op 0.80
effectiveBalanceIncrements rw all MutableVector 300000 67.658 ms/op 137.11 ms/op 0.49
phase0 afterProcessEpoch - 250000 vs - 7PWei 81.108 ms/op 130.72 ms/op 0.62
phase0 beforeProcessEpoch - 250000 vs - 7PWei 33.492 ms/op 42.785 ms/op 0.78
altair processEpoch - mainnet_e81889 385.59 ms/op 588.41 ms/op 0.66
mainnet_e81889 - altair beforeProcessEpoch 49.827 ms/op 77.743 ms/op 0.64
mainnet_e81889 - altair processJustificationAndFinalization 14.285 us/op 20.555 us/op 0.69
mainnet_e81889 - altair processInactivityUpdates 7.6533 ms/op 10.023 ms/op 0.76
mainnet_e81889 - altair processRewardsAndPenalties 52.241 ms/op 78.901 ms/op 0.66
mainnet_e81889 - altair processRegistryUpdates 2.7470 us/op 6.0120 us/op 0.46
mainnet_e81889 - altair processSlashings 495.00 ns/op 795.00 ns/op 0.62
mainnet_e81889 - altair processEth1DataReset 621.00 ns/op 912.00 ns/op 0.68
mainnet_e81889 - altair processEffectiveBalanceUpdates 930.82 us/op 1.8087 ms/op 0.51
mainnet_e81889 - altair processSlashingsReset 4.1710 us/op 7.4340 us/op 0.56
mainnet_e81889 - altair processRandaoMixesReset 7.3970 us/op 10.723 us/op 0.69
mainnet_e81889 - altair processHistoricalRootsUpdate 821.00 ns/op 1.7750 us/op 0.46
mainnet_e81889 - altair processParticipationFlagUpdates 1.6300 us/op 4.5420 us/op 0.36
mainnet_e81889 - altair processSyncCommitteeUpdates 709.00 ns/op 1.4090 us/op 0.50
mainnet_e81889 - altair afterProcessEpoch 85.474 ms/op 152.90 ms/op 0.56
capella processEpoch - mainnet_e217614 1.5646 s/op 1.8828 s/op 0.83
mainnet_e217614 - capella beforeProcessEpoch 239.04 ms/op 315.52 ms/op 0.76
mainnet_e217614 - capella processJustificationAndFinalization 14.461 us/op 22.859 us/op 0.63
mainnet_e217614 - capella processInactivityUpdates 17.273 ms/op 25.106 ms/op 0.69
mainnet_e217614 - capella processRewardsAndPenalties 250.77 ms/op 318.43 ms/op 0.79
mainnet_e217614 - capella processRegistryUpdates 28.028 us/op 30.790 us/op 0.91
mainnet_e217614 - capella processSlashings 902.00 ns/op 819.00 ns/op 1.10
mainnet_e217614 - capella processEth1DataReset 771.00 ns/op 523.00 ns/op 1.47
mainnet_e217614 - capella processEffectiveBalanceUpdates 3.2466 ms/op 5.0473 ms/op 0.64
mainnet_e217614 - capella processSlashingsReset 4.3680 us/op 4.4760 us/op 0.98
mainnet_e217614 - capella processRandaoMixesReset 6.3840 us/op 5.6360 us/op 1.13
mainnet_e217614 - capella processHistoricalRootsUpdate 1.1050 us/op 1.0560 us/op 1.05
mainnet_e217614 - capella processParticipationFlagUpdates 2.4440 us/op 3.8350 us/op 0.64
mainnet_e217614 - capella afterProcessEpoch 204.20 ms/op 330.15 ms/op 0.62
phase0 processEpoch - mainnet_e58758 302.35 ms/op 567.36 ms/op 0.53
mainnet_e58758 - phase0 beforeProcessEpoch 100.04 ms/op 154.99 ms/op 0.65
mainnet_e58758 - phase0 processJustificationAndFinalization 18.681 us/op 19.037 us/op 0.98
mainnet_e58758 - phase0 processRewardsAndPenalties 49.515 ms/op 52.476 ms/op 0.94
mainnet_e58758 - phase0 processRegistryUpdates 9.0270 us/op 16.220 us/op 0.56
mainnet_e58758 - phase0 processSlashings 653.00 ns/op 972.00 ns/op 0.67
mainnet_e58758 - phase0 processEth1DataReset 717.00 ns/op 661.00 ns/op 1.08
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 847.19 us/op 1.4317 ms/op 0.59
mainnet_e58758 - phase0 processSlashingsReset 3.8740 us/op 4.6150 us/op 0.84
mainnet_e58758 - phase0 processRandaoMixesReset 7.2060 us/op 6.7380 us/op 1.07
mainnet_e58758 - phase0 processHistoricalRootsUpdate 1.1420 us/op 642.00 ns/op 1.78
mainnet_e58758 - phase0 processParticipationRecordUpdates 7.7270 us/op 4.7890 us/op 1.61
mainnet_e58758 - phase0 afterProcessEpoch 73.892 ms/op 112.54 ms/op 0.66
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.0661 ms/op 1.3196 ms/op 0.81
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.7159 ms/op 2.4793 ms/op 0.69
altair processInactivityUpdates - 250000 normalcase 19.529 ms/op 23.065 ms/op 0.85
altair processInactivityUpdates - 250000 worstcase 19.361 ms/op 23.868 ms/op 0.81
phase0 processRegistryUpdates - 250000 normalcase 10.774 us/op 15.580 us/op 0.69
phase0 processRegistryUpdates - 250000 badcase_full_deposits 361.41 us/op 502.98 us/op 0.72
phase0 processRegistryUpdates - 250000 worstcase 0.5 127.09 ms/op 155.21 ms/op 0.82
altair processRewardsAndPenalties - 250000 normalcase 52.706 ms/op 60.286 ms/op 0.87
altair processRewardsAndPenalties - 250000 worstcase 57.191 ms/op 57.869 ms/op 0.99
phase0 getAttestationDeltas - 250000 normalcase 7.1341 ms/op 10.351 ms/op 0.69
phase0 getAttestationDeltas - 250000 worstcase 5.6739 ms/op 9.7875 ms/op 0.58
phase0 processSlashings - 250000 worstcase 1.6084 ms/op 2.6788 ms/op 0.60
altair processSyncCommitteeUpdates - 250000 96.512 ms/op 170.54 ms/op 0.57
BeaconState.hashTreeRoot - No change 360.00 ns/op 532.00 ns/op 0.68
BeaconState.hashTreeRoot - 1 full validator 113.99 us/op 174.56 us/op 0.65
BeaconState.hashTreeRoot - 32 full validator 1.6709 ms/op 1.4982 ms/op 1.12
BeaconState.hashTreeRoot - 512 full validator 17.639 ms/op 17.864 ms/op 0.99
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 184.34 us/op 194.41 us/op 0.95
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 1.9450 ms/op 2.7642 ms/op 0.70
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 25.564 ms/op 28.899 ms/op 0.88
BeaconState.hashTreeRoot - 1 balances 133.91 us/op 148.50 us/op 0.90
BeaconState.hashTreeRoot - 32 balances 1.0277 ms/op 1.3761 ms/op 0.75
BeaconState.hashTreeRoot - 512 balances 7.2228 ms/op 11.926 ms/op 0.61
BeaconState.hashTreeRoot - 250000 balances 141.29 ms/op 184.14 ms/op 0.77
aggregationBits - 2048 els - zipIndexesInBitList 9.0470 us/op 16.425 us/op 0.55
regular array get 100000 times 30.954 us/op 47.112 us/op 0.66
wrappedArray get 100000 times 30.921 us/op 45.768 us/op 0.68
arrayWithProxy get 100000 times 10.911 ms/op 15.363 ms/op 0.71
ssz.Root.equals 272.00 ns/op 232.00 ns/op 1.17
byteArrayEquals 256.00 ns/op 234.00 ns/op 1.09
shuffle list - 16384 els 4.5006 ms/op 7.4292 ms/op 0.61
shuffle list - 250000 els 66.863 ms/op 110.19 ms/op 0.61
processSlot - 1 slots 14.822 us/op 17.663 us/op 0.84
processSlot - 32 slots 2.4553 ms/op 3.3785 ms/op 0.73
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 47.352 ms/op 50.288 ms/op 0.94
getCommitteeAssignments - req 1 vs - 250000 vc 2.2598 ms/op 2.6441 ms/op 0.85
getCommitteeAssignments - req 100 vs - 250000 vc 3.4013 ms/op 3.9373 ms/op 0.86
getCommitteeAssignments - req 1000 vs - 250000 vc 3.6877 ms/op 4.3006 ms/op 0.86
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.7500 ns/op 5.6500 ns/op 0.84
state getBlockRootAtSlot - 250000 vs - 7PWei 908.31 ns/op 986.90 ns/op 0.92
computeProposers - vc 250000 6.2690 ms/op 10.373 ms/op 0.60
computeEpochShuffling - vc 250000 69.769 ms/op 112.06 ms/op 0.62
getNextSyncCommittee - vc 250000 105.50 ms/op 156.54 ms/op 0.67
computeSigningRoot for AttestationData 22.157 us/op 26.896 us/op 0.82
hash AttestationData serialized data then Buffer.toString(base64) 1.2090 us/op 2.6036 us/op 0.46
toHexString serialized data 769.67 ns/op 1.3373 us/op 0.58
Buffer.toString(base64) 143.57 ns/op 261.25 ns/op 0.55

by benchmarkbot/action

@matthewkeil
Copy link
Member Author

matthewkeil commented Aug 8, 2023

What happens if you pass trace as log level now from the CLI? See requirement mentioned in #4536.

It will error as it's unsupported per our logging policy. Should I throw an error on startup stating that its not supported?

Or perhaps should I leave the functions but throw a better error and kill the process if we use it so we know not to?

@matthewkeil matthewkeil marked this pull request as draft August 8, 2023 08:17
@nflaig
Copy link
Member

nflaig commented Aug 8, 2023

As per issue

This causes Lodestar startup to fail when trace logging is configured.

That way trace logging can be enabled for a "stack" consisting of Lodestar, an EL, Grafana, etc.

Right now we break this use case, I would suggest we go with what I suggested in #5809 (comment).

We should remove it from types to prevent accidental usage but still allow it to be passed through CLI to not break the use case mentioned in #4536.

@matthewkeil matthewkeil force-pushed the mkeil/remove-trace-log-level branch from 5ee0d47 to 4b6a3cc Compare August 8, 2023 08:22
Copy link
Contributor

@dapplion dapplion left a comment

Choose a reason for hiding this comment

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

A runtime error like this is not the best way to handle it

@matthewkeil
Copy link
Member Author

matthewkeil commented Aug 8, 2023

A runtime error like this is not the best way to handle it

I agree. Was actually just messaging @nflaig about this on discord. Was tossing around the idea of just having trace log to the debug LogLevel but that isnt great either because the function can still be used...

Another idea would be to have two "log levels" one for reporting with all of them and one for the "supported levels" that is used for interface generation so the classes do not export the symbol. That way passing --trace as the reporting level just outputs debug level but the intellisense will not have trace as a method. What do you prefer @dapplion and @nflaig?

@nflaig
Copy link
Member

nflaig commented Aug 8, 2023

We can simply update the logger interface

export type Logger = Record<LogLevel, LogHandler>;

to something like this

export type Logger = Record<Exclude<LogLevel, LogLevel.trace>, LogHandler>;

This will allow to set --logLevel trace while also preventing accidental usage in code

@wemeetagain
Copy link
Member

wemeetagain commented Sep 22, 2023

Yeah, would like to see the solution @nflaig proposed

@matthewkeil matthewkeil force-pushed the mkeil/remove-trace-log-level branch from 9fd6f86 to 92cca53 Compare September 29, 2023 14:47
@matthewkeil matthewkeil marked this pull request as ready for review September 29, 2023 15:38
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.

shouldn't this method be removed here as well?

trace(message: string, context?: LogData, error?: Error): void {

@matthewkeil matthewkeil requested a review from nflaig September 29, 2023 16:04
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.

Lgtm, can you update the PR description with the latest changes / motivation before you merge?

@nflaig
Copy link
Member

nflaig commented Sep 30, 2023

On that note, does this close #5809 as well?

The expected behavior in the issue is

A trace log should work and not break the other log levels

but after discussion, the expected behavior should rather be what I mentioend in #5861 (comment)

This will allow to set --logLevel trace while also preventing accidental usage in code

@matthewkeil
Copy link
Member Author

@wemeetagain the PR body is updated but cannot merge because of e2e test not closing cleanly. Ready to merge though I believe.

@matthewkeil matthewkeil mentioned this pull request Oct 1, 2023
@wemeetagain wemeetagain merged commit 1d14dc1 into unstable Oct 2, 2023
@wemeetagain wemeetagain deleted the mkeil/remove-trace-log-level branch October 2, 2023 02:15
@wemeetagain
Copy link
Member

🎉 This PR is included in v1.12.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.

Broken trace logging
4 participants