lighthouse takes a long time to process the getHeader block request. As a result, a block miss

[hwhe]

Description

I used the lighthouse client, at 8917143 slot proposal block miss.

the the proposal a block links are as follows:
vc -> beacon -> mevBoost -> mevRelay

The time from mevBoost to mevRelay is fixed at 950 ms. There are no issues that are outside the scope of this discussion。
The time from beacon to mevBoost is mostly within 100 ms. However, at slot 8917143, the time from beacon to mevBoost is > 1000ms，very long. As a result, the block is missed.

beacon logs: desc order
Apr 22 23:49:13.331 INFO New block received root: 0x07efc39152e174aedcc31fb2e09b2e533bcc7cb50092c5fa71afd356a01836b2, slot: 8917144 Apr 22 23:49:07.356 WARN Error processing HTTP API request method: POST, path: /eth/v2/beacon/blinded_blocks, status: 500 Internal Server Error, elapsed: 4.881772105s Apr 22 23:49:07.356 WARN Builder failed to reveal payload parent_hash: "0xc0a1…213d", block_root: 0xff12c264f143d7b3d1ee55c2faa0945630cb4c0516e1faa9e36e11e1dd5b1654, relay_response_ms: 4820, error: Builder(ServerMessage(ErrorMessage { code: 502, message: "no successful relay response", stacktraces: [] })), info: this is common behaviour for some builders and may not indicate an issue, service: exec Apr 22 23:49:05.000 INFO Synced slot: 8917143, block: … empty, epoch: 278660, finalized_epoch: 278658, finalized_root: 0x5e15…3464, exec_hash: 0xc0a1…213d (verified), peers: 109, service: slot_notifier Apr 22 23:49:02.534 ERRO Block broadcast was delayed root: 0xff12c264f143d7b3d1ee55c2faa0945630cb4c0516e1faa9e36e11e1dd5b1654, slot: 8917143, delay_ms: 3534, provenance: builder, msg: system may be overloaded, block may be orphaned Apr 22 23:49:01.771 INFO Relay block is more profitable than local block, builder_boost_factor: None, boosted_relay_value: 31297288413166382, relay_value: 31297288413166382, local_block_value: 0, service: exec Apr 22 23:49:01.769 INFO Received local and builder payloads parent_hash: 0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d, local_block_hash: 0x3832182dd35020d420942ab2f3abf5f05c16484bb5c53293c2cb4818d05558b5, relay_block_hash: 0x0967d5cfa5c2e659ecf4db382b665b333d7285a6ceceb1c51badd55b0b12f80c, service: exec Apr 22 23:49:01.769 INFO Requested blinded execution payload parent_hash: 0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d, local_response_ms: 15, local_fee_recipient: 0x61ad82d4466437d4cc250a0ceffbcbd7e07b8f96, relay_response_ms: 962, relay_fee_recipient: 0x95222290dd7278aa3ddd389cc1e1d165cc4bafe5, service: exec Apr 22 23:49:00.806 INFO Requesting blinded header from connected builder, parent_hash: 0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d, pubkey: 0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245, slot: Slot(8917143), service: exec Apr 22 23:49:00.775 WARN Block production cache miss slot: 8917143, message: falling back to snapshot cache clone, service: beacon Apr 22 23:49:00.084 WARN Delayed proposer preparation validator: 1213669, prepare_slot: 8917143, service: beacon Apr 22 23:49:00.084 INFO Prepared beacon proposer parent_root: 0x8fdaa1530dcb9a32f230ad2ab4b3a9c491293d94047ea9ea9f19646b8a969365, validator: 1213669, prepare_slot: 8917143, service: beacon Apr 22 23:48:59.904 WARN Timed out waiting for fork choice before proposal, message: this block may be orphaned, service: beacon Apr 22 23:48:58.672 WARN Beacon chain re-org reorg_distance: 1, new_slot: 8917142, new_head: 0x8fdaa1530dcb9a32f230ad2ab4b3a9c491293d94047ea9ea9f19646b8a969365, previous_slot: 8917141, previous_head: 0x137925427032912e95b135d46311d814a20cfb8c55e3004fc35e83fb4ba7835f, service: beacon Apr 22 23:48:55.003 INFO Prepared beacon proposer parent_root: 0x137925427032912e95b135d46311d814a20cfb8c55e3004fc35e83fb4ba7835f, validator: 1213669, prepare_slot: 8917143, service: beacon

