Time scrape metrics

[dapplion]

Motivation

Prometheus metrics show that the scrape time of an overloaded node is ~10 sec. However, I did a CPU profile of that exact same node on such a scrape and internally it only takes ~35ms.

Description

Measure the scrape time of metrics to understand the cost of running metrics without the huge extra time that's introduced somewhere else.

Next steps

• Understand why a 35ms scrape, causes the curl :/metrics to take 10 sec.

[codecov]

Codecov Report

Merging #3542 (23b7273) into master (53f31a7) will not change coverage.
The diff coverage is n/a.

@@           Coverage Diff           @@
##           master    #3542   +/-   ##
=======================================
  Coverage   37.56%   37.56%           
=======================================
  Files         310      310           
  Lines        8253     8253           
  Branches     1273     1273           
=======================================
  Hits         3100     3100           
  Misses       5005     5005           
  Partials      148      148           

[codeclimate]

Code Climate has analyzed commit 23b7273 and detected 1 issue on this pull request.

Here's the issue category breakdown:

Category	Count
Complexity	1

View more on Code Climate.

[github-actions]

Performance Report

✔️ no performance regression detected

Full benchmark results

Benchmark suite	Current: 8e4a70d	Previous: 53f31a7	Ratio
BeaconState.hashTreeRoot - No change	549.00 ns/op	658.00 ns/op	0.83
BeaconState.hashTreeRoot - 1 full validator	123.80 us/op	168.41 us/op	0.74
BeaconState.hashTreeRoot - 32 full validator	1.9148 ms/op	2.5359 ms/op	0.76
BeaconState.hashTreeRoot - 512 full validator	25.087 ms/op	31.835 ms/op	0.79
BeaconState.hashTreeRoot - 1 validator.effectiveBalance	128.59 us/op	164.52 us/op	0.78
BeaconState.hashTreeRoot - 32 validator.effectiveBalance	2.0392 ms/op	2.7867 ms/op	0.73
BeaconState.hashTreeRoot - 512 validator.effectiveBalance	27.774 ms/op	35.353 ms/op	0.79
BeaconState.hashTreeRoot - 1 balances	90.924 us/op	113.77 us/op	0.80
BeaconState.hashTreeRoot - 32 balances	754.21 us/op	970.97 us/op	0.78
BeaconState.hashTreeRoot - 512 balances	7.4064 ms/op	8.9425 ms/op	0.83
BeaconState.hashTreeRoot - 250000 balances	134.03 ms/op	198.30 ms/op	0.68
processSlot - 1 slots	60.187 us/op	67.491 us/op	0.89
processSlot - 32 slots	2.8510 ms/op	3.9407 ms/op	0.72
getCommitteeAssignments - req 1 vs - 250000 vc	5.2266 ms/op	5.5840 ms/op	0.94
getCommitteeAssignments - req 100 vs - 250000 vc	7.2480 ms/op	7.4837 ms/op	0.97
getCommitteeAssignments - req 1000 vs - 250000 vc	7.7637 ms/op	8.1805 ms/op	0.95
computeProposers - vc 250000	20.153 ms/op	25.616 ms/op	0.79
computeEpochShuffling - vc 250000	188.90 ms/op	197.22 ms/op	0.96
getNextSyncCommittee - vc 250000	329.34 ms/op	419.04 ms/op	0.79
altair processAttestation - 250000 vs - 7PWei normalcase	44.125 ms/op	52.026 ms/op	0.85
altair processAttestation - 250000 vs - 7PWei worstcase	45.817 ms/op	54.042 ms/op	0.85
altair processAttestation - setStatus - 1/6 committees join	10.905 ms/op	15.538 ms/op	0.70
altair processAttestation - setStatus - 1/3 committees join	23.652 ms/op	33.561 ms/op	0.70
altair processAttestation - setStatus - 1/2 committees join	39.844 ms/op	44.813 ms/op	0.89
altair processAttestation - setStatus - 2/3 committees join	45.123 ms/op	57.783 ms/op	0.78
altair processAttestation - setStatus - 4/5 committees join	53.578 ms/op	70.242 ms/op	0.76
altair processAttestation - setStatus - 100% committees join	71.052 ms/op	85.683 ms/op	0.83
altair processAttestation - updateEpochParticipants - 1/6 committees join	11.300 ms/op	14.879 ms/op	0.76
altair processAttestation - updateEpochParticipants - 1/3 committees join	24.247 ms/op	30.899 ms/op	0.78
altair processAttestation - updateEpochParticipants - 1/2 committees join	23.507 ms/op	30.623 ms/op	0.77
altair processAttestation - updateEpochParticipants - 2/3 committees join	33.270 ms/op	33.177 ms/op	1.00
altair processAttestation - updateEpochParticipants - 4/5 committees join	30.228 ms/op	41.798 ms/op	0.72
altair processAttestation - updateEpochParticipants - 100% committees join	31.634 ms/op	35.126 ms/op	0.90
altair processAttestation - updateAllStatus	21.651 ms/op	27.623 ms/op	0.78
altair processBlock - 250000 vs - 7PWei normalcase	44.979 ms/op	58.743 ms/op	0.77
altair processBlock - 250000 vs - 7PWei worstcase	140.58 ms/op	141.67 ms/op	0.99
altair processEpoch - mainnet_e81889	1.0614 s/op	1.2368 s/op	0.86
mainnet_e81889 - altair beforeProcessEpoch	365.98 ms/op	320.77 ms/op	1.14
mainnet_e81889 - altair processJustificationAndFinalization	86.132 us/op	122.40 us/op	0.70
mainnet_e81889 - altair processInactivityUpdates	18.867 ms/op	19.526 ms/op	0.97
mainnet_e81889 - altair processRewardsAndPenalties	149.18 ms/op	263.08 ms/op	0.57
mainnet_e81889 - altair processRegistryUpdates	5.4160 us/op	24.768 us/op	0.22
mainnet_e81889 - altair processSlashings	1.2060 us/op	6.7260 us/op	0.18
mainnet_e81889 - altair processEth1DataReset	1.1990 us/op	6.5840 us/op	0.18
mainnet_e81889 - altair processEffectiveBalanceUpdates	11.625 ms/op	12.987 ms/op	0.90
mainnet_e81889 - altair processSlashingsReset	13.924 us/op	39.480 us/op	0.35
mainnet_e81889 - altair processRandaoMixesReset	20.008 us/op	47.076 us/op	0.43
mainnet_e81889 - altair processHistoricalRootsUpdate	2.0270 us/op	8.5930 us/op	0.24
mainnet_e81889 - altair processParticipationFlagUpdates	104.60 ms/op	125.30 ms/op	0.83
mainnet_e81889 - altair processSyncCommitteeUpdates	1.6640 us/op	6.0710 us/op	0.27
mainnet_e81889 - altair afterProcessEpoch	229.82 ms/op	243.09 ms/op	0.95
altair processInactivityUpdates - 250000 normalcase	71.973 ms/op	82.187 ms/op	0.88
altair processInactivityUpdates - 250000 worstcase	88.502 ms/op	80.747 ms/op	1.10
altair processParticipationFlagUpdates - 250000 anycase	105.16 ms/op	111.92 ms/op	0.94
altair processRewardsAndPenalties - 250000 normalcase	153.03 ms/op	166.32 ms/op	0.92
altair processRewardsAndPenalties - 250000 worstcase	151.46 ms/op	165.27 ms/op	0.92
altair processSyncCommitteeUpdates - 250000	361.81 ms/op	446.55 ms/op	0.81
Tree 40 250000 create	880.20 ms/op	1.0115 s/op	0.87
Tree 40 250000 get(125000)	357.56 ns/op	767.97 ns/op	0.47
Tree 40 250000 set(125000)	1.8843 us/op	2.4539 us/op	0.77
Tree 40 250000 toArray()	45.418 ms/op	53.798 ms/op	0.84
Tree 40 250000 iterate all - toArray() + loop	37.993 ms/op	53.930 ms/op	0.70
Tree 40 250000 iterate all - get(i)	119.32 ms/op	134.50 ms/op	0.89
MutableVector 250000 create	24.815 ms/op	28.847 ms/op	0.86
MutableVector 250000 get(125000)	14.178 ns/op	15.342 ns/op	0.92
MutableVector 250000 set(125000)	570.66 ns/op	606.32 ns/op	0.94
MutableVector 250000 toArray()	8.8678 ms/op	9.7207 ms/op	0.91
MutableVector 250000 iterate all - toArray() + loop	9.5938 ms/op	10.975 ms/op	0.87
MutableVector 250000 iterate all - get(i)	3.4062 ms/op	3.7644 ms/op	0.90
Array 250000 create	5.4230 ms/op	5.8145 ms/op	0.93
Array 250000 clone - spread	2.4033 ms/op	2.3791 ms/op	1.01
Array 250000 get(125000)	1.0690 ns/op	1.2000 ns/op	0.89
Array 250000 set(125000)	1.0690 ns/op	1.4190 ns/op	0.75
Array 250000 iterate all - loop	167.86 us/op	157.73 us/op	1.06
aggregationBits - 2048 els - readonlyValues	243.89 us/op	232.35 us/op	1.05
aggregationBits - 2048 els - zipIndexesInBitList	42.207 us/op	41.844 us/op	1.01
regular array get 100000 times	67.469 us/op	58.249 us/op	1.16
wrappedArray get 100000 times	67.558 us/op	56.258 us/op	1.20
arrayWithProxy get 100000 times	29.002 ms/op	33.811 ms/op	0.86
ssz.Root.equals	1.1580 us/op	1.3430 us/op	0.86
ssz.Root.equals with valueOf()	1.3990 us/op	1.6360 us/op	0.86
byteArrayEquals with valueOf()	1.3530 us/op	1.6970 us/op	0.80
phase0 processBlock - 250000 vs - 7PWei normalcase	11.028 ms/op	13.400 ms/op	0.82
phase0 processBlock - 250000 vs - 7PWei worstcase	78.771 ms/op	98.259 ms/op	0.80
phase0 afterProcessEpoch - 250000 vs - 7PWei	213.43 ms/op	237.98 ms/op	0.90
phase0 beforeProcessEpoch - 250000 vs - 7PWei	599.49 ms/op	770.44 ms/op	0.78
phase0 processEpoch - mainnet_e58758	820.70 ms/op	971.35 ms/op	0.84
mainnet_e58758 - phase0 beforeProcessEpoch	506.47 ms/op	640.32 ms/op	0.79
mainnet_e58758 - phase0 processJustificationAndFinalization	53.258 us/op	118.36 us/op	0.45
mainnet_e58758 - phase0 processRewardsAndPenalties	168.20 ms/op	115.77 ms/op	1.45
mainnet_e58758 - phase0 processRegistryUpdates	36.209 us/op	88.015 us/op	0.41
mainnet_e58758 - phase0 processSlashings	1.4850 us/op	6.2670 us/op	0.24
mainnet_e58758 - phase0 processEth1DataReset	1.7300 us/op	5.8480 us/op	0.30
mainnet_e58758 - phase0 processEffectiveBalanceUpdates	9.3967 ms/op	10.996 ms/op	0.85
mainnet_e58758 - phase0 processSlashingsReset	9.5350 us/op	32.244 us/op	0.30
mainnet_e58758 - phase0 processRandaoMixesReset	12.677 us/op	39.465 us/op	0.32
mainnet_e58758 - phase0 processHistoricalRootsUpdate	2.0150 us/op	7.4880 us/op	0.27
mainnet_e58758 - phase0 processParticipationRecordUpdates	8.0520 us/op	29.120 us/op	0.28
mainnet_e58758 - phase0 afterProcessEpoch	184.75 ms/op	203.51 ms/op	0.91
phase0 processEffectiveBalanceUpdates - 250000 normalcase	10.203 ms/op	12.522 ms/op	0.81
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5	1.3652 s/op	1.8102 s/op	0.75
phase0 processRegistryUpdates - 250000 normalcase	37.673 us/op	92.418 us/op	0.41
phase0 processRegistryUpdates - 250000 badcase_full_deposits	2.9746 ms/op	4.0803 ms/op	0.73
phase0 processRegistryUpdates - 250000 worstcase 0.5	1.5045 s/op	2.5211 s/op	0.60
phase0 getAttestationDeltas - 250000 normalcase	34.759 ms/op	37.106 ms/op	0.94
phase0 getAttestationDeltas - 250000 worstcase	34.658 ms/op	37.371 ms/op	0.93
phase0 processSlashings - 250000 worstcase	38.490 ms/op	41.966 ms/op	0.92
shuffle list - 16384 els	13.073 ms/op	15.516 ms/op	0.84
shuffle list - 250000 els	186.85 ms/op	196.51 ms/op	0.95
getEffectiveBalances - 250000 vs - 7PWei	9.5839 ms/op	11.955 ms/op	0.80
computeDeltas	3.8579 ms/op	3.8978 ms/op	0.99
getPubkeys - index2pubkey - req 1000 vs - 250000 vc	2.3173 ms/op	2.4097 ms/op	0.96
getPubkeys - validatorsArr - req 1000 vs - 250000 vc	696.39 us/op	764.73 us/op	0.91
BLS verify - blst-native	1.8565 ms/op	2.2573 ms/op	0.82
BLS verifyMultipleSignatures 3 - blst-native	3.8207 ms/op	4.5062 ms/op	0.85
BLS verifyMultipleSignatures 8 - blst-native	8.2447 ms/op	10.327 ms/op	0.80
BLS verifyMultipleSignatures 32 - blst-native	29.915 ms/op	37.984 ms/op	0.79
BLS aggregatePubkeys 32 - blst-native	40.001 us/op	48.051 us/op	0.83
BLS aggregatePubkeys 128 - blst-native	154.10 us/op	186.39 us/op	0.83
getAttestationsForBlock	79.087 ms/op	89.700 ms/op	0.88
CheckpointStateCache - add get delete	15.177 us/op	76.038 us/op	0.20
validate gossip signedAggregateAndProof - struct	4.4426 ms/op	5.7335 ms/op	0.77
validate gossip signedAggregateAndProof - treeBacked	4.4243 ms/op	5.3368 ms/op	0.83
validate gossip attestation - struct	2.0877 ms/op	2.5725 ms/op	0.81
validate gossip attestation - treeBacked	2.1131 ms/op	2.7243 ms/op	0.78
Object access 1 prop	0.30200 ns/op	0.40700 ns/op	0.74
Map access 1 prop	0.27900 ns/op	0.35700 ns/op	0.78
Object get x1000	17.725 ns/op	17.406 ns/op	1.02
Map get x1000	0.97300 ns/op	0.99200 ns/op	0.98
Object set x1000	102.09 ns/op	102.93 ns/op	0.99
Map set x1000	61.303 ns/op	71.674 ns/op	0.86
Return object 10000 times	0.36890 ns/op	0.41490 ns/op	0.89
Throw Error 10000 times	5.8653 us/op	6.7281 us/op	0.87
RateTracker 1000000 limit, 1 obj count per request	176.10 ns/op	185.31 ns/op	0.95
RateTracker 1000000 limit, 2 obj count per request	130.21 ns/op	137.61 ns/op	0.95
RateTracker 1000000 limit, 4 obj count per request	106.60 ns/op	114.88 ns/op	0.93
RateTracker 1000000 limit, 8 obj count per request	94.675 ns/op	105.88 ns/op	0.89
RateTracker with prune	3.7030 us/op	4.1760 us/op	0.89

by benchmarkbot/action

[dapplion]

Tested locally and works as expected 👍