[Eth Sepolia] Lighthouse syncs slowly and intermittently

[qnduncan]

Description

Lighthouse syncs slowly and intermittently for Eth Sepolia network.

Version

sigp/lighthouse:v8.0.1
sigp/lighthouse:v8.1.1

Present Behaviour

Mar 02 08:46:42.000 INFO  Syncing                                       peers: "8", distance: "994 slots (3 hrs 18 mins)", est_time: "--"
Mar 02 08:46:54.000 INFO  Syncing                                       peers: "18", distance: "995 slots (3 hrs 19 mins)", est_time: "--"
Mar 02 08:47:06.001 INFO  Syncing                                       peers: "22", distance: "964 slots (3 hrs 12 mins)", speed: "0.67 slots/sec", est_time: "24 mins"
Mar 02 08:47:18.001 INFO  Syncing                                       peers: "28", distance: "965 slots (3 hrs 13 mins)", speed: "0.67 slots/sec", est_time: "24 mins"
Mar 02 08:47:30.001 INFO  Syncing                                       peers: "29", distance: "966 slots (3 hrs 13 mins)", speed: "0.67 slots/sec", est_time: "24 mins"
Mar 02 08:47:42.001 INFO  Syncing                                       peers: "37", distance: "967 slots (3 hrs 13 mins)", speed: "0.67 slots/sec", est_time: "24 mins"
Mar 02 08:47:54.001 INFO  Syncing                                       peers: "42", distance: "968 slots (3 hrs 13 mins)", est_time: "--"
Mar 02 08:48:06.001 INFO  Syncing                                       peers: "45", distance: "969 slots (3 hrs 13 mins)", est_time: "--"
Mar 02 08:48:18.001 INFO  Syncing                                       peers: "46", distance: "970 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:48:30.001 INFO  Syncing                                       peers: "49", distance: "971 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:48:42.004 INFO  Syncing                                       peers: "54", distance: "972 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:48:54.001 INFO  Syncing                                       peers: "55", distance: "973 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:49:06.001 INFO  Syncing                                       peers: "58", distance: "974 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:49:18.001 INFO  Syncing                                       peers: "62", distance: "975 slots (3 hrs 15 mins)", est_time: "--"
Mar 02 08:49:30.001 INFO  Syncing                                       peers: "62", distance: "976 slots (3 hrs 15 mins)", est_time: "--"
Mar 02 08:49:42.001 INFO  Syncing                                       peers: "61", distance: "977 slots (3 hrs 15 mins)", est_time: "--"
Mar 02 08:49:54.001 INFO  Syncing                                       peers: "63", distance: "978 slots (3 hrs 15 mins)", est_time: "--"
Mar 02 08:50:06.001 INFO  Syncing                                       peers: "71", distance: "979 slots (3 hrs 15 mins)", est_time: "--"
Mar 02 08:50:18.000 INFO  Syncing                                       peers: "71", distance: "980 slots (3 hrs 16 mins)", est_time: "--"
Mar 02 08:50:30.000 INFO  Syncing                                       peers: "73", distance: "981 slots (3 hrs 16 mins)", est_time: "--"
Mar 02 08:50:42.001 INFO  Syncing                                       peers: "77", distance: "982 slots (3 hrs 16 mins)", est_time: "--"
Mar 02 08:50:54.001 INFO  Syncing                                       peers: "78", distance: "983 slots (3 hrs 16 mins)", est_time: "--"
Mar 02 08:51:06.001 INFO  Syncing                                       peers: "80", distance: "984 slots (3 hrs 16 mins)", est_time: "--"
Mar 02 08:51:18.001 INFO  Syncing                                       peers: "81", distance: "985 slots (3 hrs 17 mins)", est_time: "--"
Mar 02 08:51:30.001 INFO  Syncing                                       peers: "83", distance: "954 slots (3 hrs 10 mins)", speed: "0.67 slots/sec", est_time: "23 mins"
Mar 02 08:51:42.000 INFO  Syncing                                       peers: "84", distance: "955 slots (3 hrs 11 mins)", speed: "0.67 slots/sec", est_time: "23 mins"
Mar 02 08:51:43.134 INFO  Execution engine online                     
Mar 02 08:51:43.134 INFO  Issuing forkchoiceUpdated                     forkchoice_state: ForkchoiceState { head_block_hash: 0x778e0db350c931a91520450cc2d45856a182e5565130541893100bd65a46abc8, safe_block_hash: 0x9b27171c3446d0451e36e976c96d339dc6073c729db6c5c9fdf53c13be9e1cb0, finalized_block_hash: 0xb6a72fa537ff87a7dcb8fe850a08bd69fd9aab3bd14301b3c0e35e64e48f8cc0 }
Mar 02 08:51:54.001 INFO  Syncing                                       peers: "87", distance: "956 slots (3 hrs 11 mins)", speed: "0.67 slots/sec", est_time: "23 mins"
Mar 02 08:52:06.001 INFO  Syncing                                       peers: "90", distance: "957 slots (3 hrs 11 mins)", speed: "0.67 slots/sec", est_time: "23 mins"
Mar 02 08:52:18.000 INFO  Syncing                                       peers: "95", distance: "958 slots (3 hrs 11 mins)", est_time: "--"
Mar 02 08:52:30.001 INFO  Syncing                                       peers: "96", distance: "959 slots (3 hrs 11 mins)", est_time: "--"
Mar 02 08:52:42.001 INFO  Syncing                                       peers: "99", distance: "960 slots (3 hrs 12 mins)", est_time: "--"
Mar 02 08:52:54.001 INFO  Syncing                                       peers: "102", distance: "961 slots (3 hrs 12 mins)", est_time: "--"
Mar 02 08:53:06.000 INFO  Syncing                                       peers: "104", distance: "962 slots (3 hrs 12 mins)", est_time: "--"
Mar 02 08:53:18.001 INFO  Syncing                                       peers: "105", distance: "963 slots (3 hrs 12 mins)", est_time: "--"
Mar 02 08:53:30.002 INFO  Syncing                                       peers: "105", distance: "964 slots (3 hrs 12 mins)", est_time: "--"
Mar 02 08:53:42.000 INFO  Syncing                                       peers: "110", distance: "965 slots (3 hrs 13 mins)", est_time: "--"
Mar 02 08:53:54.001 INFO  Syncing                                       peers: "112", distance: "966 slots (3 hrs 13 mins)", est_time: "--"
Mar 02 08:54:06.000 INFO  Syncing                                       peers: "114", distance: "967 slots (3 hrs 13 mins)", est_time: "--"
Mar 02 08:54:18.001 INFO  Syncing                                       peers: "117", distance: "968 slots (3 hrs 13 mins)", est_time: "--"
Mar 02 08:54:30.001 INFO  Syncing                                       peers: "121", distance: "969 slots (3 hrs 13 mins)", est_time: "--"
Mar 02 08:54:42.001 INFO  Syncing                                       peers: "127", distance: "970 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:54:54.001 INFO  Syncing                                       peers: "130", distance: "971 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:55:06.001 INFO  Syncing                                       peers: "131", distance: "972 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:55:18.001 INFO  Syncing                                       peers: "132", distance: "973 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:55:30.001 INFO  Syncing                                       peers: "135", distance: "974 slots (3 hrs 14 mins)", est_time: "--"
Mar 02 08:55:42.001 INFO  Syncing                                       peers: "140", distance: "975 slots (3 hrs 15 mins)", est_time: "--"
Mar 02 08:55:54.000 INFO  Syncing                                       peers: "140", distance: "976 slots (3 hrs 15 mins)", est_time: "--"

