Lodestar produces phase0 beacon block body very slowly

[twoeths]

Describe the bug

This is on a mainnet node, it affects both builder flow and local flow:

note that this is not an issue of execution engine

Expected behavior

with getAttestationsForBlock performance test is <100ms, I think it should take <500ms to produce block, right now it's more than that

Steps to reproduce

No response

Additional context

No response

Operating system

Linux

Lodestar version or commit hash

v1.9.2

[twoeths]

It's worth to mention that this may only happen at start slot of epoch only. Found another case at start slot at epoch:

Jul-23 09:07:36.171[]                ^[[34mdebug^[[39m: Detected new block proposer currentSlot=6939936
Jul-23 09:07:36.171[]                ^[[34mdebug^[[39m: Producing block slot=6939936, validator=0xb2217d06dc2662d0a0e84d5009a2394206d3ee5b60647b21e7e92835102626fa842176c7fab7dca63a8028b04ab1b045, isBuilderEnabled=true, builderSelection=maxprofit, expectedFeeRecipient=0x388c818ca8b9251b393131c08a736a67ccb19297, strictFeeRecipientCheck=false
Jul-23 09:07:38.610[]                ^[[34mdebug^[[39m: Block production race (builder vs execution) event=resolved, source=builder, delayMs=2437, cutoffMs=2000, timeoutMs=12000
Jul-23 09:07:38.622[]                ^[[34mdebug^[[39m: Produced block slot=6939936, validator=0xb2217d06dc2662d0a0e84d5009a2394206d3ee5b60647b21e7e92835102626fa842176c7fab7dca63a8028b04ab1b045, source=builder, blockValue=0.15308 ETH

[twoeths]

Lodestar produced phase0 beacon block body very late

Jul-23 12:06:47.016[chain]         ^[[36mverbose^[[39m: Clock slot slot=6940832
Jul-23 12:06:49.719[rest]            ^[[34mdebug^[[39m: Req req-46b7 16.16.16.31 produceBlockV2
Jul-23 12:07:01.799[chain]         ^[[36mverbose^[[39m: Produced phase0 beacon block body slot=6940832, numAttestations=128
Jul-23 12:07:01.839[chain]         ^[[36mverbose^[[39m: Produced phase0 beacon block body slot=6940832, numAttestations=128
Jul-23 12:07:01.973[chain]         ^[[36mverbose^[[39m: Fetched execution payload from engine slot=6940832, blockValue=46262358010817433, prepType=Cached, payloadId=0x18bb032e73ea6d14, fetchedTime=14.973000049591064
Jul-23 12:07:02.269[api]           ^[[36mverbose^[[39m: Produced execution block slot=6940832, blockValue=46262358010817433, root=0xaa6c47d6c7990d6f25a5aab01516b2ea9a75acc6f8af6b9817d5ccb3ce3ffaf9

[philknows]

It's worth to mention that this may only happen at start slot of epoch only. Found another case at start slot at epoch:

It seems to be pretty systemic in the network that slot 1 is trying to reorg slot 0. Potuz pointed out problems potentially on gossip validation rather than validators purposefully proposing late.

[twoeths]

on goerli, sometimes it spiked to 1s

[nazarhussain]

Below is the analysis of the highest time of the block production which is over 1s.

  |   | 2023-11-27 09:53:48.001 | Nov-27 08:53:48.001[chain]         verbose: Clock slot slot=7047269 |  
  |   | 2023-11-27 09:53:48.002 | Nov-27 08:53:48.002[]                debug: Producing block slot=7047269, validator=0x94505e569c31c18d69529125800018602122a016bee9dfaae27fd4e4400a3cbf0c7852cd4ed5e72620f1c9caf7154940, builderSelection=maxprofit, feeRecipient=0x94750381be1aba0504c666ee1db118f68f0780d4, strictFeeRecipientCheck=false, useProduceBlockV3=true |  
  |   | 2023-11-27 09:53:48.056 | Nov-27 08:53:48.056[api]           verbose: produceBlockV3 assembling block fork=capella, builderSelection=maxprofit, slot=7047269, isBuilderEnabled=true, strictFeeRecipientCheck=false |  
  |   | 2023-11-27 09:53:48.058 | Nov-27 08:53:48.058[chain]         verbose: Producing beacon block body fork=capella, blockType=Blinded, slot=7047269 |  
  |   | 2023-11-27 09:53:48.161 | Nov-27 08:53:48.160[chain]         verbose: Producing beacon block body fork=capella, blockType=Full, slot=7047269 |  
  |   | 2023-11-27 09:53:48.266 | time="2023-11-27T08:53:48.266Z" level=info msg="getHeader request start - 9683977266 milliseconds into slot 7047269" genesisTime=1606824023 method=getHeader msIntoSlot=9683977266 parentHash=0xf3dace8484b2c93d33849365234cc44bb670425d0fe5c41490775d1ed7057ef4 pubkey=0x94505e569c31c18d69529125800018602122a016bee9dfaae27fd4e4400a3cbf0c7852cd4ed5e72620f1c9caf7154940 slot=7047269 slotTimeSec=12 slotUID=6fcafe71-a254-438f-8768-d408ec3dcdc7 ua=Lodestar/v1.12.0/9d68181 version=v1.6 |  
  |   | 2023-11-27 09:53:48.272 | Nov-27 08:53:48.272[chain]         verbose: Fetched execution payload from engine slot=7047269, executionPayloadValue=156467575957239126, prepType=Cached, payloadId=0xce3b46d95c6a378e, fetchedTime=0.2720000743865967 |  
  |   | 2023-11-27 09:53:48.273 | Nov-27 08:53:48.272[chain]         verbose: Produced beacon block body fork=capella, blockType=Full, slot=7047269, attestations=128, deposits=0, voluntaryExits=0, attesterSlashings=0, proposerSlashings=0, feeRecipientType=requested, feeRecipient=0x94750381be1aba0504c666ee1db118f68f0780d4, executionPayloadPrepType=Cached, transactions=72, blsToExecutionChanges=0, withdrawals=16, executionPayloadValue=156467575957239126 |  
  |   | 2023-11-27 09:53:48.362 | Nov-27 08:53:48.362[api]           verbose: Produced execution block slot=7047269, executionPayloadValue=156467575957239126, root=0xa6bee66c91651e7be743981cae239354a0e4bca065144930c1177ea4c800d84a |  
  |   | 2023-11-27 09:53:49.217 | time="2023-11-27T08:53:49.217Z" level=warning msg="error making request to relay" error="Get \"https://bloxroute.max-profit.builder.goerli.blxrbdn.com/eth/v1/builder/header/7047269/0xf3dace8484b2c93d33849365234cc44bb670425d0fe5c41490775d1ed7057ef4/0x94505e569c31c18d69529125800018602122a016bee9dfaae27fd4e4400a3cbf0c7852cd4ed5e72620f1c9caf7154940\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)" method=getHeader parentHash=0xf3dace8484b2c93d33849365234cc44bb670425d0fe5c41490775d1ed7057ef4 pubkey=0x94505e569c31c18d69529125800018602122a016bee9dfaae27fd4e4400a3cbf0c7852cd4ed5e72620f1c9caf7154940 slot=7047269 slotUID=6fcafe71-a254-438f-8768-d408ec3dcdc7 ua=Lodestar/v1.12.0/9d68181 url="https://bloxroute.max-profit.builder.goerli.blxrbdn.com/eth/v1/builder/header/7047269/0xf3dace8484b2c93d33849365234cc44bb670425d0fe5c41490775d1ed7057ef4/0x94505e569c31c18d69529125800018602122a016bee9dfaae27fd4e4400a3cbf0c7852cd4ed5e72620f1c9caf7154940" version=v1.6 |  
  |   | 2023-11-27 09:53:49.217 | time="2023-11-27T08:53:49.217Z" level=info msg="best bid" blockHash=0x2abd12c643673bc74050a3ae16aec682c778fbbee10ca4c17db1ec1bf66490d8 blockNumber=10115209 method=getHeader parentHash=0xf3dace8484b2c93d33849365234cc44bb670425d0fe5c41490775d1ed7057ef4 pubkey=0x94505e569c31c18d69529125800018602122a016bee9dfaae27fd4e4400a3cbf0c7852cd4ed5e72620f1c9caf7154940 relays="https://0xafa4c6985aa049fb79dd37010438cfebeb0f2bd42b115b89dd678dab0670c1de38da0c4e9138c9290a398ecd9a0b3110@builder-relay-goerli.flashbots.net" slot=7047269 slotUID=6fcafe71-a254-438f-8768-d408ec3dcdc7 txRoot=0x6244882ad6cb60a6b1c7089935a4d15de888617bc04f5b8fe28940ae5ae3f682 ua=Lodestar/v1.12.0/9d68181 value=0.204610867596747902 version=v1.6 |  
  |   | 2023-11-27 09:53:49.219 | Nov-27 08:53:49.219[chain]         verbose: Fetched execution payload header from builder slot=7047269, executionPayloadValue=204610867596747902, prepType=blinded, fetchedTime=1.2190001010894775 |  
  |   | 2023-11-27 09:53:49.219 | Nov-27 08:53:49.219[chain]         verbose: Produced beacon block body fork=capella, blockType=Blinded, slot=7047269, attestations=128, deposits=0, voluntaryExits=0, attesterSlashings=0, proposerSlashings=0, feeRecipientType=cached, feeRecipient=0x94750381be1aba0504c666ee1db118f68f0780d4, blsToExecutionChanges=0, executionPayloadValue=204610867596747902 |  
  |   | 2023-11-27 09:53:49.326 | Nov-27 08:53:49.325[api]           verbose: Produced blinded block slot=7047269, executionPayloadValue=204610867596747902, root=0x90a215c7665d6fcfee96347164c7372ce6eb88e132fc0cf894c19768157c035a
  |   |  2023-11-27 09:53:49.334 | Nov-27 08:53:49.333[]                debug: Produced block slot=7047269, validator=0x94505e569c31c18d69529125800018602122a016bee9dfaae27fd4e4400a3cbf0c7852cd4ed5e72620f1c9caf7154940, source=builder, executionPayloadValue=0.20461 ETH, strictFeeRecipientCheck=false, builderSelection=maxprofit, api=produceBlockV3

- 48.001 Clock Slot (0)
- 48.002 Producing block (1)
- 48.056 Produce Block V3 (54)
	  - 48.058 Producing beacon block blinded (2)
	  	  - 49.219 Fetched execution payload (161)
	  	  - 49.219 Produced beacon block body (0)
	  	  - 49.325 Produced blinded block (6)
	  - 48.161 Producing beacon block full (105)
	  	  - 48.272 Fetched execution payload from engine (111)
	  	  - 48.272 Produced beacon block body full (0)
	  	  - 48.362 Produced execution block (90)
- 49.333 Produced block (1028)

From this analysis I had understanding that the more time consumed is because of the API calls order between builder vs execution rather the block building time. As you in above both cases block building process is taking < 100ms but block production time overall took more than 1s.