mev logs: desc order
time="2024-04-23T07:49:02.56+08:00" level=info msg="submitBlindedBlock request start - 3559 milliseconds into slot 8917143" blockHash=0x0d2708aaeb5421fda0b220a7b0bf359212fd524c9cb0dd50b710a890025df12f genesisTime=1606824023 method=getPayload msIntoSlot=3559 parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d slot=8917143 slotTimeSec=12 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c ua=Lighthouse/v5.1.3-3058b96 version=1.7 time="2024-04-23T07:49:02.536+08:00" level=debug msg="getPayload request starts" method=getPayload version=1.7 time="2024-04-23T07:49:01.763+08:00" level=info msg="http: GET /eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 200" duration=0.953929 method=GET path=/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 status=200 version=1.7 time="2024-04-23T07:49:01.759+08:00" level=info msg="best bid" blockHash=0x0967d5cfa5c2e659ecf4db382b665b333d7285a6ceceb1c51badd55b0b12f80c blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 relays="https://0xa1559ace749633b997cb3fdacffb890aeebdb0f5a3b6aaa7eeeaf1a38af0a8fe88b9e4b1f61f236d2e64d95733327a62@relay.ultrasound.money" slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x8108264cee309fdc0b94bbf55b65eddb0243f98565afcc0fc91757fefc89c974 ua=Lighthouse/v5.1.3-3058b96 value=0.031297288413166382 version=1.7 time="2024-04-23T07:49:01.759+08:00" level=debug msg="new best bid" blockHash=0x0967d5cfa5c2e659ecf4db382b665b333d7285a6ceceb1c51badd55b0b12f80c blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x8108264cee309fdc0b94bbf55b65eddb0243f98565afcc0fc91757fefc89c974 ua=Lighthouse/v5.1.3-3058b96 url="https://relay.ultrasound.money/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.031297288413166382 version=1.7 time="2024-04-23T07:49:01.759+08:00" level=debug msg="bid received" blockHash=0x0967d5cfa5c2e659ecf4db382b665b333d7285a6ceceb1c51badd55b0b12f80c blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x8108264cee309fdc0b94bbf55b65eddb0243f98565afcc0fc91757fefc89c974 ua=Lighthouse/v5.1.3-3058b96 url="https://relay.ultrasound.money/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.031297288413166382 version=1.7 time="2024-04-23T07:49:01.758+08:00" level=debug msg="bid received" blockHash=0x4014220582fb62fa69f929e229b0d1fa10a732678576d19dcfbb34500693d4d9 blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x2062a061440a259ac97dc2046162d421174352396d19dda41945b7bf3a32214a ua=Lighthouse/v5.1.3-3058b96 url="https://aestus.live/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.026911372340092590 version=1.7 time="2024-04-23T07:49:01.508+08:00" level=debug msg="bid received" blockHash=0xa9410a77d6dce380d7a07fab5dedf2a1ae43f27e956445c0a4bec2083aedb85b blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x74ca235a69afb606e8d9a695b52a59fa2ec2bf0759a9bbb4cd29a1fc38b5f3d4 ua=Lighthouse/v5.1.3-3058b96 url="https://mainnet-relay.securerpc.com/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.015176104806663416 version=1.7 time="2024-04-23T07:49:01.413+08:00" level=debug msg="bid received" blockHash=0xf0a1435b448913ff86dbb2b741aeb96f3885de61176b8e4e3c1421ce63c62578 blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0xf075eeee91f2e2c489add5c26d9b780a0e01d47cdd0f84b5f18eb2474c850ac3 ua=Lighthouse/v5.1.3-3058b96 url="https://bloxroute.max-profit.blxrbdn.com/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.030194044648933725 version=1.7 time="2024-04-23T07:49:01.413+08:00" level=debug msg="new best bid" blockHash=0xab183d38dac274aeff9f6dae5ee68af8c0aa656d696a367e3962178d651bb7e8 blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x5112f53c0222164aa7253a3e6129ba01183de3c56fcd8bf2beea5a7b804e3927 ua=Lighthouse/v5.1.3-3058b96 url="https://agnostic-relay.net/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.030721544783743474 version=1.7 time="2024-04-23T07:49:01.413+08:00" level=debug msg="bid received" blockHash=0xab183d38dac274aeff9f6dae5ee68af8c0aa656d696a367e3962178d651bb7e8 blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x5112f53c0222164aa7253a3e6129ba01183de3c56fcd8bf2beea5a7b804e3927 ua=Lighthouse/v5.1.3-3058b96 url="https://agnostic-relay.net/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.030721544783743474 version=1.7 time="2024-04-23T07:49:01.343+08:00" level=debug msg="new best bid" blockHash=0x3edf5b38b1844038624e97f457ba9b693716878c80f83ce4ba856899e6f7177d blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x6b26f7f7792e1559970332b010e40b9eea2357491d733011e5b38391772848d4 ua=Lighthouse/v5.1.3-3058b96 url="https://boost-relay.flashbots.net/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.030044179983816027 version=1.7 time="2024-04-23T07:49:01.343+08:00" level=debug msg="bid received" blockHash=0x3edf5b38b1844038624e97f457ba9b693716878c80f83ce4ba856899e6f7177d blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x6b26f7f7792e1559970332b010e40b9eea2357491d733011e5b38391772848d4 ua=Lighthouse/v5.1.3-3058b96 url="https://boost-relay.flashbots.net/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.030044179983816027 version=1.7 time="2024-04-23T07:49:01.226+08:00" level=debug msg="new best bid" blockHash=0xc9cb6b7946165916ef3d625b8c56d0982ea78f0e373647268f19bcacc98f847f blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x42158b9f0fe7afc8e9566c8ef48db83f08a11daf77c49c6a29455a5ccdefc31f ua=Lighthouse/v5.1.3-3058b96 url="https://bloxroute.regulated.blxrbdn.com/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.029988089235422258 version=1.7 time="2024-04-23T07:49:01.225+08:00" level=debug msg="bid received" blockHash=0xc9cb6b7946165916ef3d625b8c56d0982ea78f0e373647268f19bcacc98f847f blockNumber=19714318 method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c txRoot=0x42158b9f0fe7afc8e9566c8ef48db83f08a11daf77c49c6a29455a5ccdefc31f ua=Lighthouse/v5.1.3-3058b96 url="https://bloxroute.regulated.blxrbdn.com/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" value=0.029988089235422258 version=1.7 time="2024-04-23T07:49:01.162+08:00" level=debug msg="no-content response" method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c ua=Lighthouse/v5.1.3-3058b96 url="https://relay.wenmerge.com/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" version=1.7 time="2024-04-23T07:49:01.045+08:00" level=debug msg="no-content response" method=getHeader parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c ua=Lighthouse/v5.1.3-3058b96 url="https://relay.edennetwork.io/eth/v1/builder/header/8917143/0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d/0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245" version=1.7 time="2024-04-23T07:49:00.814+08:00" level=info msg="getHeader request start - 1813 milliseconds into slot 8917143" genesisTime=1606824023 method=getHeader msIntoSlot=1813 parentHash=0xc0a11de7151b2d5bcc86778e09894ffb344390ee65c2066f56e964799e1d213d pubkey=0xb3bd5acf8690342adf8b8441710aad7132a714433871a7a92a478dbd5fc6aabe231213c03d8b81a511695c9c32fea245 slot=8917143 slotTimeSec=12 slotUID=f5046ca2-eae1-45e6-8e2e-1d9871a1053c ua=Lighthouse/v5.1.3-3058b96 version=1.7
In the log, we can see time sequence

    beacon recv from client: 48:59.648 
    beacon send to mev: 49:00.806
    beacon recv from mev: 49:01.769