And in geth logs, we constantly see below from time to time

WARN [03-02|08:48:57.330] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!

Expected Behaviour

The lighthouse should sync steadily

Steps to resolve

NA

lighthouse binary options used

      - "lighthouse"
      - "beacon_node"
      - "--network=sepolia"
      - "--execution-endpoint=http://localhost:8551"
      - "--execution-jwt=/share/jwtsecret"
      - "--supernode"
      - "--historic-state-cache-size=4"
      - "--reconstruct-historic-states"
      - "--checkpoint-sync-url=https://sepolia.beaconstate.info"
      - "--prune-blobs=false"
      - "--enr-address=<ip>"
      - "--port=9000"
      - "--http"
      - "--http-address=0.0.0.0"
      - "--http-port=5052"
      - "--http-allow-origin=*"
      - "--metrics"
      - "--metrics-address=0.0.0.0"
      - "--metrics-port=5050"
      - "--metrics-allow-origin=*"

[chong-he]

Any other logs that you see on Geth?

Can you share the hardware that you are on? CPU, RAM and SSD model. And would be good to know the internet speed and bandwidth (is it limited etc)

[qnduncan]

Machine spec: Oracle Cloude Infrastructure VM.Standard.E4.Flex
ocpu: 6
memory: 128G
storage: Oracle Block Volume, 25,000 IOPS, 480 MB/s
network bandwidth: 6 gbps

