besu icon indicating copy to clipboard operation
besu copied to clipboard

Published 20 hours ago • verified publisher icon hyperledger

Slow backwards sync

Open ForceConstant opened this issue 2 years ago • 2 comments

Description

Had Besu shutoff for a week due to some issues, now restarted with 2.7.4, and it is slowly doing Backwards Sync Algorithm, it has been 15 hours, and seems like it will be another 24 hours at this rate. CPU is low at 10%, and load is 1.4, io is low. I am running as part of rocketpool tool. 16GB Ram, '--Xplugin-rocksdb-high-spec-enabled'

I do have grafana dashboard running, so can include any plots for that if wanted.

  | 2022-09-27 12:33:10.058+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588292 -> 15588292 (target: 15624713)
eth1_1           | 2022-09-27 12:33:10.060+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:11.592+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588293 -> 15588293 (target: 15624713)
eth1_1           | 2022-09-27 12:33:11.594+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:14.665+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588294 -> 15588294 (target: 15624714)
eth1_1           | 2022-09-27 12:33:14.670+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:17.299+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588295 -> 15588295 (target: 15624714)
eth1_1           | 2022-09-27 12:33:17.301+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:19.472+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588296 -> 15588296 (target: 15624714)
eth1_1           | 2022-09-27 12:33:19.474+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:19.575+00:00 | nioEventLoopGroup-3-8 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:19.576+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:19.832+00:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:19.833+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:22.872+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588297 -> 15588297 (target: 15624714)
eth1_1           | 2022-09-27 12:33:22.874+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:22.933+00:00 | nioEventLoopGroup-3-8 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:22.933+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:23.211+00:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:23.212+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:24.792+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588298 -> 15588298 (target: 15624715)
eth1_1           | 2022-09-27 12:33:24.794+00:00 | ForkJoinPool.commonPool-worker-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:24.996+00:00 | nioEventLoopGroup-3-8 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:24.996+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:25.322+00:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:25.323+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:27.356+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588299 -> 15588299 (target: 15624715)
eth1_1           | 2022-09-27 12:33:27.359+00:00 | ForkJoinPool.commonPool-worker-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:29.361+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588300 -> 15588300 (target: 15624715)
eth1_1           | 2022-09-27 12:33:29.363+00:00 | ForkJoinPool.commonPool-worker-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:29.429+00:00 | nioEventLoopGroup-3-8 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:29.430+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:29.690+00:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:29.690+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:31.632+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588301 -> 15588301 (target: 15624715)
eth1_1           | 2022-09-27 12:33:31.634+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:34.730+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588302 -> 15588302 (target: 15624715)
eth1_1           | 2022-09-27 12:33:34.733+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:36.260+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588303 -> 15588303 (target: 15624715)
eth1_1           | 2022-09-27 12:33:36.262+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:39.146+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588304 -> 15588304 (target: 15624716)
eth1_1           | 2022-09-27 12:33:39.151+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:40.681+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588305 -> 15588305 (target: 15624716)
eth1_1           | 2022-09-27 12:33:40.684+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:42.970+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588306 -> 15588306 (target: 15624716)
eth1_1           | 2022-09-27 12:33:42.972+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:44.901+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588307 -> 15588307 (target: 15624716)
eth1_1           | 2022-09-27 12:33:44.904+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:48.589+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588308 -> 15588308 (target: 15624717)
eth1_1           | 2022-09-27 12:33:48.591+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:34:00.913+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0x2fde5cf0a49ff9f6db5781a7bb92a41671498eb060aa1ec933d55925a0cfb8a1, finalized: 0x0fdbf36038871f716899616046b7d5fef94561ec04af5c0d51691bee10a6083f, safeBlockHash: 0xc491055ef1bfcdb2158b268ce0739adc845d95ae127854b0c605b0eb9242fb70
eth1_1           | 2022-09-27 12:34:25.407+00:00 | nioEventLoopGroup-3-3 | INFO  | ForwardSyncStep | Saved blocks 15588309 -> 15588337 (target: 15624720)
eth1_1           | 2022-09-27 12:34:25.411+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:34:25.487+00:00 | nioEventLoopGroup-3-6 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:34:25.488+00:00 | nioEventLoopGroup-3-6 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync

ForceConstant avatar Sep 27 '22 12:09 ForceConstant

I also get the error NO_PEERS_FOUND sometimes

image

eth1_1           | 2022-09-27 21:55:30.877+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 1. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:35.878+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:37.629+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0x2324285c691da3bda2b39922be5579c2d07a4c0d63ad76ec8287a7e78edda730, finalized: 0x3900f75eb3e46d1bd414028341ebd9d43adf78d9d305fc59a6721ce92100a08b, safeBlockHash: 0x52429b0cf7bcbd5efea3f0cda3b250fc9f0aea5cd6c588bfc6d178a53336dd1d
eth1_1           | 2022-09-27 21:55:39.786+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15599173 -> 15599174 (target: 15627498)
eth1_1           | 2022-09-27 21:55:39.876+00:00 | ForkJoinPool.commonPool-worker-3 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:39.889+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:44.890+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:44.904+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:49.904+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:49.912+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:54.913+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:54.926+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:59.927+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:59.940+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 1. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:56:04.941+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:06.525+00:00 | nioEventLoopGroup-3-9 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 21:56:06.526+00:00 | nioEventLoopGroup-3-9 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:06.694+00:00 | nioEventLoopGroup-3-9 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 21:56:06.695+00:00 | nioEventLoopGroup-3-9 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:06.858+00:00 | nioEventLoopGroup-3-9 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 21:56:06.859+00:00 | nioEventLoopGroup-3-9 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:06.861+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 1. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:56:11.862+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:48.537+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0x3dc71a74911f99d9e7fdd89f8fb2486485a94a86141c4a59895556fe5fd423a8, finalized: 0xe7fd

ForceConstant avatar Sep 27 '22 21:09 ForceConstant

Same issue(s). Also running Rocketpool, Besu 22.7.5 (just upgraded from 22.7.4) in combination with Nimbus.

image

zymox avatar Oct 05 '22 19:10 zymox

@fab-10 @gezero - Maybe we consider some new logging around this to better inform users?

non-fungible-nelson avatar Nov 08 '22 17:11 non-fungible-nelson

I agree we can improve the logging, showing only the progress and critical errors, and pushing transient errors to debug.

Instead for the timing, it is normal that it takes more time that the initial sync, since backward sync needs to fully import blocks, in a serial way, so the improvements around block import that are ongoing will benefit backward sync as well, but as rule of thumb, if Besu is down for some day is usually faster to delete the database and perform a snapsync from scratch, that wait for the backward sync to complete, since the latter is only meant for the sync of few blocks.

fab-10 avatar Nov 09 '22 09:11 fab-10

Understood - maybe we paste that in the logs if the BWS queue is large enough? Or a docs change - I will open a PR on this page.

non-fungible-nelson avatar Nov 09 '22 15:11 non-fungible-nelson