the time from beacon to mevBoost cost 1200ms， very long. and there's some fork timeout error arround.
pub const DEFAULT_FORK_CHOICE_BEFORE_PROPOSAL_TIMEOUT: u64 = 250;

Please help me confirm why lighthouse takes so long to process a getHeader block request, what is the specific mechanism of lighthouse, and how to avoid this problem.

Version

Lighthouse V5.1.3

Present Behaviour

the time from beacon to mevBoost within 100 ms in most scenarios

Expected Behaviour

the time from beacon to mevBoost within 100 ms in most scenarios

Steps to resolve

tell me

[jmcph4]

tell me

This got me.

Maybe use block code for logs instead of inline too.

[michaelsproul]

Here are some notes I took digging into this.

Block at slot 8917141 was published late.

Block at slot 8917142 reorged it successfully.

Your node did not reorg to 8917142 immediately, meaning that it did not receive and process this block on time like the majority of the network. I also found 3 of our Lighthouse nodes that took a long time to process this block and did not reorg to it immediately either as a result.

Your node did eventually reorg to 8917142, but only 328ms before the start of slot 8917143 once attestations from slot 8917142 were eligible for counting.

Apr 22 23:48:58.672 WARN Beacon chain re-org reorg_distance: 1, new_slot: 8917142, new_head: 0x8fdaa1530dcb9a32f230ad2ab4b3a9c491293d94047ea9ea9f19646b8a969365, previous_slot: 8917141, previous_head: 0x137925427032912e95b135d46311d814a20cfb8c55e3004fc35e83fb4ba7835f, service: beacon

