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

Log attestation's journey published by local validators #3534

Merged
merged 8 commits into from
Apr 13, 2022

Conversation

twoeths
Copy link
Contributor

@twoeths twoeths commented Dec 17, 2021

Motivation

We want to debug #3527 - missing attestations in mainnet

Description

  • Log attestation when it's published to topic and included in AggregateAndProof

  • Don't log when we receive gossip block because I think it's not worth to do so considering the performance to scan through all indices of aggregate and proofs, @dapplion let me know if there's a cheap way to do it. Once an attestation is included in AggregateAndProof, it's likely it's included in upcoming blocks.

part of #3527

@codecov
Copy link

codecov bot commented Dec 17, 2021

Codecov Report

Merging #3534 (caebb63) into master (6df28de) will decrease coverage by 0.11%.
The diff coverage is n/a.

@@            Coverage Diff             @@
##           master    #3534      +/-   ##
==========================================
- Coverage   36.64%   36.52%   -0.12%     
==========================================
  Files         324      324              
  Lines        8954     8980      +26     
  Branches     1406     1410       +4     
==========================================
- Hits         3281     3280       -1     
- Misses       5530     5556      +26     
- Partials      143      144       +1     

@codeclimate
Copy link

codeclimate bot commented Dec 17, 2021

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

Here's the issue category breakdown:

Category Count
Complexity 1

View more on Code Climate.

g11tech
g11tech previously approved these changes Dec 17, 2021
@github-actions
Copy link
Contributor

