Validator's performance issue

[twoeths]

Describe the bug

This is when the slot started

Apr-08 05:19:24.000[CHAIN]         ^[[36mverbose^[[39m: Clock slot slot=2739997

At validator side, block came on time (1.4s after the slot started)

Apr-08 05:19:25.423[]              ^[[36mverbose^[[39m: Found new chain head slot=2739997, head=0xa233e16a0b32634e     ae6eecd32f1d38717d3dbd01d31d3dc59bb6331df46d28f3, previouDuty=0xb1b47f4c2df1e7f0bad5d9745f93d0ee36304924f8f79058db     29ddf3b130cda6, currentDuty=0x0065698b3eea05f0b7c379296842f41ca852e389799275c86761439f2dd0637c

however it took alsmot 6s until the attestations were signed

8860 Apr-08 05:19:31.250[]                ^[[34mdebug^[[39m: Signed attestation slot=2739997, index=13, head=0xa233e16a     0b32634eae6eecd32f1d38717d3dbd01d31d3dc59bb6331df46d28f3, validatorIndex=200305
8861 Apr-08 05:19:31.255[]                ^[[34mdebug^[[39m: Signed attestation slot=2739997, index=31, head=0xa233e16a     0b32634eae6eecd32f1d38717d3dbd01d31d3dc59bb6331df46d28f3, validatorIndex=200333

Expected behavior

Attestations should be signed right after beacon block come

This happened in contabo-20 which contains 50 connected validators

[twoeths]

For a contabo node of 50 validators, it takes 10% of cpu time to sign SelectionProof

since we get attestation duties for current epoch and next epoch, and reorg rarely happens, we should be able to do a cache to divide that time by 2

[twoeths]

Found another example in contabo-19 (30 connected validators atm)

• The node

Apr-10 07:46:24.012[CHAIN]         ^[[36mverbose^[[39m: Clock slot slot=2755132
Apr-10 07:46:24.528[NETWORK]       ^[[36mverbose^[[39m: Received gossip block slot=2755132, root=0x4071…a951, curentSlot=2755132, peerId=bafzaajiiaijccaxdw5dry56grstzoqmadtdlb62vzelzxm44woanmjzaks4pfdjmga

• Validator receives new head on time

Tuyens-MacBook-Pro-16519:~ tuyennguyen$ Apr-10 07:46:25.066[]              ^[[36mverbose^[[39m: Found new chain head slot=2755132, head=0x407115cb641d7f144185807f8afa6bf200a34deda066e0a0a03e87c9c164a951, previouDuty=0x63232b3f6f7b475f40c822026256cc5a86ee8e32e2910a43a354b85f6660b882, currentDuty=0x1f70f883610179c3aee6069ffc68ff388a675b6b693b01c3a25514cce8ff03ba

but it takes >6s until the attestation is signed

Tuyens-MacBook-Pro-16519:~ tuyennguyen$ Apr-10 07:46:31.868[]                ^[[34mdebug^[[39m: Signed attestation slot=2755132, index=63, head=0x407115cb641d7f144185807f8afa6bf200a34deda066e0a0a03e87c9c164a951, validatorIndex=200250

then node published attestation very late, 8s after the block starts

Tuyens-MacBook-Pro-16519:~ tuyennguyen$ Apr-10 07:46:32.141[VMON]          ^[[36mverbose^[[39m: Local validator published unaggregated attestation validatorIndex=200250, slot=2755132, committeeIndex=63, subnet=63, sentPeers=26

and it's not included in any AggregateAndProof

This is one of the reasons for missed attestation in prater #3527, we should track the published attestation delay time in both validator side and the node in #2007

[twoeths]

I debugged the issue, we cache duties by dependent root so we're all good. The profile is ~5 min, which is not enough to conclude the percentage of signing selection proofs, since it may span 2 epochs.