We've checked that the cpu utilization, memory usage, and disk utilization are under 30%.

[qnduncan]

Attaching more logs of geth from another lagging node. No errors but just some sync messages followed with WARNs that Beacon client online, but no consensus updates received in a while.

WARN [03-03|04:36:33.974] Retrieved pivot header from local        number=10,372,385 hash=5359ba..7cbf84 latest=10,372,449 oldest=10,372,419
INFO [03-03|04:36:36.201] Imported new chain segment               number=10,372,449 hash=b6b83d..8eacb2 blocks=31 txs=2682 mgas=310.271 elapsed=1.804s    mgasps=171.952 age=2h40m     triediffs=83.69MiB  triedirty=36.49MiB
WARN [03-03|04:38:33.403] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!
WARN [03-03|04:41:15.129] Fetching the unknown forkchoice head from network hash=0e81d4..d6f948
INFO [03-03|04:41:15.219] Forkchoice requested sync to new head    number=10,372,480 hash=0e81d4..d6f948 finalized=unknown
INFO [03-03|04:41:15.219] Restarting sync cycle                    reason="chain gapped, head: 10372449, newHead: 10372480"
INFO [03-03|04:41:15.236] Syncing beacon headers                   downloaded=6265 left=0 eta=0s
WARN [03-03|04:41:15.247] Retrieved pivot header from local        number=10,372,416 hash=ea0d67..d97223 latest=10,372,480 oldest=10,372,450
INFO [03-03|04:41:17.866] Imported new chain segment               number=10,372,480 hash=0e81d4..d6f948 blocks=31 txs=2876 mgas=337.141 elapsed=2.182s    mgasps=154.485 age=2h38m17s  triediffs=84.59MiB  triedirty=39.62MiB
WARN [03-03|04:43:18.437] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!
WARN [03-03|04:48:18.474] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!
WARN [03-03|04:50:16.194] Fetching the unknown forkchoice head from network hash=4c2d54..0c14dd
INFO [03-03|04:50:16.279] Forkchoice requested sync to new head    number=10,372,512 hash=4c2d54..0c14dd finalized=unknown
INFO [03-03|04:50:16.279] Restarting sync cycle                    reason="chain gapped, head: 10372480, newHead: 10372512"
INFO [03-03|04:50:16.296] Syncing beacon headers                   downloaded=6296 left=0 eta=0s
WARN [03-03|04:50:16.307] Retrieved pivot header from local        number=10,372,448 hash=6c7065..2b9ffd latest=10,372,512 oldest=10,372,481
INFO [03-03|04:50:18.988] Imported new chain segment               number=10,372,512 hash=4c2d54..0c14dd blocks=32 txs=2973 mgas=346.608 elapsed=2.156s    mgasps=160.696 age=2h40m54s  triediffs=85.75MiB  triedirty=42.68MiB
WARN [03-03|04:52:18.501] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!
WARN [03-03|04:55:01.283] Fetching the unknown forkchoice head from network hash=336407..194db5
INFO [03-03|04:55:01.404] Forkchoice requested sync to new head    number=10,372,544 hash=336407..194db5 finalized=unknown
INFO [03-03|04:55:01.404] Restarting sync cycle                    reason="chain gapped, head: 10372512, newHead: 10372544"
INFO [03-03|04:55:01.415] Syncing beacon headers                   downloaded=6327 left=0 eta=0s
WARN [03-03|04:55:01.424] Retrieved pivot header from local        number=10,372,480 hash=0e81d4..d6f948 latest=10,372,544 oldest=10,372,513
INFO [03-03|04:55:03.792] Imported new chain segment               number=10,372,544 hash=336407..194db5 blocks=32 txs=3069 mgas=388.397 elapsed=1.931s    mgasps=201.094 age=2h39m15s  triediffs=86.17MiB  triedirty=46.43MiB
WARN [03-03|04:57:18.533] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!
WARN [03-03|04:59:14.134] Fetching the unknown forkchoice head from network hash=1c1d57..6f3f68
INFO [03-03|04:59:14.159] Forkchoice requested sync to new head    number=10,372,575 hash=1c1d57..6f3f68 finalized=unknown
INFO [03-03|04:59:14.159] Restarting sync cycle                    reason="chain gapped, head: 10372544, newHead: 10372575"
INFO [03-03|04:59:14.170] Syncing beacon headers                   downloaded=6357 left=0 eta=0s
WARN [03-03|04:59:14.182] Retrieved pivot header from local        number=10,372,511 hash=cb619d..af3047 latest=10,372,575 oldest=10,372,545
INFO [03-03|04:59:16.849] Imported new chain segment               number=10,372,575 hash=1c1d57..6f3f68 blocks=31 txs=3007 mgas=373.556 elapsed=2.224s    mgasps=167.898 age=2h37m4s   triediffs=88.03MiB  triedirty=49.16MiB
WARN [03-03|05:01:18.555] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!
WARN [03-03|05:04:34.982] Fetching the unknown forkchoice head from network hash=5aca00..809cae
INFO [03-03|05:04:34.989] Forkchoice requested sync to new head    number=10,372,607 hash=5aca00..809cae finalized=unknown
INFO [03-03|05:04:34.989] Restarting sync cycle                    reason="chain gapped, head: 10372575, newHead: 10372607"
INFO [03-03|05:04:35.002] Syncing beacon headers                   downloaded=6388 left=0 eta=0s
WARN [03-03|05:04:35.013] Retrieved pivot header from local        number=10,372,543 hash=778d9f..1cb855 latest=10,372,607 oldest=10,372,576
INFO [03-03|05:04:37.445] Imported new chain segment               number=10,372,605 hash=99cfd5..35ca78 blocks=30 txs=2919 mgas=427.677 elapsed=1.984s    mgasps=215.538 age=2h36m25s  triediffs=89.01MiB  triedirty=51.88MiB
INFO [03-03|05:04:37.567] Imported new chain segment               number=10,372,607 hash=5aca00..809cae blocks=2  txs=182  mgas=30.415  elapsed=121.840ms mgasps=249.630 age=2h36m1s   triediffs=88.55MiB  triedirty=52.13MiB
WARN [03-03|05:06:38.585] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!
WARN [03-03|05:09:47.375] Fetching the unknown forkchoice head from network hash=5e8770..01ffd9
INFO [03-03|05:09:47.496] Forkchoice requested sync to new head    number=10,372,638 hash=5e8770..01ffd9 finalized=unknown
INFO [03-03|05:09:47.496] Restarting sync cycle                    reason="chain gapped, head: 10372607, newHead: 10372638"
INFO [03-03|05:09:47.516] Syncing beacon headers                   downloaded=6418 left=0 eta=0s
WARN [03-03|05:09:47.526] Retrieved pivot header from local        number=10,372,574 hash=513eda..0961f6 latest=10,372,638 oldest=10,372,608
INFO [03-03|05:09:49.872] Imported new chain segment               number=10,372,636 hash=731bc2..b4f76d blocks=29 txs=3486 mgas=433.321 elapsed=1.904s    mgasps=227.468 age=2h35m25s  triediffs=90.21MiB  triedirty=55.08MiB
INFO [03-03|05:09:50.012] Imported new chain segment               number=10,372,638 hash=5e8770..01ffd9 blocks=2  txs=433  mgas=40.504  elapsed=140.151ms mgasps=289.002 age=2h34m50s  triediffs=91.08MiB  triedirty=55.25MiB
WARN [03-03|05:11:48.617] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!