github-actions bot commented Dec 17, 2021

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 43470af Previous: a81bf84 Ratio
BeaconState.hashTreeRoot - No change 549.00 ns/op 388.00 ns/op 1.41
BeaconState.hashTreeRoot - 1 full validator 75.881 us/op 49.936 us/op 1.52
BeaconState.hashTreeRoot - 32 full validator 774.50 us/op 480.94 us/op 1.61
BeaconState.hashTreeRoot - 512 full validator 8.0282 ms/op 5.9342 ms/op 1.35
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 98.300 us/op 69.030 us/op 1.42
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 1.3382 ms/op 961.50 us/op 1.39
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 17.596 ms/op 13.712 ms/op 1.28
BeaconState.hashTreeRoot - 1 balances 73.306 us/op 53.512 us/op 1.37
BeaconState.hashTreeRoot - 32 balances 644.71 us/op 467.04 us/op 1.38
BeaconState.hashTreeRoot - 512 balances 6.2498 ms/op 4.1727 ms/op 1.50
BeaconState.hashTreeRoot - 250000 balances 133.01 ms/op 94.450 ms/op 1.41
processSlot - 1 slots 14.874 us/op 9.1160 us/op 1.63
processSlot - 32 slots 2.2441 ms/op 1.4394 ms/op 1.56
getCommitteeAssignments - req 1 vs - 250000 vc 5.8964 ms/op 5.2825 ms/op 1.12
getCommitteeAssignments - req 100 vs - 250000 vc 8.5007 ms/op 7.4078 ms/op 1.15
getCommitteeAssignments - req 1000 vs - 250000 vc 8.9791 ms/op 7.2135 ms/op 1.24
computeProposers - vc 250000 20.755 ms/op 15.950 ms/op 1.30
computeEpochShuffling - vc 250000 168.99 ms/op 148.97 ms/op 1.13
getNextSyncCommittee - vc 250000 351.32 ms/op 258.83 ms/op 1.36
altair processAttestation - 250000 vs - 7PWei normalcase 4.5110 ms/op 4.5174 ms/op 1.00
altair processAttestation - 250000 vs - 7PWei worstcase 7.1922 ms/op 5.9770 ms/op 1.20
altair processAttestation - setStatus - 1/6 committees join 242.44 us/op 196.82 us/op 1.23
altair processAttestation - setStatus - 1/3 committees join 438.23 us/op 337.02 us/op 1.30
altair processAttestation - setStatus - 1/2 committees join 619.55 us/op 522.52 us/op 1.19
altair processAttestation - setStatus - 2/3 committees join 816.99 us/op 604.76 us/op 1.35
altair processAttestation - setStatus - 4/5 committees join 1.1503 ms/op 940.17 us/op 1.22
altair processAttestation - setStatus - 100% committees join 1.3412 ms/op 1.0100 ms/op 1.33
altair processBlock - 250000 vs - 7PWei normalcase 31.521 ms/op 24.285 ms/op 1.30
altair processBlock - 250000 vs - 7PWei normalcase hashState 42.922 ms/op 35.264 ms/op 1.22
altair processBlock - 250000 vs - 7PWei worstcase 90.464 ms/op 77.980 ms/op 1.16
altair processBlock - 250000 vs - 7PWei worstcase hashState 121.36 ms/op 93.880 ms/op 1.29
altair processEth1Data - 250000 vs - 7PWei normalcase 1.1507 ms/op 871.74 us/op 1.32
altair processEpoch - mainnet_e81889 657.74 ms/op 540.45 ms/op 1.22
mainnet_e81889 - altair beforeProcessEpoch 148.74 ms/op 134.92 ms/op 1.10
mainnet_e81889 - altair processJustificationAndFinalization 78.854 us/op 25.809 us/op 3.06
mainnet_e81889 - altair processInactivityUpdates 11.889 ms/op 11.230 ms/op 1.06
mainnet_e81889 - altair processRewardsAndPenalties 153.43 ms/op 81.624 ms/op 1.88
mainnet_e81889 - altair processRegistryUpdates 16.607 us/op 3.6080 us/op 4.60
mainnet_e81889 - altair processSlashings 5.5160 us/op 1.1400 us/op 4.84
mainnet_e81889 - altair processEth1DataReset 6.4010 us/op 1.1280 us/op 5.67
mainnet_e81889 - altair processEffectiveBalanceUpdates 8.4441 ms/op 6.4589 ms/op 1.31
mainnet_e81889 - altair processSlashingsReset 23.378 us/op 5.1500 us/op 4.54
mainnet_e81889 - altair processRandaoMixesReset 28.488 us/op 6.2200 us/op 4.58
mainnet_e81889 - altair processHistoricalRootsUpdate 8.6840 us/op 1.3800 us/op 6.29
mainnet_e81889 - altair processParticipationFlagUpdates 16.693 us/op 8.3110 us/op 2.01
mainnet_e81889 - altair processSyncCommitteeUpdates 5.0710 us/op 2.7970 us/op 1.81
mainnet_e81889 - altair afterProcessEpoch 204.92 ms/op 203.21 ms/op 1.01
altair processInactivityUpdates - 250000 normalcase 52.725 ms/op 40.973 ms/op 1.29
altair processInactivityUpdates - 250000 worstcase 37.400 ms/op 51.839 ms/op 0.72
altair processRewardsAndPenalties - 250000 normalcase 98.382 ms/op 144.23 ms/op 0.68
altair processRewardsAndPenalties - 250000 worstcase 144.36 ms/op 144.42 ms/op 1.00
altair processSyncCommitteeUpdates - 250000 374.07 ms/op 299.08 ms/op 1.25
Tree 40 250000 create 879.55 ms/op 797.08 ms/op 1.10
Tree 40 250000 get(125000) 351.37 ns/op 279.98 ns/op 1.25
Tree 40 250000 set(125000) 2.8276 us/op 2.2929 us/op 1.23
Tree 40 250000 toArray() 38.509 ms/op 32.659 ms/op 1.18
Tree 40 250000 iterate all - toArray() + loop 38.403 ms/op 33.717 ms/op 1.14
Tree 40 250000 iterate all - get(i) 140.21 ms/op 99.526 ms/op 1.41
MutableVector 250000 create 17.036 ms/op 24.142 ms/op 0.71
MutableVector 250000 get(125000) 15.609 ns/op 15.325 ns/op 1.02
MutableVector 250000 set(125000) 756.60 ns/op 619.50 ns/op 1.22
MutableVector 250000 toArray() 6.7220 ms/op 6.4916 ms/op 1.04
MutableVector 250000 iterate all - toArray() + loop 7.4312 ms/op 6.8700 ms/op 1.08
MutableVector 250000 iterate all - get(i) 4.0587 ms/op 3.4455 ms/op 1.18
Array 250000 create 6.5082 ms/op 6.0012 ms/op 1.08
Array 250000 clone - spread 2.8166 ms/op 1.9079 ms/op 1.48
Array 250000 get(125000) 1.3430 ns/op 0.88000 ns/op 1.53
Array 250000 set(125000) 1.3240 ns/op 0.87000 ns/op 1.52
Array 250000 iterate all - loop 158.15 us/op 148.10 us/op 1.07
effectiveBalanceIncrements clone Uint8Array 300000 421.70 us/op 73.897 us/op 5.71
effectiveBalanceIncrements clone MutableVector 300000 658.00 ns/op 546.00 ns/op 1.21
effectiveBalanceIncrements rw all Uint8Array 300000 214.81 us/op 266.42 us/op 0.81
effectiveBalanceIncrements rw all MutableVector 300000 191.98 ms/op 182.86 ms/op 1.05
aggregationBits - 2048 els - zipIndexesInBitList 25.955 us/op 30.884 us/op 0.84
regular array get 100000 times 62.596 us/op 59.480 us/op 1.05
wrappedArray get 100000 times 62.865 us/op 59.595 us/op 1.05
arrayWithProxy get 100000 times 42.577 ms/op 26.235 ms/op 1.62
ssz.Root.equals 556.00 ns/op 422.00 ns/op 1.32
byteArrayEquals 546.00 ns/op 410.00 ns/op 1.33
phase0 processBlock - 250000 vs - 7PWei normalcase 4.3808 ms/op 3.5218 ms/op 1.24
phase0 processBlock - 250000 vs - 7PWei worstcase 59.081 ms/op 41.943 ms/op 1.41
phase0 afterProcessEpoch - 250000 vs - 7PWei 191.14 ms/op 161.65 ms/op 1.18
phase0 beforeProcessEpoch - 250000 vs - 7PWei 90.445 ms/op 148.67 ms/op 0.61
phase0 processEpoch - mainnet_e58758 605.39 ms/op 691.22 ms/op 0.88
mainnet_e58758 - phase0 beforeProcessEpoch 223.09 ms/op 320.84 ms/op 0.70
mainnet_e58758 - phase0 processJustificationAndFinalization 73.488 us/op 26.694 us/op 2.75
mainnet_e58758 - phase0 processRewardsAndPenalties 146.98 ms/op 135.97 ms/op 1.08
mainnet_e58758 - phase0 processRegistryUpdates 35.187 us/op 9.8550 us/op 3.57
mainnet_e58758 - phase0 processSlashings 7.0930 us/op 1.1060 us/op 6.41
mainnet_e58758 - phase0 processEth1DataReset 6.0570 us/op 1.0320 us/op 5.87
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 7.3725 ms/op 4.7450 ms/op 1.55
mainnet_e58758 - phase0 processSlashingsReset 22.792 us/op 5.8540 us/op 3.89
mainnet_e58758 - phase0 processRandaoMixesReset 28.135 us/op 6.4500 us/op 4.36
mainnet_e58758 - phase0 processHistoricalRootsUpdate 7.2910 us/op 1.1560 us/op 6.31
mainnet_e58758 - phase0 processParticipationRecordUpdates 25.569 us/op 5.2930 us/op 4.83
mainnet_e58758 - phase0 afterProcessEpoch 173.66 ms/op 148.11 ms/op 1.17
phase0 processEffectiveBalanceUpdates - 250000 normalcase 7.6919 ms/op 6.4705 ms/op 1.19
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 8.2614 ms/op 6.8433 ms/op 1.21
phase0 processRegistryUpdates - 250000 normalcase 30.481 us/op 8.4030 us/op 3.63
phase0 processRegistryUpdates - 250000 badcase_full_deposits 542.33 us/op 370.78 us/op 1.46
phase0 processRegistryUpdates - 250000 worstcase 0.5 259.74 ms/op 275.25 ms/op 0.94
phase0 getAttestationDeltas - 250000 normalcase 17.207 ms/op 13.835 ms/op 1.24
phase0 getAttestationDeltas - 250000 worstcase 17.226 ms/op 14.421 ms/op 1.19
phase0 processSlashings - 250000 worstcase 7.3273 ms/op 5.6902 ms/op 1.29
shuffle list - 16384 els 11.543 ms/op 9.4780 ms/op 1.22
shuffle list - 250000 els 165.18 ms/op 136.68 ms/op 1.21
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 405.54 us/op 363.39 us/op 1.12
pass gossip attestations to forkchoice per slot 4.6492 ms/op 3.7293 ms/op 1.25
computeDeltas 4.0680 ms/op 5.1460 ms/op 0.79
computeProposerBoostScoreFromBalances 520.74 us/op 503.12 us/op 1.04
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 2.7867 ms/op 2.4644 ms/op 1.13
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 87.751 us/op 74.321 us/op 1.18
BLS verify - blst-native 2.4870 ms/op 1.6407 ms/op 1.52
BLS verifyMultipleSignatures 3 - blst-native 4.9172 ms/op 3.3599 ms/op 1.46
BLS verifyMultipleSignatures 8 - blst-native 10.662 ms/op 7.2256 ms/op 1.48
BLS verifyMultipleSignatures 32 - blst-native 39.322 ms/op 26.193 ms/op 1.50
BLS aggregatePubkeys 32 - blst-native 51.373 us/op 35.109 us/op 1.46
BLS aggregatePubkeys 128 - blst-native 202.80 us/op 135.50 us/op 1.50
getAttestationsForBlock 64.487 ms/op 58.601 ms/op 1.10
CheckpointStateCache - add get delete 13.983 us/op 10.810 us/op 1.29
validate gossip signedAggregateAndProof - struct 5.5504 ms/op 4.2866 ms/op 1.29
validate gossip attestation - struct 2.7307 ms/op 2.0279 ms/op 1.35
pickEth1Vote - no votes 2.8261 ms/op 2.2395 ms/op 1.26
pickEth1Vote - max votes 22.950 ms/op 21.184 ms/op 1.08
pickEth1Vote - Eth1Data hashTreeRoot value x2048 16.089 ms/op 10.967 ms/op 1.47
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 26.991 ms/op 28.587 ms/op 0.94
pickEth1Vote - Eth1Data fastSerialize value x2048 2.1955 ms/op 1.7358 ms/op 1.26
pickEth1Vote - Eth1Data fastSerialize tree x2048 15.381 ms/op 14.370 ms/op 1.07
bytes32 toHexString 1.3320 us/op 926.00 ns/op 1.44
bytes32 Buffer.toString(hex) 897.00 ns/op 647.00 ns/op 1.39
bytes32 Buffer.toString(hex) from Uint8Array 1.1620 us/op 840.00 ns/op 1.38
bytes32 Buffer.toString(hex) + 0x 878.00 ns/op 653.00 ns/op 1.34
Object access 1 prop 0.43300 ns/op 0.31600 ns/op 1.37
Map access 1 prop 0.38200 ns/op 0.27300 ns/op 1.40
Object get x1000 18.446 ns/op 15.405 ns/op 1.20
Map get x1000 1.1160 ns/op 0.90600 ns/op 1.23
Object set x1000 110.70 ns/op 99.225 ns/op 1.12
Map set x1000 76.693 ns/op 60.164 ns/op 1.27
Return object 10000 times 0.45330 ns/op 0.32800 ns/op 1.38
Throw Error 10000 times 7.7973 us/op 5.1339 us/op 1.52
enrSubnets - fastDeserialize 64 bits 1.2940 us/op 864.00 ns/op 1.50
enrSubnets - ssz BitVector 64 bits 788.00 ns/op 548.00 ns/op 1.44
enrSubnets - fastDeserialize 4 bits 564.00 ns/op 384.00 ns/op 1.47
enrSubnets - ssz BitVector 4 bits 787.00 ns/op 544.00 ns/op 1.45
RateTracker 1000000 limit, 1 obj count per request 237.21 ns/op 164.53 ns/op 1.44
RateTracker 1000000 limit, 2 obj count per request 164.37 ns/op 123.74 ns/op 1.33
RateTracker 1000000 limit, 4 obj count per request 132.55 ns/op 104.11 ns/op 1.27
RateTracker 1000000 limit, 8 obj count per request 127.37 ns/op 95.234 ns/op 1.34
RateTracker with prune 4.9630 us/op 4.0590 us/op 1.22
array of 16000 items push then shift 5.7270 us/op 2.7927 us/op 2.05
LinkedList of 16000 items push then shift 21.410 ns/op 17.333 ns/op 1.24
array of 16000 items push then pop 241.75 ns/op 200.38 ns/op 1.21
LinkedList of 16000 items push then pop 18.443 ns/op 15.817 ns/op 1.17
array of 24000 items push then shift 8.6475 us/op 4.0458 us/op 2.14
LinkedList of 24000 items push then shift 18.806 ns/op 22.439 ns/op 0.84
array of 24000 items push then pop 226.60 ns/op 204.94 ns/op 1.11
LinkedList of 24000 items push then pop 18.723 ns/op 19.944 ns/op 0.94

