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

Track fetch response streaming time #5233

Merged
merged 1 commit into from
Mar 6, 2023
Merged

Track fetch response streaming time #5233

merged 1 commit into from
Mar 6, 2023

Conversation

twoeths
Copy link
Contributor

@twoeths twoeths commented Mar 6, 2023

Motivation

As found in #5227, sometimes it takes a lot of time to stream the block body to client, thanks @nflaig for the finding.

Description

  • Add streamTime to all http client metrics

Closes #5227

@github-actions
Copy link
Contributor

github-actions bot commented Mar 6, 2023

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 2ede6df Previous: fa13bdb Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 1.2151 ms/op 733.82 us/op 1.66
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 68.549 us/op 56.334 us/op 1.22
BLS verify - blst-native 1.2341 ms/op 1.3199 ms/op 0.93
BLS verifyMultipleSignatures 3 - blst-native 2.5118 ms/op 2.6091 ms/op 0.96
BLS verifyMultipleSignatures 8 - blst-native 5.4310 ms/op 5.5054 ms/op 0.99
BLS verifyMultipleSignatures 32 - blst-native 19.537 ms/op 20.527 ms/op 0.95
BLS aggregatePubkeys 32 - blst-native 26.440 us/op 27.375 us/op 0.97
BLS aggregatePubkeys 128 - blst-native 102.53 us/op 104.71 us/op 0.98
getAttestationsForBlock 82.889 ms/op 60.983 ms/op 1.36
isKnown best case - 1 super set check 270.00 ns/op 271.00 ns/op 1.00
isKnown normal case - 2 super set checks 264.00 ns/op 265.00 ns/op 1.00
isKnown worse case - 16 super set checks 268.00 ns/op 263.00 ns/op 1.02
CheckpointStateCache - add get delete 6.3430 us/op 5.9960 us/op 1.06
validate gossip signedAggregateAndProof - struct 2.8385 ms/op 2.9155 ms/op 0.97
validate gossip attestation - struct 1.3455 ms/op 1.3857 ms/op 0.97
pickEth1Vote - no votes 1.4692 ms/op 1.5619 ms/op 0.94
pickEth1Vote - max votes 15.297 ms/op 14.034 ms/op 1.09
pickEth1Vote - Eth1Data hashTreeRoot value x2048 9.4281 ms/op 10.323 ms/op 0.91
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 16.179 ms/op 15.992 ms/op 1.01
pickEth1Vote - Eth1Data fastSerialize value x2048 650.37 us/op 792.32 us/op 0.82
pickEth1Vote - Eth1Data fastSerialize tree x2048 6.4138 ms/op 5.4127 ms/op 1.18
bytes32 toHexString 488.00 ns/op 626.00 ns/op 0.78
bytes32 Buffer.toString(hex) 349.00 ns/op 435.00 ns/op 0.80
bytes32 Buffer.toString(hex) from Uint8Array 557.00 ns/op 638.00 ns/op 0.87
bytes32 Buffer.toString(hex) + 0x 341.00 ns/op 444.00 ns/op 0.77
Object access 1 prop 0.16400 ns/op 0.21100 ns/op 0.78
Map access 1 prop 0.16500 ns/op 0.18200 ns/op 0.91
Object get x1000 6.8090 ns/op 7.3250 ns/op 0.93
Map get x1000 0.60100 ns/op 0.69800 ns/op 0.86
Object set x1000 52.591 ns/op 69.373 ns/op 0.76
Map set x1000 43.079 ns/op 57.468 ns/op 0.75
Return object 10000 times 0.23430 ns/op 0.25360 ns/op 0.92
Throw Error 10000 times 4.1450 us/op 4.5633 us/op 0.91
fastMsgIdFn sha256 / 200 bytes 3.3910 us/op 3.7540 us/op 0.90
fastMsgIdFn h32 xxhash / 200 bytes 277.00 ns/op 331.00 ns/op 0.84
fastMsgIdFn h64 xxhash / 200 bytes 388.00 ns/op 497.00 ns/op 0.78
fastMsgIdFn sha256 / 1000 bytes 11.489 us/op 12.330 us/op 0.93
fastMsgIdFn h32 xxhash / 1000 bytes 401.00 ns/op 486.00 ns/op 0.83
fastMsgIdFn h64 xxhash / 1000 bytes 465.00 ns/op 584.00 ns/op 0.80
fastMsgIdFn sha256 / 10000 bytes 103.08 us/op 111.58 us/op 0.92
fastMsgIdFn h32 xxhash / 10000 bytes 1.9060 us/op 2.1670 us/op 0.88
fastMsgIdFn h64 xxhash / 10000 bytes 1.3780 us/op 1.5370 us/op 0.90
enrSubnets - fastDeserialize 64 bits 1.8430 us/op 1.9070 us/op 0.97
enrSubnets - ssz BitVector 64 bits 755.00 ns/op 646.00 ns/op 1.17
enrSubnets - fastDeserialize 4 bits 227.00 ns/op 221.00 ns/op 1.03
enrSubnets - ssz BitVector 4 bits 731.00 ns/op 620.00 ns/op 1.18
prioritizePeers score -10:0 att 32-0.1 sync 2-0 126.02 us/op 119.47 us/op 1.05
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 180.21 us/op 167.31 us/op 1.08
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 217.54 us/op 204.19 us/op 1.07
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 401.03 us/op 403.25 us/op 0.99
prioritizePeers score 0:0 att 64-1 sync 4-1 490.50 us/op 517.01 us/op 0.95
array of 16000 items push then shift 1.7637 us/op 1.8864 us/op 0.93
LinkedList of 16000 items push then shift 11.075 ns/op 11.264 ns/op 0.98
array of 16000 items push then pop 142.35 ns/op 136.36 ns/op 1.04
LinkedList of 16000 items push then pop 10.611 ns/op 10.419 ns/op 1.02
array of 24000 items push then shift 2.5164 us/op 2.7902 us/op 0.90
LinkedList of 24000 items push then shift 11.810 ns/op 11.119 ns/op 1.06
array of 24000 items push then pop 94.731 ns/op 103.94 ns/op 0.91
LinkedList of 24000 items push then pop 10.369 ns/op 9.6910 ns/op 1.07
intersect bitArray bitLen 8 14.138 ns/op 14.398 ns/op 0.98
intersect array and set length 8 124.17 ns/op 100.18 ns/op 1.24
intersect bitArray bitLen 128 46.466 ns/op 47.154 ns/op 0.99
intersect array and set length 128 1.4160 us/op 1.3164 us/op 1.08
Buffer.concat 32 items 2.7980 us/op 2.9450 us/op 0.95
Uint8Array.set 32 items 2.6070 us/op 2.8290 us/op 0.92
pass gossip attestations to forkchoice per slot 2.5185 ms/op 2.5601 ms/op 0.98
computeDeltas 3.0328 ms/op 3.2564 ms/op 0.93
computeProposerBoostScoreFromBalances 1.8244 ms/op 1.9067 ms/op 0.96
altair processAttestation - 250000 vs - 7PWei normalcase 3.8459 ms/op 3.0934 ms/op 1.24
altair processAttestation - 250000 vs - 7PWei worstcase 3.9032 ms/op 4.2382 ms/op 0.92
altair processAttestation - setStatus - 1/6 committees join 147.78 us/op 156.05 us/op 0.95
altair processAttestation - setStatus - 1/3 committees join 292.06 us/op 296.97 us/op 0.98
altair processAttestation - setStatus - 1/2 committees join 377.95 us/op 411.21 us/op 0.92
altair processAttestation - setStatus - 2/3 committees join 479.69 us/op 486.11 us/op 0.99
altair processAttestation - setStatus - 4/5 committees join 683.51 us/op 713.34 us/op 0.96
altair processAttestation - setStatus - 100% committees join 801.18 us/op 816.51 us/op 0.98
altair processBlock - 250000 vs - 7PWei normalcase 19.430 ms/op 17.621 ms/op 1.10
altair processBlock - 250000 vs - 7PWei normalcase hashState 34.529 ms/op 32.314 ms/op 1.07
altair processBlock - 250000 vs - 7PWei worstcase 51.040 ms/op 52.085 ms/op 0.98
altair processBlock - 250000 vs - 7PWei worstcase hashState 71.448 ms/op 74.244 ms/op 0.96
phase0 processBlock - 250000 vs - 7PWei normalcase 2.2269 ms/op 2.4600 ms/op 0.91
phase0 processBlock - 250000 vs - 7PWei worstcase 29.656 ms/op 33.782 ms/op 0.88
altair processEth1Data - 250000 vs - 7PWei normalcase 663.15 us/op 649.73 us/op 1.02
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 7.5550 us/op 13.404 us/op 0.56
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 20.991 us/op 30.321 us/op 0.69
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 8.2620 us/op 9.5270 us/op 0.87
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 12.262 us/op 12.389 us/op 0.99
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 123.92 us/op 110.01 us/op 1.13
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 658.20 us/op 703.80 us/op 0.94
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 919.02 us/op 940.29 us/op 0.98
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 915.79 us/op 944.10 us/op 0.97
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.3443 ms/op 2.5729 ms/op 0.91
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.6949 ms/op 1.6452 ms/op 1.03
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 3.9377 ms/op 4.7530 ms/op 0.83
Tree 40 250000 create 289.17 ms/op 465.11 ms/op 0.62
Tree 40 250000 get(125000) 178.21 ns/op 215.20 ns/op 0.83
Tree 40 250000 set(125000) 906.44 ns/op 1.3289 us/op 0.68
Tree 40 250000 toArray() 18.376 ms/op 26.897 ms/op 0.68
Tree 40 250000 iterate all - toArray() + loop 17.267 ms/op 26.810 ms/op 0.64
Tree 40 250000 iterate all - get(i) 66.547 ms/op 82.857 ms/op 0.80
MutableVector 250000 create 10.336 ms/op 12.503 ms/op 0.83
MutableVector 250000 get(125000) 6.3520 ns/op 7.0770 ns/op 0.90
MutableVector 250000 set(125000) 261.14 ns/op 316.25 ns/op 0.83
MutableVector 250000 toArray() 3.8507 ms/op 3.9952 ms/op 0.96
MutableVector 250000 iterate all - toArray() + loop 4.0384 ms/op 4.1401 ms/op 0.98
MutableVector 250000 iterate all - get(i) 1.5686 ms/op 1.6474 ms/op 0.95
Array 250000 create 2.6226 ms/op 3.7942 ms/op 0.69
Array 250000 clone - spread 1.2686 ms/op 1.3368 ms/op 0.95
Array 250000 get(125000) 0.60900 ns/op 0.66200 ns/op 0.92
Array 250000 set(125000) 0.67700 ns/op 0.74900 ns/op 0.90
Array 250000 iterate all - loop 82.219 us/op 112.34 us/op 0.73
effectiveBalanceIncrements clone Uint8Array 300000 28.555 us/op 49.860 us/op 0.57
effectiveBalanceIncrements clone MutableVector 300000 401.00 ns/op 452.00 ns/op 0.89
effectiveBalanceIncrements rw all Uint8Array 300000 165.17 us/op 183.94 us/op 0.90
effectiveBalanceIncrements rw all MutableVector 300000 84.459 ms/op 114.72 ms/op 0.74
phase0 afterProcessEpoch - 250000 vs - 7PWei 119.37 ms/op 125.38 ms/op 0.95
phase0 beforeProcessEpoch - 250000 vs - 7PWei 34.813 ms/op 50.837 ms/op 0.68
altair processEpoch - mainnet_e81889 322.19 ms/op 369.01 ms/op 0.87
mainnet_e81889 - altair beforeProcessEpoch 62.268 ms/op 82.943 ms/op 0.75
mainnet_e81889 - altair processJustificationAndFinalization 16.080 us/op 21.259 us/op 0.76
mainnet_e81889 - altair processInactivityUpdates 5.0428 ms/op 6.9712 ms/op 0.72
mainnet_e81889 - altair processRewardsAndPenalties 50.235 ms/op 55.847 ms/op 0.90
mainnet_e81889 - altair processRegistryUpdates 2.3820 us/op 3.1190 us/op 0.76
mainnet_e81889 - altair processSlashings 490.00 ns/op 630.00 ns/op 0.78
mainnet_e81889 - altair processEth1DataReset 500.00 ns/op 618.00 ns/op 0.81
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.2093 ms/op 1.3898 ms/op 0.87
mainnet_e81889 - altair processSlashingsReset 4.5790 us/op 4.7710 us/op 0.96
mainnet_e81889 - altair processRandaoMixesReset 4.5650 us/op 12.278 us/op 0.37
mainnet_e81889 - altair processHistoricalRootsUpdate 613.00 ns/op 2.2400 us/op 0.27
mainnet_e81889 - altair processParticipationFlagUpdates 2.2230 us/op 6.8360 us/op 0.33
mainnet_e81889 - altair processSyncCommitteeUpdates 469.00 ns/op 942.00 ns/op 0.50
mainnet_e81889 - altair afterProcessEpoch 115.44 ms/op 139.40 ms/op 0.83
phase0 processEpoch - mainnet_e58758 311.22 ms/op 405.77 ms/op 0.77
mainnet_e58758 - phase0 beforeProcessEpoch 119.64 ms/op 209.67 ms/op 0.57
mainnet_e58758 - phase0 processJustificationAndFinalization 15.861 us/op 27.983 us/op 0.57
mainnet_e58758 - phase0 processRewardsAndPenalties 52.020 ms/op 59.215 ms/op 0.88
mainnet_e58758 - phase0 processRegistryUpdates 7.5290 us/op 12.778 us/op 0.59
mainnet_e58758 - phase0 processSlashings 499.00 ns/op 1.4440 us/op 0.35
mainnet_e58758 - phase0 processEth1DataReset 512.00 ns/op 1.0440 us/op 0.49
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 944.14 us/op 1.0844 ms/op 0.87
mainnet_e58758 - phase0 processSlashingsReset 3.3550 us/op 6.0420 us/op 0.56
mainnet_e58758 - phase0 processRandaoMixesReset 4.5160 us/op 4.6920 us/op 0.96
mainnet_e58758 - phase0 processHistoricalRootsUpdate 598.00 ns/op 1.0350 us/op 0.58
mainnet_e58758 - phase0 processParticipationRecordUpdates 3.8430 us/op 5.4870 us/op 0.70
mainnet_e58758 - phase0 afterProcessEpoch 94.536 ms/op 107.72 ms/op 0.88
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.2016 ms/op 1.2922 ms/op 0.93
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.4621 ms/op 1.6187 ms/op 0.90
altair processInactivityUpdates - 250000 normalcase 23.038 ms/op 30.182 ms/op 0.76
altair processInactivityUpdates - 250000 worstcase 20.927 ms/op 28.994 ms/op 0.72
phase0 processRegistryUpdates - 250000 normalcase 5.9820 us/op 7.5370 us/op 0.79
phase0 processRegistryUpdates - 250000 badcase_full_deposits 216.74 us/op 281.37 us/op 0.77
phase0 processRegistryUpdates - 250000 worstcase 0.5 105.68 ms/op 157.63 ms/op 0.67
altair processRewardsAndPenalties - 250000 normalcase 48.747 ms/op 77.646 ms/op 0.63
altair processRewardsAndPenalties - 250000 worstcase 58.726 ms/op 79.830 ms/op 0.74
phase0 getAttestationDeltas - 250000 normalcase 6.1319 ms/op 7.1786 ms/op 0.85
phase0 getAttestationDeltas - 250000 worstcase 6.6345 ms/op 7.1574 ms/op 0.93
phase0 processSlashings - 250000 worstcase 3.5774 ms/op 3.7883 ms/op 0.94
altair processSyncCommitteeUpdates - 250000 167.54 ms/op 199.81 ms/op 0.84
BeaconState.hashTreeRoot - No change 256.00 ns/op 348.00 ns/op 0.74
BeaconState.hashTreeRoot - 1 full validator 49.654 us/op 56.164 us/op 0.88
BeaconState.hashTreeRoot - 32 full validator 492.11 us/op 583.81 us/op 0.84
BeaconState.hashTreeRoot - 512 full validator 5.1456 ms/op 6.1484 ms/op 0.84
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 61.513 us/op 69.971 us/op 0.88
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 853.72 us/op 1.0163 ms/op 0.84
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 10.987 ms/op 14.562 ms/op 0.75
BeaconState.hashTreeRoot - 1 balances 48.220 us/op 53.576 us/op 0.90
BeaconState.hashTreeRoot - 32 balances 441.56 us/op 533.88 us/op 0.83
BeaconState.hashTreeRoot - 512 balances 4.2561 ms/op 4.7098 ms/op 0.90
BeaconState.hashTreeRoot - 250000 balances 72.747 ms/op 81.864 ms/op 0.89
aggregationBits - 2048 els - zipIndexesInBitList 16.300 us/op 21.031 us/op 0.78
regular array get 100000 times 32.184 us/op 35.718 us/op 0.90
wrappedArray get 100000 times 32.180 us/op 34.619 us/op 0.93
arrayWithProxy get 100000 times 15.605 ms/op 17.600 ms/op 0.89
ssz.Root.equals 539.00 ns/op 610.00 ns/op 0.88
byteArrayEquals 523.00 ns/op 600.00 ns/op 0.87
shuffle list - 16384 els 6.7217 ms/op 7.4243 ms/op 0.91
shuffle list - 250000 els 98.135 ms/op 109.01 ms/op 0.90
processSlot - 1 slots 8.4650 us/op 10.583 us/op 0.80
processSlot - 32 slots 1.3013 ms/op 1.5304 ms/op 0.85
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 189.05 us/op 227.17 us/op 0.83
getCommitteeAssignments - req 1 vs - 250000 vc 2.9039 ms/op 3.1812 ms/op 0.91
getCommitteeAssignments - req 100 vs - 250000 vc 4.1418 ms/op 4.5714 ms/op 0.91
getCommitteeAssignments - req 1000 vs - 250000 vc 4.4306 ms/op 4.9255 ms/op 0.90
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.3800 ns/op 5.5100 ns/op 0.79
state getBlockRootAtSlot - 250000 vs - 7PWei 955.23 ns/op 670.85 ns/op 1.42
computeProposers - vc 250000 10.288 ms/op 11.293 ms/op 0.91
computeEpochShuffling - vc 250000 100.81 ms/op 108.74 ms/op 0.93
getNextSyncCommittee - vc 250000 174.21 ms/op 186.50 ms/op 0.93

by benchmarkbot/action

@twoeths twoeths marked this pull request as ready for review March 6, 2023 08:35
@twoeths twoeths requested a review from a team as a code owner March 6, 2023 08:35
nflaig
nflaig approved these changes Mar 6, 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

@twoeths twoeths merged commit eca63ad into unstable Mar 6, 2023
@twoeths twoeths deleted the tuyen/fetch_streaming_time branch March 6, 2023 13:03
@dapplion
Copy link
Contributor

dapplion commented Mar 7, 2023

@tuyennhv if that's an issue we can fine-tune the vc-bn interaction to:

  • Always use blinded mode
  • Exchange SSZ instead of JSON

@wemeetagain
Copy link
Member

🎉 This PR is included in v1.6.0 🎉

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

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

Vc delays publishing block for unknown reason
4 participants
@twoeths @dapplion @wemeetagain @nflaig