besu
besu copied to clipboard
hyperledger
Besu Execution timeout/missed attestations
Description
Basic story, details to come - essentially Besu is constrained in execution time and is hitting CL timeouts that are causing it to miss attestations. This is our working theory, with supporting evidence. The team will update with more below.
Is this potentially the same issue as https://github.com/hyperledger/besu/issues/4398?
Is this potentially the same issue as https://github.com/hyperledger/besu/issues/4398?
I'm seeing timeouts and missed attestations without any JSON-RPC errors or exceptions, fwiw
Anecdotal evidence in Discord of users experiencing this issue with very high speced machines. Likely only tangentially tied to resource usage.
I'm missing attestations, but I see no indication of besu not having enough resources. I have dedicated hardware (6c ryzen, 32gb, 2tb 970 evo plus) that is fast enough
I filtered out the following topics from the debug log to see if I could make sense of the rest: GetPooledTransactionsFromPeerTask RlpxAgent AbstractPeerConnection EthPeer RecursivePeerRefreshState EthProtocolManager DeFramer HandshakeHandlerOutbound
Could this lead to Teku logging empty slots, as mentioned in https://github.com/ConsenSys/teku/issues/6205 ? By the way, also plenty of resources on my side: Ryzen 5, 56GB RAM, fast SSD
I'm not sure I'm in the right place, but I'll paste my logs. Things were executing normally until this happened:
Sep 15 17:01:25 node besu[1137]: java.lang.RuntimeException: java.lang.IllegalStateException: Expected to create code, but the code exists. Address=0x9b873b45b23965cc69b81b5596e4bf4dfe31b6ba
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:206)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.forwardWorldStateTo(MergeCoordinator.java:362)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.setNewHead(MergeCoordinator.java:351)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.updateForkChoice(MergeCoordinator.java:314)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.updateForkChoice(TransitionCoordinator.java:151)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineForkchoiceUpdated.syncResponse(EngineForkchoiceUpdated.java:127)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:67)
Sep 15 17:01:25 node besu[1137]: at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
Sep 15 17:01:25 node besu[1137]: at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
Sep 15 17:01:25 node besu[1137]: at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
Sep 15 17:01:25 node besu[1137]: at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
Sep 15 17:01:25 node besu[1137]: at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Sep 15 17:01:25 node besu[1137]: at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Sep 15 17:01:25 node besu[1137]: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Sep 15 17:01:25 node besu[1137]: at java.base/java.lang.Thread.run(Thread.java:829)
Sep 15 17:01:25 node besu[1137]: Caused by: java.lang.IllegalStateException: Expected to create code, but the code exists. Address=0x9b873b45b23965cc69b81b5596e4bf4dfe31b6ba
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollCodeChange(BonsaiWorldStateUpdater.java:558)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.lambda$rollForward$10(BonsaiWorldStateUpdater.java:428)
Sep 15 17:01:25 node besu[1137]: at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1764)
Sep 15 17:01:25 node besu[1137]: at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollForward(BonsaiWorldStateUpdater.java:426)
Sep 15 17:01:25 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:195)
Sep 15 17:01:25 node besu[1137]: ... 14 more
Sep 15 17:01:25 node besu[1137]: 2022-09-15 17:01:25.629-04:00 | vert.x-worker-thread-0 | ERROR | MergeCoordinator | Could not persist world for root hash 0x3eabaa18a03d0d5a6d7571809049f9e9da514a5008ff12b7058f4bed38a6d5a3 and block hash 0xdb633f99b11f4ce55fa3d4c8dedd4b9af3561b953caad54aae2079f2c8b6d0ae
Sep 15 17:01:35 node besu[1137]: java.lang.RuntimeException: java.lang.IllegalStateException: Expected to create code, but the code exists. Address=0x9b873b45b23965cc69b81b5596e4bf4dfe31b6ba
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:206)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:100)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:268)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:284)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:203)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:67)
Sep 15 17:01:35 node besu[1137]: at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
Sep 15 17:01:35 node besu[1137]: at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
Sep 15 17:01:35 node besu[1137]: at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
Sep 15 17:01:35 node besu[1137]: at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
Sep 15 17:01:35 node besu[1137]: at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Sep 15 17:01:35 node besu[1137]: at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Sep 15 17:01:35 node besu[1137]: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Sep 15 17:01:35 node besu[1137]: at java.base/java.lang.Thread.run(Thread.java:829)
Sep 15 17:01:35 node besu[1137]: Caused by: java.lang.IllegalStateException: Expected to create code, but the code exists. Address=0x9b873b45b23965cc69b81b5596e4bf4dfe31b6ba
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollCodeChange(BonsaiWorldStateUpdater.java:558)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.lambda$rollForward$10(BonsaiWorldStateUpdater.java:428)
Sep 15 17:01:35 node besu[1137]: at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1764)
Sep 15 17:01:35 node besu[1137]: at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
Sep 15 17:01:35 node besu[1137]: at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Sep 15 17:01:35 node besu[1137]: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Sep 15 17:01:35 node besu[1137]: at java.base/java.lang.Thread.run(Thread.java:829)
Sep 15 17:01:35 node besu[1137]: Caused by: java.lang.IllegalStateException: Expected to create code, but the code exists. Address=0x9b873b45b23965cc69b81b5596e4bf4dfe31b6ba
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollCodeChange(BonsaiWorldStateUpdater.java:558)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.lambda$rollForward$10(BonsaiWorldStateUpdater.java:428)
Sep 15 17:01:35 node besu[1137]: at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1764)
Sep 15 17:01:35 node besu[1137]: at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollForward(BonsaiWorldStateUpdater.java:426)
Sep 15 17:01:35 node besu[1137]: at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:195)
Sep 15 17:01:35 node besu[1137]: ... 14 more
Sep 15 17:01:35 node besu[1137]: 2022-09-15 17:01:35.790-04:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Unable to process block because parent world state 0x3eabaa18a03d0d5a6d7571809049f9e9da514a5008ff12b7058f4bed38a6d5a3 is not available. Block 15541630 (0xf0b07adfabb828be09e26d72fa0f58b98ed7c6637a1b1d8f3c350275ff7fe79a)
Sep 15 17:01:35 node besu[1137]: 2022-09-15 17:01:35.792-04:00 | vert.x-worker-thread-0 | WARN | EngineNewPayload | Invalid new payload: number: 15541630, hash: 0xf0b07adfabb828be09e26d72fa0f58b98ed7c6637a1b1d8f3c350275ff7fe79a, parentHash: 0xdb633f99b11f4ce55fa3d4c8dedd4b9af3561b953caad54aae2079f2c8b6d0ae, latestValidHash: 0xdb633f99b11f4ce55fa3d4c8dedd4b9af3561b953caad54aae2079f2c8b6d0ae, status: INVALID>
Sep 15 17:02:39 node besu[1137]: 2022-09-15 17:02:39.331-04:00 | vert.x-worker-thread-0 | INFO | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xdb633f99b11f4ce55fa3d4c8dedd4b9af3561b953caad54aae2079f2c8b6d0ae, finalized: 0x8057e61a7260bf7aad7c11ca230fd88bf125affe72d20c2831695b2953d44d1b, safeBlockHash: 0x4cde9e26fa06dce04d2019b46acb8f964b22d01502131f8fb3b49792b54b6d9b
Sep 15 17:03:51 node besu[1137]: 2022-09-15 17:03:51.331-04:00 | vert.x-worker-thread-0 | INFO | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xdb633f99b11f4ce55fa3d4c8dedd4b9af3561b953caad54aae2079f2c8b6d0ae, finalized: 0x8057e61a7260bf7aad7c11ca230fd88bf125affe72d20c2831695b2953d44d1b, safeBlockHash: 0x4cde9e26fa06dce04d2019b46acb8f964b22d01502131f8fb3b49792b54b6d9b
Sep 15 17:05:03 node besu[1137]: 2022-09-15 17:05:03.331-04:00 | vert.x-worker-thread-0 | INFO | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xdb633f99b11f4ce55fa3d4c8dedd4b9af3561b953caad54aae2079f2c8b6d0ae, finalized: 0x8057e61a7260bf7aad7c11ca230fd88bf125affe72d20c2831695b2953d44d1b, safeBlockHash: 0x4cde9e26fa06dce04d2019b46acb8f964b22d01502131f8fb3b49792b54b6d9b
Sep 15 17:06:15 node besu[1137]: 2022-09-15 17:06:15.330-04:00 | vert.x-worker-thread-0 | INFO | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xdb633f99b11f4ce55fa3d4c8dedd4b9af3561b953caad54aae2079f2c8b6d0ae, finalized: 0x8057e61a7260bf7aad7c11ca230fd88bf125affe72d20c2831695b2953d44d1b, safeBlockHash: 0x4cde9e26fa06dce04d2019b46acb8f964b22d01502131f8fb3b49792b54b6d9b
And then it just repeats that last line over an over again, never moving on to a new head block.
- Missed attestation on 4704652
- Logs from Besu debug, and Lighthouse BN/VC
validator.log besu_cut.log lighthouse.log
Thanks
I'm seeing timeouts and missed attestations without any JSON-RPC errors or exceptions, fwiw
Agree this is probably a different issue to #4398 although maybe some ppl have both issues.
Can you post your timeout logs please @ColinCampbell?
consensus_1 | 2022-09-15 23:16:19.210 ERROR - Execution Client is offline
consensus_1 | java.util.concurrent.TimeoutException: null
consensus_1 | at java.util.concurrent.CompletableFuture$Timeout.run(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.FutureTask.run(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
consensus_1 | at java.lang.Thread.run(Unknown Source) ~[?:?]
consensus_1 | 2022-09-15 23:16:19.215 ERROR - An error occurred while querying remote transition configuration
consensus_1 | java.util.concurrent.CompletionException: java.lang.IllegalArgumentException: Invalid remote response: TimeoutException
consensus_1 | at java.util.concurrent.CompletableFuture.encodeThrowable(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.CompletableFuture.completeThrowable(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.CompletableFuture$UniApply.tryFire(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.CompletableFuture.complete(Unknown Source) ~[?:?]
consensus_1 | at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:147) ~[teku-infrastructure-async-22.9.0.jar:22.9.0]
consensus_1 | at java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.CompletableFuture$Timeout.run(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.FutureTask.run(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
consensus_1 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
consensus_1 | at java.lang.Thread.run(Unknown Source) ~[?:?]
consensus_1 | Caused by: java.lang.IllegalArgumentException: Invalid remote response: TimeoutException
consensus_1 | at com.google.common.base.Preconditions.checkArgument(Preconditions.java:220) ~[guava-31.1-jre.jar:?]
consensus_1 | at tech.pegasys.teku.ethereum.executionlayer.ExecutionLayerManagerImpl.unwrapResponseOrThrow(ExecutionLayerManagerImpl.java:504) ~[teku-ethereum-executionlayer-22.9.0.jar:22.9.0]
consensus_1 | ... 15 more
consensus_1 | 2022-09-15 23:16:19.403 INFO - Execution Client is online
This is the output from Teku. The only thing interesting from the Besu logs at that time is.a valid fork-choice-update message, but I'm getting those once every so often without corresponding timeouts in the Teku logs:
execution_1 | 2022-09-15 23:15:48.910+00:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,542,290 / 123 tx / base fee 9.33 gwei / 13,102,269 (43.7%) gas / (0xf4d58d62ba7ee0a248896e1a28af8e0f91206350ee157dd007c992b3de28e2c5) in 0.670s. Peers: 26
execution_1 | 2022-09-15 23:16:17.136+00:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,542,291 / 318 tx / base fee 9.18 gwei / 26,293,665 (87.6%) gas / (0xcbd5f0a03e89f715a66022bdd325d0c09ec3f9ece2401b7a203c8a3b62a3fe79) in 2.364s. Peers: 26
execution_1 | 2022-09-15 23:16:19.028+00:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,542,291 / 326 tx / base fee 9.18 gwei / 28,321,681 (94.4%) gas / (0x5854c653f477be38720cf72266889b7f5d99fd6a3e98b809eafeb00f0335c614) in 1.882s. Peers: 26
execution_1 | 2022-09-15 23:16:19.402+00:00 | vert.x-worker-thread-0 | INFO | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xcbd5f0a03e89f715a66022bdd325d0c09ec3f9ece2401b7a203c8a3b62a3fe79, finalized: 0xd8f5936ccdd70dbd46a0f5e99ff9928380cab18fa18fb7aa39639f9b543504f1, safeBlockHash: 0x7ac6bcd743656d9d71e24b56047b7d3729140d5c464509f00a30eae31a2fe87f
execution_1 | 2022-09-15 23:16:24.721+00:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,542,292 / 116 tx / base fee 10.20 gwei / 8,523,982 (28.4%) gas / (0x8870df0929e5a0e602dc2dc45c8217e9304dd5fa108030857308ab30f3c70830) in 0.749s. Peers: 26
execution_1 | 2022-09-15 23:16:36.827+00:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,542,293 / 119 tx / base fee 9.65 gwei / 8,580,851 (28.6%) gas / (0x0c4e4ea98c755ca187504679aede927416b67056357e1e1a79780b6a5b5e902c) in 0.450s. Peers: 26
execution_1 | 2022-09-15 23:16:48.081+00:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,542,294 / 84 tx / base fee 9.13 gwei / 6,548,350 (21.8%) gas / (0x443525fe21cc41a454cf85c5c018330022a2dc77124775f3999423600a455c11) in 0.385s. Peers: 26
Edit: I suppose it could have something to do with Teku asking Besu for data while Besu is busy dealing with the event causing the EngineForkchoiceUpdated log?
For what's it worth, I've experienced this with Prysm+Besu combo. I've seen this problem both with and without the JSON-RPC error reported. Initially post merge with the instance still running from pre-merge, I've experienced this issue with no errors that I can remember. Upon restarting (post merge) besu and the machine it was operating on, I've started experiencing the same degradation in vote performance, this time with the JSON-RPC errors coming up constantly.
Linux reported loads never exceeded 1.0 Plenty of CPUs plenty of RAM.
Not sure if EngineForkchoiceUpdated is a log statement that's supposed to come or not, but in all cases I've gotten it consistently throughout.
For Prysm, the beacon chain's errors started with this for about the first hour after merge:
time="2022-09-15 08:38:28" level=error msg="Could not get reconstruct full bellatrix block from blinded body" error="could not fetch execution block with txs by hash 0x3277250ae24a5901661a45d25015fcde6561c33a87eddf9d4d8e3dad104857a3: timeout from http.Client" handler="beacon_blocks_by_root" prefix=sync
and progressed to being these in the following hour:
time="2022-09-15 08:59:21" level=error msg="Could not reconstruct full bellatrix block batch from blinded bodies" error="could not fetch execution blocks with txs by hash [0x61fa400096d8e7d75306799d029143fc83106a7c4a5d4efd6ad193318c1f3d6a 0x3e89c5f1d6fa871966392268e2c8d37b81352fce61a5bea28daca95514606080 0xba0f7355164814591fb1b5329f8533681949f97d2657b08ea3aec9e46ba5add7 0x70369a94d8c5a35132f4638ac56bece849a6122fbe7c670361e9fb6d42d6f8fb 0x9e5997a304ea1a0efde12939688b9312212f623fabecd024d8505bd3cf6e1455 0x6566adeb71326fa3b640eaa25810179c1c6907bebf2415f210189c1b49023da5 0x666e870a51a4abbd637fce0da4ab3397ca91befd5eb4e08c7e0e897a9aad4ffb 0x3a98be6af20cf0e2d4b62638f79590f954a246e60be7e6dd61d7896092ab1cd1 0x9ccb5b2ab4c2a38cd0bc4226e2802aef25d83d5e366d1b676bc50109e51b16e6 0x8e130b7d8b47250140b329daf7e38666154225a61f8b183cf8f653ddd09aa3e5 0x978432861e1fbbf3cc1537bc63e0211ea92f7599f19c6da999b5a797e09b295f 0x2855ef1f1f318d41b3f6af766fd63e51038edd7b2f353deb00ba9e3a43a597ea 0x053969fd410335b0f8e50f9361240f30c3bbca27f67f026811370aa65645b0b9 0x574dc74adb36107ca9bb0703093b6f994d948032156a91c32c0ab889bba1c4c6 0xfdaf9a04bb95f3c1703fca41e6908ba2b4caf960e48ad7e9523b3b593e213d5b 0x4f8baed5127f8fd7fdbd59b4c8f2383605f0cf3ca4b9150e45168afc86c6415c 0x1aa4554bdd9f7a76518d4df125472bacba8a6f0f2a013f9dead7530fee629a52 0x40df7c8519b714258c6239c1ac9720e52b8cbbdc3c1b7332f783d97d5af76928 0x49621a85cda6411418652b62afb6710468df44c22595a804373a8ad287437676 0xc7c9098e24e1dc7677069f3ca4bef846462e0200227dff24e26ccc5df6ac4644 0xbb1dda04037aa67928d86b467b8665296f971260dfac0064e2621d39c742f250 0xf928fa14a8d3ba063fcf550f3de5c2dc1c70f084495328ccea0f73cafb9ea512 0xdd156559d6afd1e86d04a65d85243b35848968fe18ddab61a0b613a73df18801 0x5ec8fad9744738e75d6b6fdbb96739e9dff36f2275fdf9076edb3089dfc3cf3b 0x0363e8ec2541825ae1e56421e758313e4d2b1ea742e438bbe0926adaf89b6510 0xfc9f68b8aae8b938df7f26675d8f25481506645a69c218cc0a584f61e16cf7c1 0xced912a4cf1cd49b6b85f5c4068f8ac741d5e42efc3b793f7b7d9abc06b3b1a4 0x1f1091020e9712be5d92ac14652795c0d2961b89142deb34e9b3ea7391f8ff1e 0x8a97c8d8025534c4c579cba444b538d8c545b00d8e862e1fa373bf0c6c26f4ef 0x84ba4b697f8eff9aae7f1ec3e7ef94cee35c23d85373a4e8ff04dfea4beb2d4d 0x73007d8a4632171d1cdcadb2c75fb2c52ca91f52986d90d7d90f26ef5ab923d7 0x7452239120415b44302afd7c8c5b3bc31b09838c253d8ca5f2d6cf4400e30399 0xa0e488be0a355edf69748806b2451ce76848dc14de0ef189b7a3f8736d62bd81 0x636e5259af57a9379bd7013bd8f1f9300f5edd3b30d9e7a8766618158edf7043 0x8c6391fe52ceecd85c4b359dd88794181cbb3be2976f6392cf67829ffbcb42a8 0x8cb1376ef65bf731e13a70b4232bf7a052025f337f190b90c113e2ad3cf15a57 0x4462e9e7303e2e0b3212963cb528071ba7e8493c6acf6a4d25241f79f3929037 0x792e17a20be2462d618e0f810584def0d2025face08ba2bea5f51ea92451dc4e 0x77fd7f362eee037d39edb60146fb3b3790418ebbc709eccb52b1c6ea19982dc7 0xdad62de8f29db7db34126d85ff4156da5e9cae8101473abc12ac61c31da7ebc5 0xc88782d9f1a4b09d3868667b674947e049341d59d2db0be9930659a26fb403a0 0x0292275bfdb7bd9e29d0dea85c5f5a36eebf2ef313208cf62026df7813eaa998 0x26259ccef8e821f915768545c3ab4e6993ffd65f8a9e3c9f5f9c0a1614530e0b 0xd3ee309e24032f033fbb5ea2a6cdb8b6da45d5576b74ab724784898fc087b280 0x4ea6da305140ed1475e1f03039a77ebad5f51aa3fbfaf7abda811b14c46382f5 0xba9f627b8f3ada6adce93fdaeac47c287be6cad779ca0f7d27c33912a133f7c3 0xa5a1140dbd3e56b4b6d1e2815192d559a3909b8718ca10c98d2891f4f3ffa026 0xb71dc61e7d753b51fc7b717ca4a387b95b890b3fdb4100f85cda70cad33efa8e 0xc724b2bf69e637b9f5681461a76de8b8d2096b120a3f60816136ae25944d0f23 0xc33695ceb85c175667394814cb17389882304db8a05ffda6d9a5692eaa753ae7 0x9bfd4b8c36be0cfaf08d8fec636f735b1fe94163dc392b85e4b53280b71fdc5f 0x5dbfd214241cdc016de05d0e034c845142e7f051b89cdf8ba87e5efe8af66263 0x78c51617cda355d56502e6e55e1e19843b6a4c2ef43625aa6b696dc9b7ad826e 0xaeed761da9d1e447625be119a932395e1e88e4ac39f0eb4d7363bbba962d97f7 0x7f88cc4bde81131ef78f30bce7eabbeb30e0d1ff754cf095368b7066e4296205 0x353d51332138784d3123e403c004512e6c9052c12d9bb76af4b396b6ecb22bcf 0xda31a94c1aa1af5c2afca19334ee17b6de1e332782db90f4e53dbb6d82f86611 0xd8d898f725cfde7610629ef17eb49fc12b4acc25914bd8c98b4c52ccd973805a 0x8c16e13982d6ea564943b2754e17c6bc53dc8c1fbff022e53d53cbbf3c23533c 0xdb627ec98c5d8da83bc766f66c2a7e3ef8d9a0b0f6e428e6e45d8cdbd7052388 0xf504d7cfdfc69d82180e634e1bb8ce35b02e92106cce7943d7b95070c5a39666 0x7936c5bef6d4770a15691173ebe674bf4e1284542d724e7e1cc8bd4fd25b0336 0x93f5e62ef5047efc56c6eaea85a10fb227c18c5c8a22cec45444c1682c90abde]: Post "http://besu:8551": net/http: request canceled (Client.Timeout exceeded while awaiting headers)" prefix=sync
Times are in UTC
@schonex thanks for the report. What's your attestation performance % like? EngineForkchoiceUpdated is expected by the way, it means the CL correctly told besu about the chain head (we throttle these logs to once every minute)
I have added the logs at the exact moment of the missed attestation, system config and other background: https://github.com/hyperledger/besu/issues/4398#issuecomment-1248470636
@schonex thanks for the report. What's your attestation performance % like? EngineForkchoiceUpdated is expected by the way, it means the CL correctly told besu about the chain head (we throttle these logs to once every minute)
I am sad to say that at the time, after a few hours of this abysmal performance i switched back to geth which i kept on standby for exactly such a case. Here are my grafana stats for the time period of just before merge, post merge, and my switchover to geth (meaning it's not the system resources).
Times are in UTC.
Here some update from the team. We find a bug in the code where all the calls that come through the engine API port (8551) are sequential. For example, especially for the pair Lighthouse/Besu, all the errors io.netty.channel.StacklessClosedChannelException on eth calls are thrown because they have to wait to some engine_newPayloadV1 call to finish its execution, and this may take more than 1 second, which is the timeout set from the CL side. We're currently working to make ETH calls parallel to the engine API calls, even if these ETH calls are made on port 8551.
We also still working on engine_newPayloadV1 call performance.
Unfortunately, the PR ahamlat created to did not alleviate my missed attestations. Besu/Prysm over here.
I hate to say it, but there may be more than one bug. But at least this first fix will narrow down the behavior to find the deeper problems.
Unfortunately, the PR ahamlat created to did not alleviate my missed attestations. Besu/Prysm over here.
I hate to say it, but there may be more than one bug. But at least this first fix will narrow down the behavior to find the deeper problems.
Same here, been running from source with #4410 for ~12hrs now, no effect on missed attestations (Besu/Nimbus).
Hi everyone - we have narrowed down the root cause to the block import performance. we are working now on improvements to that specific pipeline that should alleviate this issue. Thanks for the patience, we will potentially have some PRs to test ASAP, thank you for bearing with us. We are still targeting a fix for our scheduled Wednesday release, but will have more to share soon.
Not to beat a dead horse, but wanted to chime in that post 22.7.3 and the new --X flag, I am seeing frequent timeouts and missed attestations.
Intel i7 w/ 32g ram and 2tb M.2 NVMe
Not to beat a dead horse, but wanted to chime in that post 22.7.3 and the new
--Xflag, I am seeing frequent timeouts and missed attestations.Intel i7 w/ 32g ram and 2tb M.2 NVMe
You’re not the only one @EvilJordan, 22.7.3 had just about zero effect on my setup as well and I see other users on the discord with similar results.
I'm on 22.7.4 now and missing more attestations than I did with 22.7.2 and 22.7.3,
Does this bug also affect sync committee? I'm missing about 1/4 of all slots. Not seeing anything particularity interesting in the logs.
10 core AMD, 40 GB RAM, VM running rocketpool
Peers: 30
eth1_1 | 2022-10-01 16:56:15.534+00:00 | vert.x-worker-thread-19 | ERROR | MainnetTransactionProcessor | Critical Exception Processing Transaction
eth1_1 | org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0x8c396b415b390b925309cdd8bf598e4d779abf912f3f8ccf522f265220cfa737 location 0x0c02
eth1_1 | at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
eth1_1 | at java.base/java.util.Optional.orElseThrow(Optional.java:403)
eth1_1 | at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
eth1_1 | at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
eth1_1 | at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
eth1_1 | at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
eth1_1 | at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
eth1_1 | at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Still missing attestations on a daily basis.
Looking at logs with the Lighthouse folks we found that observation times were high, which correlated to import times reported in the besu logs as well.
Applied the --Xplugin-rocksdb-high-spec-enabled when it was released and some other tweaking to lighthouse. Didn't really make too much of a difference.
Lighthouse logs analysis:
Examples of blocks taking a long time to import (which would cause attestation misses):
Sep 26 23:36:51.290 DEBG Delayed head block, set_as_head_delay: Some(161.93156ms), imported_delay: Some(3.454792648s), observed_delay: Some(674.050859ms), block_delay: 4.290775067s, slot: 4785282, proposer_index: 101554, block_root: 0x9d6f249480030f48e5bb55cc59e80c38f268edaaa4bf5d855bf86e197815b864, service: beacon, module: beacon_chain::canonical_head:1355
Sep 26 23:35:17.464 DEBG Delayed head block, set_as_head_delay: Some(169.091299ms), imported_delay: Some(4.850303718s), observed_delay: Some(1.445085803s), block_delay: 6.46448082s, slot: 4785274, proposer_index: 308159, block_root: 0x5bb69346550f94015c31acf9a1382915c39a87dea42956f58783a3d49f8b9ba8, service: beacon, module: beacon_chain::canonical_head:1355
And here's an example of a block taking a long time and also causing a cache miss (which will slow down the next block too):
Sep 26 23:00:17.001 INFO Synced, slot: 4784099, block: … empty, epoch: 149553, finalized_epoch: 149551, finalized_root: 0x3ee8…fdf9, exec_hash: 0xbbf2…9197 (verified), peers: 88, service: slot_notifier, module: client::notifier:290
Sep 26 23:00:20.050 WARN Did not advance head state, reason: Err(HeadMissingFromSnapshotCache(0x9dc027043e539aece5edfcc6a57c2844a0c0988554ef655bdc6d34d4c5460027)), service: state_advance, module: beacon_chain::state_advance_timer:192
Sep 26 23:00:20.053 DEBG Delayed head block, set_as_head_delay: Some(145.987644ms), imported_delay: Some(7.637258638s), observed_delay: Some(1.27002282s), block_delay: 9.053269102s, slot: 4785099, proposer_index: 210577, block_root: 0x4e7b1e0417cdb6b4b09eef955845e97e3990c4202d18d2ddf90b64de5673d1fb, service: beacon, module: beacon_chain::canonical_head:1355
Still missing attestations on a daily basis.
Looking at logs with the Lighthouse folks we found that observation times were high, which correlated to import times reported in the besu logs as well.
Applied the
--Xplugin-rocksdb-high-spec-enabledwhen it was released and some other tweaking to lighthouse. Didn't really make too much of a difference.Lighthouse logs analysis:
Examples of blocks taking a long time to import (which would cause attestation misses): Sep 26 23:36:51.290 DEBG Delayed head block, set_as_head_delay: Some(161.93156ms), imported_delay: Some(3.454792648s), observed_delay: Some(674.050859ms), block_delay: 4.290775067s, slot: 4785282, proposer_index: 101554, block_root: 0x9d6f249480030f48e5bb55cc59e80c38f268edaaa4bf5d855bf86e197815b864, service: beacon, module: beacon_chain::canonical_head:1355 Sep 26 23:35:17.464 DEBG Delayed head block, set_as_head_delay: Some(169.091299ms), imported_delay: Some(4.850303718s), observed_delay: Some(1.445085803s), block_delay: 6.46448082s, slot: 4785274, proposer_index: 308159, block_root: 0x5bb69346550f94015c31acf9a1382915c39a87dea42956f58783a3d49f8b9ba8, service: beacon, module: beacon_chain::canonical_head:1355 And here's an example of a block taking a long time and also causing a cache miss (which will slow down the next block too): Sep 26 23:00:17.001 INFO Synced, slot: 4784099, block: … empty, epoch: 149553, finalized_epoch: 149551, finalized_root: 0x3ee8…fdf9, exec_hash: 0xbbf2…9197 (verified), peers: 88, service: slot_notifier, module: client::notifier:290 Sep 26 23:00:20.050 WARN Did not advance head state, reason: Err(HeadMissingFromSnapshotCache(0x9dc027043e539aece5edfcc6a57c2844a0c0988554ef655bdc6d34d4c5460027)), service: state_advance, module: beacon_chain::state_advance_timer:192 Sep 26 23:00:20.053 DEBG Delayed head block, set_as_head_delay: Some(145.987644ms), imported_delay: Some(7.637258638s), observed_delay: Some(1.27002282s), block_delay: 9.053269102s, slot: 4785099, proposer_index: 210577, block_root: 0x4e7b1e0417cdb6b4b09eef955845e97e3990c4202d18d2ddf90b64de5673d1fb, service: beacon, module: beacon_chain::canonical_head:1355
I’m experiencing exactly this. No errors/warnings in Besu logs, but can see import delays of up to 6 seconds which cause roughly 10 missed attestations per day.
Post v22.10.0 I decided to give besu another chance, unfortunately I am still missing attestations daily.
My besu version:
❯ besu --version
besu/v22.10.0/linux-x86_64/openjdk-java-17
2022-11-10 13:56:59.771-05:00 | main | INFO | Besu | Using jemalloc
Right after the merge I was facing this issue due to relatively long block import sizes, on blocks that were >250 tx (or high gas usage) some blocks were taking north of 4-5 seconds to import where there's a clear connection to the missed attestations.
This doesn't seem to be the case anymore, I've collected all the logs of the missed slots from the last few days and aside from one block which was 7 seconds they all seem to have relatively decent import times so I'm not sure why this continues to happen, logs are otherwise squicky clean:
2022-11-10 13:11:39.322-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,941,325 / 270 tx / base fee 31.11 gwei / 27,168,232 (90.6%) gas / (0x6faf3a54d4c67826f3d06f8d65c40f97f25b382e88a8c1be6b0140d7447dc2a0) in 2.278s. Peers: 100
2022-11-10 10:36:52.257-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,940,553 / 318 tx / base fee 49.20 gwei / 28,219,050 (94.1%) gas / (0x53b085bce1996de77c43ae13180cfd768237706e1e019308bc47254d583bb15a) in 3.034s. Peers: 100
2022-11-10 08:10:03.005-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,939,827 / 191 tx / base fee 47.20 gwei / 17,454,292 (58.2%) gas / (0x2932074785fff943e6ecab074fe0c02b23e5fa0f491c237002437bc964294e48) in 1.452s. Peers: 100
2022-11-10 06:28:51.623-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,939,322 / 300 tx / base fee 23.49 gwei / 29,842,885 (99.5%) gas / (0x4e9d9f35547b02fabbb69d854b657e2cb7bc5271ad2eaebdcd11a317545ecc48) in 2.871s. Peers: 100
2022-11-10 05:11:15.041-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,938,938 / 227 tx / base fee 17.87 gwei / 16,487,973 (55.0%) gas / (0xb2327c91c74a1b67eb5b309ef6bc2054391fdcaaf179724440f9515fcfa37539) in 1.606s. Peers: 99
2022-11-10 02:11:39.110-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,938,045 / 256 tx / base fee 20.43 gwei / 23,708,618 (79.0%) gas / (0x89e2d32fe89e173ceb0948e9430b551d34ded9a7669271c02cd85985540ee2e9) in 2.499s. Peers: 100
2022-11-10 00:52:15.152-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,937,650 / 223 tx / base fee 19.11 gwei / 20,853,964 (69.5%) gas / (0xd7370131e5720e2f3dbd49da9b14b234615e75db546c9af67e45c3ab421e0231) in 1.650s. Peers: 100
2022-11-09 23:55:51.708-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,937,368 / 526 tx / base fee 20.24 gwei / 29,985,257 (100.0%) gas / (0xd6ecc2593e225cfa7df219d3d68cf04984698a75ada4d03ca6033b6b8feacbb8) in 3.803s. Peers: 100
2022-11-09 20:25:27.498-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,936,323 / 261 tx / base fee 32.11 gwei / 29,987,440 (100.0%) gas / (0x268fd3ac434c7a66532892bafdff39e3a3f1dff18298beced0e507cd78e6c101) in 3.644s. Peers: 100
2022-11-09 18:38:04.023-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,935,789 / 325 tx / base fee 71.02 gwei / 29,925,643 (99.8%) gas / (0x2cf2c127e8b5c8ca42f9d424040dabcdfc1dcffac605af921f031a8bf1dd2d1c) in 2.576s. Peers: 100
2022-11-09 14:07:03.221-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,934,447 / 125 tx / base fee 96.00 gwei / 11,832,902 (39.4%) gas / (0xe98c6ff3a65f50cf047fe17c74c443fd8d3175e07fcc47b09a4c6b09a02ab056) in 1.355s. Peers: 99
2022-11-09 03:15:39.442-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,931,220 / 291 tx / base fee 15.32 gwei / 27,691,034 (92.3%) gas / (0xdcc28e8e6586da8af4abe4b568f0882027c78a2eceee889e149578bdbd5878b5) in 2.445s. Peers: 100
2022-11-09 01:25:51.072-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,930,676 / 126 tx / base fee 11.73 gwei / 12,620,138 (42.1%) gas / (0x020d41346515bff340a98b1611dd5ac0de437eb08bbc2417edb04fa81c42b428) in 1.145s. Peers: 100
2022-11-09 00:39:03.738-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,930,442 / 142 tx / base fee 13.49 gwei / 18,784,931 (62.6%) gas / (0x3ed165c7d53f1b66e7d6278387a6c891ef301e85737901de48948a2d124905bb) in 3.147s. Peers: 100
2022-11-08 19:55:20.177-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,929,028 / 162 tx / base fee 19.48 gwei / 23,555,159 (78.5%) gas / (0x1b6e2fab1177402dac88d5e2ad69eca6018ce82fe9d0ca996bec1e7cfb2189e3) in 7.419s. Peers: 100
2022-11-08 17:20:39.108-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,928,258 / 173 tx / base fee 37.66 gwei / 13,329,406 (44.4%) gas / (0xb81a876fd19188a9a8a31dde81d33798035063150b26137c4a82c5272e159177) in 1.129s. Peers: 99
2022-11-08 16:19:51.557-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,927,958 / 212 tx / base fee 67.66 gwei / 17,838,731 (59.5%) gas / (0xa838f23674cbac715de797a1fb95f5ac17f939e318ee5264cf5570d981db7a66) in 1.852s. Peers: 100
2022-11-08 13:51:04.168-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,927,220 / 276 tx / base fee 106.09 gwei / 25,855,981 (86.2%) gas / (0x765e18332bdcc89e8a103b6d312d88b87b52325c33ca83a9910108ffe9a2ee88) in 2.323s. Peers: 100
2022-11-08 08:41:51.072-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,925,680 / 328 tx / base fee 11.47 gwei / 25,684,861 (85.6%) gas / (0x535e9dcfde2cf9faa2e8b8074d8d53ff935fc33b108504d01f7e45a79ecb84a8) in 2.118s. Peers: 71
2022-11-08 07:34:39.130-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,925,344 / 234 tx / base fee 11.80 gwei / 26,786,147 (89.3%) gas / (0x756f5733981123b1bc10ff5f6f20fd2a899bac3e1ff7cb0377500ca7a13b2138) in 2.317s. Peers: 100
2022-11-08 06:37:04.048-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,925,056 / 384 tx / base fee 11.87 gwei / 29,303,035 (97.7%) gas / (0xa0dcebd12ffb9d3a74e6fa4b0fd6c206063e61df83f9e956f504269e71c0fdb0) in 3.364s. Peers: 100
2022-11-08 05:36:15.491-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,924,754 / 205 tx / base fee 11.61 gwei / 20,931,904 (69.8%) gas / (0x29c7451dc3e826fad20d561b49a2dc07cc3b0bbd9d371004843f72c91f4c844f) in 2.447s. Peers: 98
2022-11-07 23:12:51.212-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,922,846 / 233 tx / base fee 40.86 gwei / 28,780,554 (95.9%) gas / (0x72b0513eae001723c22f1f87565a5d3e5d021673c5ca837779162f9516cc5382) in 2.181s. Peers: 100
2022-11-07 15:12:03.001-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,920,453 / 182 tx / base fee 29.62 gwei / 13,997,339 (46.7%) gas / (0xb098a14d5ab4d227822ddf60a13864dbcdb446a0ebce1c402efbd843868ba31e) in 1.703s. Peers: 98
2022-11-07 14:01:27.117-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,920,101 / 247 tx / base fee 22.38 gwei / 16,915,698 (56.4%) gas / (0x616c1f883c58b8fc4dbf6d3bd57b02d327305f34d1a136e8ee1a742694406cda) in 2.028s. Peers: 100
2022-11-07 14:02:39.340-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,920,107 / 346 tx / base fee 20.29 gwei / 21,491,065 (71.6%) gas / (0x9eff0ac3b2e8b24264f7010a00707621422746e578dd259a193dc72315c9a4cb) in 2.753s. Peers: 100
2022-11-07 13:00:03.460-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,919,797 / 164 tx / base fee 16.52 gwei / 28,608,409 (95.4%) gas / (0x543c1cfb911c84077635280f41c64620a8b0cb8f653b877dfb71c2bc5a34c9e5) in 3.072s. Peers: 100
2022-11-07 12:34:03.526-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,919,667 / 163 tx / base fee 17.76 gwei / 24,660,270 (82.2%) gas / (0x9730c06271e160aecf479e02926643bf2e67eac1c791665122267e1d3ad4d076) in 2.690s. Peers: 100
2022-11-07 03:24:03.698-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,916,930 / 146 tx / base fee 10.75 gwei / 19,568,875 (65.2%) gas / (0x7c37960da9ea5b1b791cb82bf69543226343bc4d45f86637b85b5e565981e800) in 1.928s. Peers: 100
2022-11-07 00:45:15.226-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,916,140 / 123 tx / base fee 10.12 gwei / 29,958,302 (99.9%) gas / (0x32fab66891b1dbc2a911b5c4ca8bd1bce84e43a69ce94614be7ee2152734df68) in 3.250s. Peers: 100
2022-11-07 00:21:51.212-05:00 | vert.x-worker-thread-0 | INFO | EngineNewPayload | Imported #15,916,023 / 218 tx / base fee 9.89 gwei / 23,382,122 (77.9%) gas / (0x32c9eab88e3aa4ab12f3480d4decaa46fa18422819ff0af30e220977c3844d5c) in 3.331s. Peers: 100
My config.toml running the process with JAVA_OPTS=-Xmx5g with 16GB as recommended:
sync-mode = "X_CHECKPOINT"
network = "MAINNET"
p2p-enabled = true
p2p-port = 30303
max-peers = 100
host-allowlist = [ "localhost", "127.0.0.1", "::1" ]
rpc-http-enabled = true
rpc-http-port = 8545
rpc-http-host = "127.0.0.1"
rpc-http-cors-origins = [ "*" ]
rpc-http-api=["ADMIN","ETH","NET","DEBUG","TXPOOL","WEB3"]
rpc-ws-enabled = true
rpc-ws-port = 8546
rpc-ws-host = "0.0.0.0"
engine-jwt-enabled = true
engine-jwt-secret = "<redacted>"
engine-rpc-enabled = true
engine-rpc-port = 8551
engine-host-allowlist = [ "localhost", "127.0.0.1", "::1" ]
graphql-http-enabled = true
graphql-http-host = "0.0.0.0"
graphql-http-port = 8547
graphql-http-cors-origins = [ "*" ]
#metrics-enabled = true
#metrics-port = 9545
#metrics-host = "0.0.0.0"
data-storage-format = "BONSAI"
data-path = "/var/lib/besu/mainnet"
Xplugin-rocksdb-high-spec-enabled = true
@ibhagwan Could you please share your hardware spec as well?
I’m using an Optimized Cloud Compute instance from Vultr hosting with dedicated 4 vCPUs, 16GB RAM and a 1TB dedicated NVMe block device.
Edit: another thing worth mentioning is that the missed attestations seem to be getting worse with uptime, it starts with 97-99% effectiveness and few misses per day to just about ~92% effectivenesss, this already happened twice and aftet restart the situation is clearly better.