This is what caused the warnings:

• WARN Timed out waiting for fork choice before proposal
• WARN Block production cache miss slot: 8917143, message: falling back to snapshot cache clone

The reason for the fork choice timeout could be:

• In case of a reorg, Lighthouse writes some data to disk here:

  lighthouse/beacon_node/beacon_chain/src/canonical_head.rs

  Lines 900 to 903 in 3058b96

  	if is_epoch_transition || reorg_distance.is_some() {
  	self.persist_head_and_fork_choice()?;
  	self.op_pool.prune_attestations(self.epoch()?);
  	}

• In case of finalization (which can happen >2/3 of the way into the epoch, e.g. at slot 22/32),
  Lighthouse loads some data from disk and then does some database cleanup in the background:
  

  lighthouse/beacon_node/beacon_chain/src/canonical_head.rs

  Line 771 in 3058b96

  self.after_finalization(&new_cached_head, new_view, finalized_proto_block)

These could be new avenues for optimisation! We should probably ensure all that I/O gets done in the background
and does not block up the completion of fork choice. This could explain why Lighthouse is often reorged at slot 22 in the epoch according to https://reorg.pics

Having fork choice time out means we waste 250ms waiting, the rest is explained by the block production cache miss.

The block production cache is designed to save ~500ms, which is the time it takes to clone the parent state from the snapshot cache. Because the reorg was so last-minute, the clone into the block production cache did not happen ahead of time. The warning is letting us know that Lighthouse is going to spend an extra 500ms cloning from the snapshot cache due to the cache miss.

Some of these issues will be resolved by tree-states, which we are close to merging here:

• In-memory tree states #5533

Tree states helps because:

• The snapshot cache is gone in favour of a larger state cache which is quick to clone from. No more
  waiting 500ms to clone the parent state.
• The state cache accelerates fork choice and after_finalization as well, because they can load
  states from memory without having to do I/O. However, as I mentioned above, even with tree-states
  there might be some more optimising to do to avoid I/O writes on the fork choice code path.

If you are able to share debug logs via DM on Discord, that would help us optimise. You can find
debug logs in your data directory under $datadir/beacon/logs. You can compress them to fit them
in a DM. My Discord username is @sproul.

Debug logs will also help us diagnose whether your node has other issues with peering or block processing which caused it to process the block at slot 8917142 slowly.

As a temporary workaround you could reduce the mev-boost timeout so that Lighthouse has a better chance of proposing even when these ugly cache misses occur.

Longer term, you can update to the next version of Lighthouse (v5.2.0) once it's out, which will include at least the tree-states optimisation, and maybe more.

[hwhe]

beacon.zip

Here is the 1 hour log you can view。 very tks. @michaelsproul