[chong-he]

Not familiar with the terms used by Oracle cloud, Oracle Block Volume or the OCPU.

But anyway, Geth has a consistent warning:
WARN [03-03|04:36:33.974] Retrieved pivot header from local number=10,372,385 hash=5359ba..7cbf84 latest=10,372,449 oldest=10,372,419

and it's also strange in terms of the timing of the logs - sometimes there is nothing for 1-2 minutes and it has happened at all time for the log you posted, for example:

INFO [03-03|04:55:03.792] Imported new chain segment               number=10,372,544 hash=336407..194db5 blocks=32 txs=3069 mgas=388.397 elapsed=1.931s    mgasps=201.094 age=2h39m15s  triediffs=86.17MiB  triedirty=46.43MiB
WARN [03-03|04:57:18.533] Beacon client online, but no consensus updates received in a while. Please fix your beacon client to follow the chain!
WARN [03-03|04:59:14.134] Fetching the unknown forkchoice head from network hash=1c1d57..6f3f68

Nothing happened between mnute-55 to minute-57 and also from 57 to 59. This is odd. I guess the EL and CL don't hear from each other, and then suddenly hear something, and it repeats

Do you see any other logs in the beacon node? Any warn or error log?

I recommend to restart both Geth and Lighthouse to see if things improve. If not, I suggest deleting Geth database and resync