by benchmarkbot/action

@dapplion
Copy link
Contributor

dapplion commented Dec 17, 2021

I think this log statements should be part of the validator monitor. And be activated behind a flag since this could be extremely verbose?.

Also, consider using a sub-logger with different module name so it's easier to filter logs with grep.

logger.child({module: "VMON"})

Don't log when we receive gossip block because I think it's not worth to do so considering the performance to scan through all indices of aggregate and proofs

We already do that in the validator monitor

registerAttestationInBlock(indexedAttestation, parentSlot, rootCache): void {

@@ -530,6 +530,11 @@ export function createLodestarMetrics(
help: "The delay between when the validator should send the attestation and when it was received",
labelNames: ["index", "src"],
}),
unaggregatedAttestationMissed: register.gauge<"index" | "subnet">({
Copy link
Contributor

Choose a reason for hiding this comment

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

This is not correct since it doesn't mean it was missed. A better name would be

unaggregatedAttestationSubmittedNoSubnetPeers

but you should clarify if you are counting

  • no mesh peers
  • no peers in the same topic

@dapplion
Copy link
Contributor

@tuyennhv What's the status of this? Waiting for some changes upstream?

@twoeths
Copy link
Contributor Author

twoeths commented Jan 14, 2022

@tuyennhv What's the status of this? Waiting for some changes upstream?

yeah, we also need to upgrade gossipsub-js, gossipsub-js also needs to work with latest libp2p-interface

@philknows philknows added the status-blocked This is blocked by another issue that requires resolving first. label Apr 4, 2022
@twoeths twoeths dismissed a stale review via a7769d9 April 6, 2022 04:23
@twoeths twoeths force-pushed the tuyen/log-attestation-journey branch from d6124e4 to a7769d9 Compare April 6, 2022 04:23
@twoeths twoeths removed the status-blocked This is blocked by another issue that requires resolving first. label Apr 7, 2022
@twoeths twoeths force-pushed the tuyen/log-attestation-journey branch from 0efa9b3 to c475345 Compare April 8, 2022 02:16
@twoeths twoeths marked this pull request as draft April 10, 2022 07:30
@twoeths twoeths force-pushed the tuyen/log-attestation-journey branch from c475345 to 757863b Compare April 10, 2022 07:40
@twoeths twoeths marked this pull request as ready for review April 12, 2022 12:13
@twoeths twoeths requested a review from dapplion April 12, 2022 12:13
@twoeths twoeths requested a review from g11tech April 12, 2022 12:13
@@ -424,7 +423,6 @@ export function getValidatorApi({chain, config, logger, metrics, network, sync}:
async publishAggregateAndProofs(signedAggregateAndProofs) {
notWhileSyncing();

const seenTimestampSec = Date.now() / 1000;
Copy link
Contributor

@dapplion dapplion Apr 12, 2022

Choose a reason for hiding this comment

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

By removing the seenTimestamp from here, now the metric is slightly different:

  • before: Tracks time attestation is received at the start of handling the REST call
  • now: Track the time the attestation is published to gossip. I agree this is the one that matters to us

We should track both, or track the validation time individually. But can be done in a new PR

}

const balance = balances && balances[index];
if (balance !== undefined) {
metrics.validatorMonitor.prevEpochOnChainBalance.set({index}, balance);
}

if (failedAttestation) {
logger.verbose("Failed attestation in previous epoch", {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

change this log level to debug

@twoeths twoeths dismissed a stale review via 702c4d5 April 13, 2022 09:00
@twoeths twoeths requested a review from a team as a code owner April 13, 2022 09:00
const fork = this.config.getForkName(aggregateAndProof.message.aggregate.data.slot);
await this.publishObject<GossipType.beacon_aggregate_and_proof>(
return await this.publishObject<GossipType.beacon_aggregate_and_proof>(
Copy link
Contributor

Choose a reason for hiding this comment

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

Change in all publish* methods for consistency

dapplion
dapplion previously approved these changes Apr 13, 2022
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.

LGMT!

@twoeths twoeths merged commit 106a05a into master Apr 13, 2022
@twoeths twoeths deleted the tuyen/log-attestation-journey branch April 13, 2022 10:09
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.

5 participants