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(logger): avoid creating new winston instance for each child #5597

Merged
merged 1 commit into from
Jun 1, 2023

Conversation

nflaig
Copy link
Member

@nflaig nflaig commented Jun 1, 2023

Motivation

As discussed in #5490 (comment)

Method to create child loggers was updated in

This causes issues with no clear benefit

Description

Reverts logger.child implementation back to original approach

child(options: LoggerChildOpts): WinstonLogger {

This avoids MaxListenersExceededWarning warnings as it no longer creates a new winston instance for each child logger.

Reverts #5537 as the workaround is no longer needed.

@nflaig nflaig marked this pull request as ready for review June 1, 2023 12:48
@nflaig nflaig requested a review from a team as a code owner June 1, 2023 12:48
@github-actions
Copy link
Contributor

github-actions bot commented Jun 1, 2023

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 98c6d10 Previous: e2e5417 Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 1.1685 ms/op 852.99 us/op 1.37
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 67.036 us/op 43.675 us/op 1.53
BLS verify - blst-native 1.4155 ms/op 1.2199 ms/op 1.16
BLS verifyMultipleSignatures 3 - blst-native 2.8944 ms/op 2.4440 ms/op 1.18
BLS verifyMultipleSignatures 8 - blst-native 6.2718 ms/op 5.2677 ms/op 1.19
BLS verifyMultipleSignatures 32 - blst-native 22.702 ms/op 19.036 ms/op 1.19
BLS aggregatePubkeys 32 - blst-native 31.426 us/op 25.625 us/op 1.23
BLS aggregatePubkeys 128 - blst-native 119.45 us/op 100.37 us/op 1.19
getAttestationsForBlock 66.565 ms/op 55.099 ms/op 1.21
isKnown best case - 1 super set check 287.00 ns/op 260.00 ns/op 1.10
isKnown normal case - 2 super set checks 290.00 ns/op 288.00 ns/op 1.01
isKnown worse case - 16 super set checks 285.00 ns/op 250.00 ns/op 1.14
CheckpointStateCache - add get delete 6.0260 us/op 5.0810 us/op 1.19
validate gossip signedAggregateAndProof - struct 3.1173 ms/op 2.7725 ms/op 1.12
validate gossip attestation - struct 1.4854 ms/op 1.3397 ms/op 1.11
pickEth1Vote - no votes 1.4348 ms/op 1.3736 ms/op 1.04
pickEth1Vote - max votes 11.114 ms/op 11.733 ms/op 0.95
pickEth1Vote - Eth1Data hashTreeRoot value x2048 10.655 ms/op 8.8090 ms/op 1.21
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 20.906 ms/op 15.050 ms/op 1.39
pickEth1Vote - Eth1Data fastSerialize value x2048 880.72 us/op 620.85 us/op 1.42
pickEth1Vote - Eth1Data fastSerialize tree x2048 7.1987 ms/op 7.8530 ms/op 0.92
bytes32 toHexString 734.00 ns/op 525.00 ns/op 1.40
bytes32 Buffer.toString(hex) 448.00 ns/op 369.00 ns/op 1.21
bytes32 Buffer.toString(hex) from Uint8Array 713.00 ns/op 550.00 ns/op 1.30
bytes32 Buffer.toString(hex) + 0x 484.00 ns/op 355.00 ns/op 1.36
Object access 1 prop 0.21500 ns/op 0.16300 ns/op 1.32
Map access 1 prop 0.19000 ns/op 0.15800 ns/op 1.20
Object get x1000 7.5200 ns/op 6.5900 ns/op 1.14
Map get x1000 0.71500 ns/op 0.56000 ns/op 1.28
Object set x1000 74.461 ns/op 53.647 ns/op 1.39
Map set x1000 60.843 ns/op 44.299 ns/op 1.37
Return object 10000 times 0.28390 ns/op 0.23520 ns/op 1.21
Throw Error 10000 times 5.1565 us/op 4.2426 us/op 1.22
fastMsgIdFn sha256 / 200 bytes 4.1000 us/op 3.4890 us/op 1.18
fastMsgIdFn h32 xxhash / 200 bytes 367.00 ns/op 284.00 ns/op 1.29
fastMsgIdFn h64 xxhash / 200 bytes 541.00 ns/op 399.00 ns/op 1.36
fastMsgIdFn sha256 / 1000 bytes 13.301 us/op 11.679 us/op 1.14
fastMsgIdFn h32 xxhash / 1000 bytes 488.00 ns/op 471.00 ns/op 1.04
fastMsgIdFn h64 xxhash / 1000 bytes 600.00 ns/op 583.00 ns/op 1.03
fastMsgIdFn sha256 / 10000 bytes 117.01 us/op 106.73 us/op 1.10
fastMsgIdFn h32 xxhash / 10000 bytes 2.1660 us/op 2.1500 us/op 1.01
fastMsgIdFn h64 xxhash / 10000 bytes 1.5380 us/op 1.6170 us/op 0.95
enrSubnets - fastDeserialize 64 bits 1.8880 us/op 1.8450 us/op 1.02
enrSubnets - ssz BitVector 64 bits 668.00 ns/op 644.00 ns/op 1.04
enrSubnets - fastDeserialize 4 bits 227.00 ns/op 214.00 ns/op 1.06
enrSubnets - ssz BitVector 4 bits 656.00 ns/op 670.00 ns/op 0.98
prioritizePeers score -10:0 att 32-0.1 sync 2-0 120.88 us/op 122.25 us/op 0.99
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 174.58 us/op 171.62 us/op 1.02
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 216.02 us/op 189.65 us/op 1.14
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 426.52 us/op 348.85 us/op 1.22
prioritizePeers score 0:0 att 64-1 sync 4-1 475.87 us/op 413.83 us/op 1.15
array of 16000 items push then shift 1.8804 us/op 1.7190 us/op 1.09
LinkedList of 16000 items push then shift 10.432 ns/op 9.3400 ns/op 1.12
array of 16000 items push then pop 124.14 ns/op 116.08 ns/op 1.07
LinkedList of 16000 items push then pop 10.435 ns/op 8.4840 ns/op 1.23
array of 24000 items push then shift 2.7660 us/op 2.3589 us/op 1.17
LinkedList of 24000 items push then shift 10.898 ns/op 8.6810 ns/op 1.26
array of 24000 items push then pop 103.87 ns/op 75.018 ns/op 1.38
LinkedList of 24000 items push then pop 11.090 ns/op 8.5410 ns/op 1.30
intersect bitArray bitLen 8 15.198 ns/op 13.082 ns/op 1.16
intersect array and set length 8 112.46 ns/op 74.701 ns/op 1.51
intersect bitArray bitLen 128 49.890 ns/op 43.449 ns/op 1.15
intersect array and set length 128 1.3819 us/op 1.0304 us/op 1.34
Buffer.concat 32 items 3.4620 us/op 2.5820 us/op 1.34
Uint8Array.set 32 items 2.8940 us/op 2.6060 us/op 1.11
transfer serialized Status (84 B) 2.3580 us/op 2.1070 us/op 1.12
copy serialized Status (84 B) 1.9430 us/op 1.7310 us/op 1.12
transfer serialized SignedVoluntaryExit (112 B) 2.5470 us/op 2.1300 us/op 1.20
copy serialized SignedVoluntaryExit (112 B) 2.0430 us/op 1.6710 us/op 1.22
transfer serialized ProposerSlashing (416 B) 2.9040 us/op 2.1610 us/op 1.34
copy serialized ProposerSlashing (416 B) 3.1890 us/op 1.9440 us/op 1.64
transfer serialized Attestation (485 B) 3.0560 us/op 2.1520 us/op 1.42
copy serialized Attestation (485 B) 2.9280 us/op 2.2450 us/op 1.30
transfer serialized AttesterSlashing (33232 B) 3.0520 us/op 2.7190 us/op 1.12
copy serialized AttesterSlashing (33232 B) 7.9520 us/op 5.3820 us/op 1.48
transfer serialized Small SignedBeaconBlock (128000 B) 3.7200 us/op 2.6360 us/op 1.41
copy serialized Small SignedBeaconBlock (128000 B) 27.308 us/op 13.049 us/op 2.09
transfer serialized Avg SignedBeaconBlock (200000 B) 4.8990 us/op 3.1100 us/op 1.58
copy serialized Avg SignedBeaconBlock (200000 B) 49.231 us/op 18.369 us/op 2.68
transfer serialized BlobsSidecar (524380 B) 4.1770 us/op 2.9550 us/op 1.41
copy serialized BlobsSidecar (524380 B) 222.95 us/op 123.33 us/op 1.81
transfer serialized Big SignedBeaconBlock (1000000 B) 4.4930 us/op 3.0970 us/op 1.45
copy serialized Big SignedBeaconBlock (1000000 B) 365.44 us/op 262.58 us/op 1.39
pass gossip attestations to forkchoice per slot 3.2310 ms/op 2.6229 ms/op 1.23
forkChoice updateHead vc 100000 bc 64 eq 0 2.5778 ms/op 2.1349 ms/op 1.21
forkChoice updateHead vc 600000 bc 64 eq 0 13.434 ms/op 13.704 ms/op 0.98
forkChoice updateHead vc 1000000 bc 64 eq 0 25.913 ms/op 18.887 ms/op 1.37
forkChoice updateHead vc 600000 bc 320 eq 0 19.123 ms/op 16.397 ms/op 1.17
forkChoice updateHead vc 600000 bc 1200 eq 0 100.24 ms/op 80.825 ms/op 1.24
forkChoice updateHead vc 600000 bc 64 eq 1000 24.185 ms/op 20.365 ms/op 1.19
forkChoice updateHead vc 600000 bc 64 eq 10000 26.513 ms/op 21.833 ms/op 1.21
forkChoice updateHead vc 600000 bc 64 eq 300000 45.461 ms/op 30.515 ms/op 1.49
computeDeltas 3.5687 ms/op 3.4121 ms/op 1.05
computeProposerBoostScoreFromBalances 2.1079 ms/op 1.7871 ms/op 1.18
altair processAttestation - 250000 vs - 7PWei normalcase 3.6693 ms/op 2.2611 ms/op 1.62
altair processAttestation - 250000 vs - 7PWei worstcase 5.0251 ms/op 4.6181 ms/op 1.09
altair processAttestation - setStatus - 1/6 committees join 174.79 us/op 155.09 us/op 1.13
altair processAttestation - setStatus - 1/3 committees join 355.43 us/op 279.88 us/op 1.27
altair processAttestation - setStatus - 1/2 committees join 447.06 us/op 376.51 us/op 1.19
altair processAttestation - setStatus - 2/3 committees join 567.40 us/op 481.26 us/op 1.18
altair processAttestation - setStatus - 4/5 committees join 796.29 us/op 664.16 us/op 1.20
altair processAttestation - setStatus - 100% committees join 909.94 us/op 758.44 us/op 1.20
altair processBlock - 250000 vs - 7PWei normalcase 23.591 ms/op 19.099 ms/op 1.24
altair processBlock - 250000 vs - 7PWei normalcase hashState 31.949 ms/op 27.076 ms/op 1.18
altair processBlock - 250000 vs - 7PWei worstcase 73.251 ms/op 52.320 ms/op 1.40
altair processBlock - 250000 vs - 7PWei worstcase hashState 94.785 ms/op 77.297 ms/op 1.23
phase0 processBlock - 250000 vs - 7PWei normalcase 3.7348 ms/op 2.3637 ms/op 1.58
phase0 processBlock - 250000 vs - 7PWei worstcase 38.490 ms/op 30.358 ms/op 1.27
altair processEth1Data - 250000 vs - 7PWei normalcase 778.03 us/op 545.55 us/op 1.43
getExpectedWithdrawals 250000 eb:1,eth1:1,we:0,wn:0,smpl:15 13.103 us/op 13.466 us/op 0.97
getExpectedWithdrawals 250000 eb:0.95,eth1:0.1,we:0.05,wn:0,smpl:219 36.512 us/op 37.773 us/op 0.97
getExpectedWithdrawals 250000 eb:0.95,eth1:0.3,we:0.05,wn:0,smpl:42 16.681 us/op 17.348 us/op 0.96
getExpectedWithdrawals 250000 eb:0.95,eth1:0.7,we:0.05,wn:0,smpl:18 13.251 us/op 13.052 us/op 1.02
getExpectedWithdrawals 250000 eb:0.1,eth1:0.1,we:0,wn:0,smpl:1020 122.90 us/op 114.92 us/op 1.07
getExpectedWithdrawals 250000 eb:0.03,eth1:0.03,we:0,wn:0,smpl:11777 913.51 us/op 785.60 us/op 1.16
getExpectedWithdrawals 250000 eb:0.01,eth1:0.01,we:0,wn:0,smpl:16384 1.1523 ms/op 1.2929 ms/op 0.89
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,smpl:16384 1.2304 ms/op 1.3647 ms/op 0.90
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,nocache,smpl:16384 3.0997 ms/op 4.0953 ms/op 0.76
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,smpl:16384 2.0251 ms/op 2.1739 ms/op 0.93
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,nocache,smpl:16384 5.4949 ms/op 7.5507 ms/op 0.73
Tree 40 250000 create 639.27 ms/op 857.44 ms/op 0.75
Tree 40 250000 get(125000) 235.24 ns/op 205.70 ns/op 1.14
Tree 40 250000 set(125000) 1.6975 us/op 2.2813 us/op 0.74
Tree 40 250000 toArray() 26.534 ms/op 38.430 ms/op 0.69
Tree 40 250000 iterate all - toArray() + loop 26.267 ms/op 33.439 ms/op 0.79
Tree 40 250000 iterate all - get(i) 88.323 ms/op 92.671 ms/op 0.95
MutableVector 250000 create 15.066 ms/op 17.127 ms/op 0.88
MutableVector 250000 get(125000) 7.5720 ns/op 7.4610 ns/op 1.01
MutableVector 250000 set(125000) 579.80 ns/op 660.54 ns/op 0.88
MutableVector 250000 toArray() 4.6361 ms/op 5.6466 ms/op 0.82
MutableVector 250000 iterate all - toArray() + loop 5.2259 ms/op 5.6047 ms/op 0.93
MutableVector 250000 iterate all - get(i) 1.8163 ms/op 1.7579 ms/op 1.03
Array 250000 create 4.2771 ms/op 5.3717 ms/op 0.80
Array 250000 clone - spread 1.4450 ms/op 4.6801 ms/op 0.31
Array 250000 get(125000) 0.70300 ns/op 1.9790 ns/op 0.36
Array 250000 set(125000) 0.72100 ns/op 2.2310 ns/op 0.32
Array 250000 iterate all - loop 96.153 us/op 129.06 us/op 0.75
effectiveBalanceIncrements clone Uint8Array 300000 46.841 us/op 83.099 us/op 0.56
effectiveBalanceIncrements clone MutableVector 300000 403.00 ns/op 1.7820 us/op 0.23
effectiveBalanceIncrements rw all Uint8Array 300000 208.98 us/op 224.18 us/op 0.93
effectiveBalanceIncrements rw all MutableVector 300000 107.50 ms/op 264.67 ms/op 0.41
phase0 afterProcessEpoch - 250000 vs - 7PWei 137.84 ms/op 150.00 ms/op 0.92
phase0 beforeProcessEpoch - 250000 vs - 7PWei 53.780 ms/op 83.755 ms/op 0.64
altair processEpoch - mainnet_e81889 418.67 ms/op 475.00 ms/op 0.88
mainnet_e81889 - altair beforeProcessEpoch 90.079 ms/op 143.34 ms/op 0.63
mainnet_e81889 - altair processJustificationAndFinalization 34.060 us/op 42.871 us/op 0.79
mainnet_e81889 - altair processInactivityUpdates 9.0939 ms/op 8.9825 ms/op 1.01
mainnet_e81889 - altair processRewardsAndPenalties 79.481 ms/op 92.408 ms/op 0.86
mainnet_e81889 - altair processRegistryUpdates 5.5810 us/op 6.6710 us/op 0.84
mainnet_e81889 - altair processSlashings 1.3140 us/op 1.6760 us/op 0.78
mainnet_e81889 - altair processEth1DataReset 1.2620 us/op 1.0920 us/op 1.16
mainnet_e81889 - altair processEffectiveBalanceUpdates 2.0063 ms/op 2.0431 ms/op 0.98
mainnet_e81889 - altair processSlashingsReset 7.8570 us/op 7.1030 us/op 1.11
mainnet_e81889 - altair processRandaoMixesReset 9.7210 us/op 6.9100 us/op 1.41
mainnet_e81889 - altair processHistoricalRootsUpdate 2.0830 us/op 851.00 ns/op 2.45
mainnet_e81889 - altair processParticipationFlagUpdates 5.4240 us/op 2.7310 us/op 1.99
mainnet_e81889 - altair processSyncCommitteeUpdates 1.3010 us/op 1.1030 us/op 1.18
mainnet_e81889 - altair afterProcessEpoch 172.02 ms/op 131.61 ms/op 1.31
phase0 processEpoch - mainnet_e58758 488.99 ms/op 373.05 ms/op 1.31
mainnet_e58758 - phase0 beforeProcessEpoch 192.34 ms/op 138.24 ms/op 1.39
mainnet_e58758 - phase0 processJustificationAndFinalization 24.280 us/op 29.633 us/op 0.82
mainnet_e58758 - phase0 processRewardsAndPenalties 76.222 ms/op 62.316 ms/op 1.22
mainnet_e58758 - phase0 processRegistryUpdates 13.788 us/op 13.516 us/op 1.02
mainnet_e58758 - phase0 processSlashings 880.00 ns/op 1.2680 us/op 0.69
mainnet_e58758 - phase0 processEth1DataReset 1.4510 us/op 1.1480 us/op 1.26
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 1.3942 ms/op 1.0679 ms/op 1.31
mainnet_e58758 - phase0 processSlashingsReset 9.9740 us/op 8.9530 us/op 1.11
mainnet_e58758 - phase0 processRandaoMixesReset 9.5650 us/op 7.6350 us/op 1.25
mainnet_e58758 - phase0 processHistoricalRootsUpdate 917.00 ns/op 1.3600 us/op 0.67
mainnet_e58758 - phase0 processParticipationRecordUpdates 13.407 us/op 4.1420 us/op 3.24
mainnet_e58758 - phase0 afterProcessEpoch 112.25 ms/op 94.992 ms/op 1.18
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.6711 ms/op 1.2531 ms/op 1.33
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 2.3638 ms/op 1.5420 ms/op 1.53
altair processInactivityUpdates - 250000 normalcase 34.413 ms/op 25.326 ms/op 1.36
altair processInactivityUpdates - 250000 worstcase 22.660 ms/op 27.282 ms/op 0.83
phase0 processRegistryUpdates - 250000 normalcase 9.1050 us/op 6.4670 us/op 1.41
phase0 processRegistryUpdates - 250000 badcase_full_deposits 384.57 us/op 264.90 us/op 1.45
phase0 processRegistryUpdates - 250000 worstcase 0.5 142.51 ms/op 115.35 ms/op 1.24
altair processRewardsAndPenalties - 250000 normalcase 67.905 ms/op 68.351 ms/op 0.99
altair processRewardsAndPenalties - 250000 worstcase 77.878 ms/op 68.364 ms/op 1.14
phase0 getAttestationDeltas - 250000 normalcase 6.8132 ms/op 7.5528 ms/op 0.90
phase0 getAttestationDeltas - 250000 worstcase 7.3859 ms/op 6.8690 ms/op 1.08
phase0 processSlashings - 250000 worstcase 3.5391 ms/op 3.4782 ms/op 1.02
altair processSyncCommitteeUpdates - 250000 193.84 ms/op 179.53 ms/op 1.08
BeaconState.hashTreeRoot - No change 280.00 ns/op 357.00 ns/op 0.78
BeaconState.hashTreeRoot - 1 full validator 59.223 us/op 52.648 us/op 1.12
BeaconState.hashTreeRoot - 32 full validator 593.36 us/op 500.38 us/op 1.19
BeaconState.hashTreeRoot - 512 full validator 6.3720 ms/op 5.4991 ms/op 1.16
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 69.978 us/op 61.080 us/op 1.15
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 926.28 us/op 953.96 us/op 0.97
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 11.794 ms/op 10.968 ms/op 1.08
BeaconState.hashTreeRoot - 1 balances 58.160 us/op 48.663 us/op 1.20
BeaconState.hashTreeRoot - 32 balances 517.03 us/op 478.71 us/op 1.08
BeaconState.hashTreeRoot - 512 balances 5.0345 ms/op 4.3530 ms/op 1.16
BeaconState.hashTreeRoot - 250000 balances 87.021 ms/op 74.107 ms/op 1.17
aggregationBits - 2048 els - zipIndexesInBitList 17.148 us/op 15.404 us/op 1.11
regular array get 100000 times 35.150 us/op 39.662 us/op 0.89
wrappedArray get 100000 times 46.950 us/op 32.302 us/op 1.45
arrayWithProxy get 100000 times 17.855 ms/op 15.801 ms/op 1.13
ssz.Root.equals 580.00 ns/op 546.00 ns/op 1.06
byteArrayEquals 578.00 ns/op 531.00 ns/op 1.09
shuffle list - 16384 els 7.4118 ms/op 6.8646 ms/op 1.08
shuffle list - 250000 els 107.98 ms/op 100.55 ms/op 1.07
processSlot - 1 slots 9.7940 us/op 8.6430 us/op 1.13
processSlot - 32 slots 1.4782 ms/op 1.3397 ms/op 1.10
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 39.429 ms/op 36.387 ms/op 1.08
getCommitteeAssignments - req 1 vs - 250000 vc 3.0368 ms/op 2.8699 ms/op 1.06
getCommitteeAssignments - req 100 vs - 250000 vc 4.2940 ms/op 4.0738 ms/op 1.05
getCommitteeAssignments - req 1000 vs - 250000 vc 4.6569 ms/op 4.5197 ms/op 1.03
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 5.0000 ns/op 4.9600 ns/op 1.01
state getBlockRootAtSlot - 250000 vs - 7PWei 641.60 ns/op 661.54 ns/op 0.97
computeProposers - vc 250000 10.773 ms/op 10.566 ms/op 1.02
computeEpochShuffling - vc 250000 110.24 ms/op 104.02 ms/op 1.06
getNextSyncCommittee - vc 250000 188.36 ms/op 171.75 ms/op 1.10
computeSigningRoot for AttestationData 14.274 us/op 13.089 us/op 1.09
hash AttestationData serialized data then Buffer.toString(base64) 2.6275 us/op 2.4733 us/op 1.06
toHexString serialized data 1.1343 us/op 1.0673 us/op 1.06
Buffer.toString(base64) 351.97 ns/op 313.82 ns/op 1.12

by benchmarkbot/action

@wemeetagain wemeetagain merged commit f7df70a into unstable Jun 1, 2023
@wemeetagain wemeetagain deleted the nflaig/revert-logger-child branch June 1, 2023 14:12
@wemeetagain
Copy link
Member

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

2 participants