I also suggest to remove this flag for now: "--supernode" to reduce resource usage

[qnduncan]

Thanks for the advices.

I guess the EL and CL don't hear from each other, and then suddenly hear something, and it repeats

The geth and lighthouse are on the same server. How would this happen? 🤔

Do you see any other logs in the beacon node? Any warn or error log?

Nothing stands out, pretty much same as we posted above.

I recommend to restart both Geth and Lighthouse to see if things improve. If not, I suggest deleting Geth database and resync

We've restarted both services several times, it didn't help. We'll see if resyncing geth helps.

I also suggest to remove this flag for now: "--supernode" to reduce resource usage

We've checked that the cpu utilization, memory usage, and disk utilization are under 30%. Resource usage seems less likely the cause?

[chong-he]

Thanks for the advices.

I guess the EL and CL don't hear from each other, and then suddenly hear something, and it repeats

The geth and lighthouse are on the same server. How would this happen? 🤔

Do you see any other logs in the beacon node? Any warn or error log?

Nothing stands out, pretty much same as we posted above.

I recommend to restart both Geth and Lighthouse to see if things improve. If not, I suggest deleting Geth database and resync

We've restarted both services several times, it didn't help. We'll see if resyncing geth helps.

I also suggest to remove this flag for now: "--supernode" to reduce resource usage

We've checked that the cpu utilization, memory usage, and disk utilization are under 30%. Resource usage seems less likely the cause?

Yeah try to resync Geth first to see if it helps.