Skip to content

Add logging support to prover - #5250

Merged
wemeetagain merged 2 commits into
unstablefrom
nh/4706-prover-logging
Apr 3, 2023
Merged

Add logging support to prover#5250
wemeetagain merged 2 commits into
unstablefrom
nh/4706-prover-logging

Conversation

@nazarhussain

@nazarhussain nazarhussain commented Mar 9, 2023

Copy link
Copy Markdown
Contributor

Motivation

Add detailed logging support to the prover.

Description

Use should be able to see th logs in the browser as well in the console for the proxy.

Partially resolves #4706

Steps to test or reproduce

Run all tests.

@nazarhussain
nazarhussain requested a review from a team as a code owner March 9, 2023 14:05
@nazarhussain
nazarhussain force-pushed the nh/4706-prover-logging branch from 5abd9bd to 8b092c7 Compare March 13, 2023 12:16
Base automatically changed from nh/4706-lc-prover to unstable March 26, 2023 13:28
@nazarhussain
nazarhussain force-pushed the nh/4706-prover-logging branch from 87fcfde to 74e1b1c Compare March 27, 2023 08:06
github-advanced-security[bot]
github-advanced-security AI found potential problems Mar 27, 2023
View reviewed changes
Comment thread packages/prover/src/utils/execution.ts
if (verifiedHandler !== undefined) {
return verifiedHandler({payload, handler, rootProvider: proofProvider});
logger.verbose("Verified request handler found", {method: payload.method});
return verifiedHandler({payload, handler, proofProvider, logger});

Check failure

Code scanning / CodeQL

Unvalidated dynamic method call

Invocation of method with [user-controlled](1) name may dispatch to unexpected target and cause an exception.
@github-actions

github-actions Bot commented Mar 27, 2023

Copy link
Copy Markdown
Contributor

Performance Report

鉁旓笍 no performance regression detected

Full benchmark results
Benchmark suite Current: 1f8ae05 Previous: 358b9e0 Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 955.54 us/op 802.63 us/op 1.19
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 56.211 us/op 43.793 us/op 1.28
BLS verify - blst-native 1.2406 ms/op 1.1669 ms/op 1.06
BLS verifyMultipleSignatures 3 - blst-native 2.5218 ms/op 2.3730 ms/op 1.06
BLS verifyMultipleSignatures 8 - blst-native 5.4176 ms/op 5.1014 ms/op 1.06
BLS verifyMultipleSignatures 32 - blst-native 19.652 ms/op 18.421 ms/op 1.07
BLS aggregatePubkeys 32 - blst-native 26.514 us/op 24.656 us/op 1.08
BLS aggregatePubkeys 128 - blst-native 102.75 us/op 96.252 us/op 1.07
getAttestationsForBlock 81.798 ms/op 51.296 ms/op 1.59
isKnown best case - 1 super set check 265.00 ns/op 248.00 ns/op 1.07
isKnown normal case - 2 super set checks 259.00 ns/op 246.00 ns/op 1.05
isKnown worse case - 16 super set checks 257.00 ns/op 244.00 ns/op 1.05
CheckpointStateCache - add get delete 6.7860 us/op 4.7230 us/op 1.44
validate gossip signedAggregateAndProof - struct 2.9584 ms/op 2.6616 ms/op 1.11
validate gossip attestation - struct 1.3939 ms/op 1.2762 ms/op 1.09
pickEth1Vote - no votes 1.5061 ms/op 1.1864 ms/op 1.27
pickEth1Vote - max votes 18.409 ms/op 11.440 ms/op 1.61
pickEth1Vote - Eth1Data hashTreeRoot value x2048 11.207 ms/op 8.5610 ms/op 1.31
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 22.122 ms/op 12.598 ms/op 1.76
pickEth1Vote - Eth1Data fastSerialize value x2048 835.02 us/op 620.35 us/op 1.35
pickEth1Vote - Eth1Data fastSerialize tree x2048 7.0339 ms/op 7.8305 ms/op 0.90
bytes32 toHexString 890.00 ns/op 483.00 ns/op 1.84
bytes32 Buffer.toString(hex) 513.00 ns/op 339.00 ns/op 1.51
bytes32 Buffer.toString(hex) from Uint8Array 764.00 ns/op 541.00 ns/op 1.41
bytes32 Buffer.toString(hex) + 0x 507.00 ns/op 347.00 ns/op 1.46
Object access 1 prop 0.22600 ns/op 0.16500 ns/op 1.37
Map access 1 prop 0.17400 ns/op 0.16300 ns/op 1.07
Object get x1000 7.1420 ns/op 6.4590 ns/op 1.11
Map get x1000 0.64700 ns/op 0.59700 ns/op 1.08
Object set x1000 86.110 ns/op 49.770 ns/op 1.73
Map set x1000 63.987 ns/op 43.192 ns/op 1.48
Return object 10000 times 0.28120 ns/op 0.22910 ns/op 1.23
Throw Error 10000 times 4.8772 us/op 4.0732 us/op 1.20
fastMsgIdFn sha256 / 200 bytes 4.0020 us/op 3.3420 us/op 1.20
fastMsgIdFn h32 xxhash / 200 bytes 415.00 ns/op 276.00 ns/op 1.50
fastMsgIdFn h64 xxhash / 200 bytes 590.00 ns/op 376.00 ns/op 1.57
fastMsgIdFn sha256 / 1000 bytes 12.735 us/op 11.240 us/op 1.13
fastMsgIdFn h32 xxhash / 1000 bytes 541.00 ns/op 398.00 ns/op 1.36
fastMsgIdFn h64 xxhash / 1000 bytes 612.00 ns/op 449.00 ns/op 1.36
fastMsgIdFn sha256 / 10000 bytes 107.91 us/op 100.83 us/op 1.07
fastMsgIdFn h32 xxhash / 10000 bytes 2.0380 us/op 1.8350 us/op 1.11
fastMsgIdFn h64 xxhash / 10000 bytes 1.5150 us/op 1.2860 us/op 1.18
enrSubnets - fastDeserialize 64 bits 2.0840 us/op 1.2510 us/op 1.67
enrSubnets - ssz BitVector 64 bits 717.00 ns/op 484.00 ns/op 1.48
enrSubnets - fastDeserialize 4 bits 234.00 ns/op 173.00 ns/op 1.35
enrSubnets - ssz BitVector 4 bits 713.00 ns/op 485.00 ns/op 1.47
prioritizePeers score -10:0 att 32-0.1 sync 2-0 120.12 us/op 106.35 us/op 1.13
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 160.12 us/op 132.43 us/op 1.21
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 191.78 us/op 166.71 us/op 1.15
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 355.24 us/op 301.36 us/op 1.18
prioritizePeers score 0:0 att 64-1 sync 4-1 463.52 us/op 366.55 us/op 1.26
array of 16000 items push then shift 1.6771 us/op 1.6248 us/op 1.03
LinkedList of 16000 items push then shift 9.1190 ns/op 8.8510 ns/op 1.03
array of 16000 items push then pop 128.99 ns/op 77.499 ns/op 1.66
LinkedList of 16000 items push then pop 8.7720 ns/op 8.1100 ns/op 1.08
array of 24000 items push then shift 2.4050 us/op 2.2506 us/op 1.07
LinkedList of 24000 items push then shift 9.1930 ns/op 8.3400 ns/op 1.10
array of 24000 items push then pop 81.182 ns/op 73.539 ns/op 1.10
LinkedList of 24000 items push then pop 8.6390 ns/op 8.2640 ns/op 1.05
intersect bitArray bitLen 8 13.385 ns/op 13.278 ns/op 1.01
intersect array and set length 8 80.515 ns/op 75.373 ns/op 1.07
intersect bitArray bitLen 128 44.110 ns/op 43.026 ns/op 1.03
intersect array and set length 128 1.3617 us/op 1.0237 us/op 1.33
Buffer.concat 32 items 2.9350 us/op 2.7560 us/op 1.06
Uint8Array.set 32 items 3.0400 us/op 2.8270 us/op 1.08
pass gossip attestations to forkchoice per slot 3.7148 ms/op 2.4449 ms/op 1.52
computeDeltas 4.3674 ms/op 2.8242 ms/op 1.55
computeProposerBoostScoreFromBalances 1.8729 ms/op 1.7790 ms/op 1.05
altair processAttestation - 250000 vs - 7PWei normalcase 5.1741 ms/op 2.0323 ms/op 2.55
altair processAttestation - 250000 vs - 7PWei worstcase 5.0947 ms/op 3.1499 ms/op 1.62
altair processAttestation - setStatus - 1/6 committees join 142.11 us/op 138.18 us/op 1.03
altair processAttestation - setStatus - 1/3 committees join 280.74 us/op 272.39 us/op 1.03
altair processAttestation - setStatus - 1/2 committees join 385.16 us/op 365.14 us/op 1.05
altair processAttestation - setStatus - 2/3 committees join 482.05 us/op 445.71 us/op 1.08
altair processAttestation - setStatus - 4/5 committees join 666.97 us/op 646.66 us/op 1.03
altair processAttestation - setStatus - 100% committees join 909.32 us/op 727.97 us/op 1.25
altair processBlock - 250000 vs - 7PWei normalcase 30.159 ms/op 18.456 ms/op 1.63
altair processBlock - 250000 vs - 7PWei normalcase hashState 41.281 ms/op 25.221 ms/op 1.64
altair processBlock - 250000 vs - 7PWei worstcase 47.440 ms/op 51.667 ms/op 0.92
altair processBlock - 250000 vs - 7PWei worstcase hashState 72.221 ms/op 67.758 ms/op 1.07
phase0 processBlock - 250000 vs - 7PWei normalcase 2.3140 ms/op 1.9420 ms/op 1.19
phase0 processBlock - 250000 vs - 7PWei worstcase 32.969 ms/op 27.958 ms/op 1.18
altair processEth1Data - 250000 vs - 7PWei normalcase 526.03 us/op 457.66 us/op 1.15
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 8.8200 us/op 6.6880 us/op 1.32
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 27.065 us/op 19.415 us/op 1.39
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 11.046 us/op 8.5810 us/op 1.29
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 8.0570 us/op 6.3410 us/op 1.27
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 116.00 us/op 74.715 us/op 1.55
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 712.28 us/op 612.15 us/op 1.16
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 967.97 us/op 902.92 us/op 1.07
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 910.62 us/op 912.39 us/op 1.00
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.6927 ms/op 2.2769 ms/op 1.18
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.5362 ms/op 1.4613 ms/op 1.05
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 3.9742 ms/op 3.5228 ms/op 1.13
Tree 40 250000 create 362.18 ms/op 316.55 ms/op 1.14
Tree 40 250000 get(125000) 197.06 ns/op 185.04 ns/op 1.06
Tree 40 250000 set(125000) 1.0709 us/op 909.88 ns/op 1.18
Tree 40 250000 toArray() 21.959 ms/op 16.878 ms/op 1.30
Tree 40 250000 iterate all - toArray() + loop 21.613 ms/op 16.803 ms/op 1.29
Tree 40 250000 iterate all - get(i) 74.225 ms/op 66.781 ms/op 1.11
MutableVector 250000 create 10.315 ms/op 9.1913 ms/op 1.12
MutableVector 250000 get(125000) 6.5010 ns/op 6.3550 ns/op 1.02
MutableVector 250000 set(125000) 263.73 ns/op 255.66 ns/op 1.03
MutableVector 250000 toArray() 3.4794 ms/op 2.6966 ms/op 1.29
MutableVector 250000 iterate all - toArray() + loop 3.2648 ms/op 2.8467 ms/op 1.15
MutableVector 250000 iterate all - get(i) 1.5495 ms/op 1.5241 ms/op 1.02
Array 250000 create 3.3839 ms/op 2.5164 ms/op 1.34
Array 250000 clone - spread 1.2141 ms/op 1.2687 ms/op 0.96
Array 250000 get(125000) 0.59600 ns/op 0.62100 ns/op 0.96
Array 250000 set(125000) 0.69400 ns/op 0.69500 ns/op 1.00
Array 250000 iterate all - loop 83.633 us/op 109.03 us/op 0.77
effectiveBalanceIncrements clone Uint8Array 300000 36.206 us/op 28.010 us/op 1.29
effectiveBalanceIncrements clone MutableVector 300000 396.00 ns/op 418.00 ns/op 0.95
effectiveBalanceIncrements rw all Uint8Array 300000 171.23 us/op 168.01 us/op 1.02
effectiveBalanceIncrements rw all MutableVector 300000 88.955 ms/op 83.114 ms/op 1.07
phase0 afterProcessEpoch - 250000 vs - 7PWei 117.95 ms/op 108.85 ms/op 1.08
phase0 beforeProcessEpoch - 250000 vs - 7PWei 40.536 ms/op 33.544 ms/op 1.21
altair processEpoch - mainnet_e81889 306.03 ms/op 296.98 ms/op 1.03
mainnet_e81889 - altair beforeProcessEpoch 52.278 ms/op 61.321 ms/op 0.85
mainnet_e81889 - altair processJustificationAndFinalization 17.946 us/op 17.159 us/op 1.05
mainnet_e81889 - altair processInactivityUpdates 6.3331 ms/op 5.3121 ms/op 1.19
mainnet_e81889 - altair processRewardsAndPenalties 54.225 ms/op 68.066 ms/op 0.80
mainnet_e81889 - altair processRegistryUpdates 2.8280 us/op 2.7570 us/op 1.03
mainnet_e81889 - altair processSlashings 680.00 ns/op 619.00 ns/op 1.10
mainnet_e81889 - altair processEth1DataReset 867.00 ns/op 652.00 ns/op 1.33
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.2621 ms/op 1.2000 ms/op 1.05
mainnet_e81889 - altair processSlashingsReset 5.2900 us/op 4.6290 us/op 1.14
mainnet_e81889 - altair processRandaoMixesReset 7.5970 us/op 4.6240 us/op 1.64
mainnet_e81889 - altair processHistoricalRootsUpdate 706.00 ns/op 672.00 ns/op 1.05
mainnet_e81889 - altair processParticipationFlagUpdates 3.6370 us/op 2.0560 us/op 1.77
mainnet_e81889 - altair processSyncCommitteeUpdates 461.00 ns/op 921.00 ns/op 0.50
mainnet_e81889 - altair afterProcessEpoch 131.86 ms/op 117.05 ms/op 1.13
phase0 processEpoch - mainnet_e58758 346.54 ms/op 359.29 ms/op 0.96
mainnet_e58758 - phase0 beforeProcessEpoch 119.59 ms/op 128.45 ms/op 0.93
mainnet_e58758 - phase0 processJustificationAndFinalization 20.152 us/op 16.739 us/op 1.20
mainnet_e58758 - phase0 processRewardsAndPenalties 61.846 ms/op 64.207 ms/op 0.96
mainnet_e58758 - phase0 processRegistryUpdates 9.3160 us/op 8.1620 us/op 1.14
mainnet_e58758 - phase0 processSlashings 1.3800 us/op 529.00 ns/op 2.61
mainnet_e58758 - phase0 processEth1DataReset 1.3130 us/op 552.00 ns/op 2.38
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 1.0552 ms/op 949.15 us/op 1.11
mainnet_e58758 - phase0 processSlashingsReset 5.8340 us/op 3.6640 us/op 1.59
mainnet_e58758 - phase0 processRandaoMixesReset 5.1140 us/op 4.4320 us/op 1.15
mainnet_e58758 - phase0 processHistoricalRootsUpdate 836.00 ns/op 664.00 ns/op 1.26
mainnet_e58758 - phase0 processParticipationRecordUpdates 6.6620 us/op 4.0560 us/op 1.64
mainnet_e58758 - phase0 afterProcessEpoch 99.735 ms/op 93.201 ms/op 1.07
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.2841 ms/op 1.1891 ms/op 1.08
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.5053 ms/op 1.4474 ms/op 1.04
altair processInactivityUpdates - 250000 normalcase 26.147 ms/op 18.568 ms/op 1.41
altair processInactivityUpdates - 250000 worstcase 28.624 ms/op 24.328 ms/op 1.18
phase0 processRegistryUpdates - 250000 normalcase 7.3160 us/op 6.8240 us/op 1.07
phase0 processRegistryUpdates - 250000 badcase_full_deposits 270.50 us/op 235.31 us/op 1.15
phase0 processRegistryUpdates - 250000 worstcase 0.5 134.12 ms/op 126.70 ms/op 1.06
altair processRewardsAndPenalties - 250000 normalcase 69.565 ms/op 65.120 ms/op 1.07
altair processRewardsAndPenalties - 250000 worstcase 70.765 ms/op 70.039 ms/op 1.01
phase0 getAttestationDeltas - 250000 normalcase 6.8127 ms/op 6.3844 ms/op 1.07
phase0 getAttestationDeltas - 250000 worstcase 6.6879 ms/op 6.4737 ms/op 1.03
phase0 processSlashings - 250000 worstcase 3.3703 ms/op 3.2262 ms/op 1.04
altair processSyncCommitteeUpdates - 250000 173.15 ms/op 171.26 ms/op 1.01
BeaconState.hashTreeRoot - No change 349.00 ns/op 334.00 ns/op 1.04
BeaconState.hashTreeRoot - 1 full validator 50.516 us/op 51.944 us/op 0.97
BeaconState.hashTreeRoot - 32 full validator 482.93 us/op 533.79 us/op 0.90
BeaconState.hashTreeRoot - 512 full validator 5.5775 ms/op 5.0232 ms/op 1.11
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 61.112 us/op 64.689 us/op 0.94
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 921.92 us/op 870.47 us/op 1.06
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 11.500 ms/op 10.888 ms/op 1.06
BeaconState.hashTreeRoot - 1 balances 52.118 us/op 49.222 us/op 1.06
BeaconState.hashTreeRoot - 32 balances 443.54 us/op 445.17 us/op 1.00
BeaconState.hashTreeRoot - 512 balances 4.5877 ms/op 4.2913 ms/op 1.07
BeaconState.hashTreeRoot - 250000 balances 73.129 ms/op 75.251 ms/op 0.97
aggregationBits - 2048 els - zipIndexesInBitList 15.844 us/op 14.973 us/op 1.06
regular array get 100000 times 32.468 us/op 31.807 us/op 1.02
wrappedArray get 100000 times 32.472 us/op 32.067 us/op 1.01
arrayWithProxy get 100000 times 16.070 ms/op 17.686 ms/op 0.91
ssz.Root.equals 545.00 ns/op 544.00 ns/op 1.00
byteArrayEquals 549.00 ns/op 527.00 ns/op 1.04
shuffle list - 16384 els 6.9624 ms/op 6.4408 ms/op 1.08
shuffle list - 250000 els 101.96 ms/op 94.398 ms/op 1.08
processSlot - 1 slots 8.8650 us/op 9.0670 us/op 0.98
processSlot - 32 slots 1.3683 ms/op 1.3258 ms/op 1.03
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 36.446 ms/op 37.812 ms/op 0.96
getCommitteeAssignments - req 1 vs - 250000 vc 3.1295 ms/op 2.9068 ms/op 1.08
getCommitteeAssignments - req 100 vs - 250000 vc 4.1727 ms/op 4.1279 ms/op 1.01
getCommitteeAssignments - req 1000 vs - 250000 vc 4.4791 ms/op 4.4956 ms/op 1.00
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.7200 ns/op 4.6400 ns/op 1.02
state getBlockRootAtSlot - 250000 vs - 7PWei 593.12 ns/op 764.92 ns/op 0.78
computeProposers - vc 250000 11.313 ms/op 9.8933 ms/op 1.14
computeEpochShuffling - vc 250000 109.55 ms/op 96.539 ms/op 1.13
getNextSyncCommittee - vc 250000 187.93 ms/op 168.75 ms/op 1.11

by benchmarkbot/action

@wemeetagain
wemeetagain merged commit 887064d into unstable Apr 3, 2023
@wemeetagain
wemeetagain deleted the nh/4706-prover-logging branch April 3, 2023 19:52
@wemeetagain

wemeetagain commented May 4, 2023

Copy link
Copy Markdown
Member

馃帀 This PR is included in v1.8.0 馃帀

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@wemeetagain wemeetagain wemeetagain 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.

Lodestar prover for execution api

3 participants

@nazarhussain @wemeetagain @github-advanced-security