Slow block import #13
Comments
|
Can you run the node with |
|
@altonen thanks for your response. |
|
From the logs it looks like there are no block announcements coming for the relay chain so that could possibly explain why the target block is not progressing. And since for most peers you're connected the best block is not progressing because either a) they're major syncing as well and don't announce blocks or b) the inbound Why it takes a minute between importing block |
|
Just for clarification, the relay chain in question is Polkadot. |
No. It started directly the checking of the header of |
|
@purestakeoskar is this reproducible for you on |
|
Bringing in we have the same problem on Astar with an http endpoint which is heavily queried, tested on both 9933 and 9944. |
I do not have a client with v0.9.36 to test with unfortunately. Is there any change in particular in 0.9.37 that stands out? |
|
@purestakeoskar Does this node use paritydb or rocksdb? And does this problem persist forever or are block imports normal again after some time? Sync mode normal? |
|
@skunert The node is using rocksdb, and the blocks does slowly import, some faster than others, the syncing does eventually finish and after that the node follows the chain. Another interesting note (this might be a separate issue). when the node restarts the grandpa sessions takes a while to be established on the relay side, so we dont see blocks finalizing for sometimes up to 15 minutes. But then when the grandpa notification streams are open we start to see the finalization moving again. During this time block import still happens. Also to note, we have the same behaviour when we use external RPC for the relay chain. |
Perhaps you can reproduce the issue use Khala network, we're on the latest Polkadot v0.9.41, can both reproduce no matter ParityDB or RocksDB You should see a significant sync speed regression when the progress reaches ~50% Some users will experience the sync speed reduction to 0 bps (both Parachain and Relaychain), some lucky users will have ~ 50bps (in my experience) |
|
We left some comments on paritytech/substrate#9360 |
|
You can use https://github.com/koute/not-perf for profiling |
|
@arkpar Here it is, the node uses the default arguments, recording when sync is slow I see
|
|
There seem to be a lot of time wasted in |
|
Yeah, @skunert is already working on this: paritytech/cumulus#2495 |
|
Yes, the problem are finality notifications that reach the node while syncing when the finalized block is far away from the tip of the chain. For each of these finalization attempts, we calculate multiple tree routes. One from last finalized -> new finalized and one from new_finalized -> best_block. This last route is very long in the collator case and takes up to 15 seconds on my machine. During this time, the import lock is taken, and no other import operations are possible. We do not hit the cache since the distance between finalized and best can be millions of blocks. I see the following options:
@arkpar Any opinions on this? |
|
So this looks like paritytech/substrate#9360, p.2
What is that last route used for? Maybe we can make some assumptions if the difference in block numbers is over some threshold?
In theory, we can finalize any chain in constant time, without having to check all the intermediate blocks. IIRC we only query tree routes to get a list of discarded blocks and actually discard them. This list should be empty after the initial sync anyway. Implementing this at the database level could be a bit involved. |
|
We could check the number of leaves. If the number of leaves is one, we don't need to calculate the tree route as there isn't any other chain. This should also hold for the initial sync and should give us the speed up we need. |
This sounds reasonable, will give it a try. |
This sounds reasonable for this particular issue, but it won't fix the problem reported in paritytech/cumulus#2495 There will still be a million blocks finalized at once. |
True, but this issue here is particularly annoying since this blocks the entire syncing. paritytech/cumulus#2495 is for sure still problematic but will only stall the node for a few minutes before it continues operation normally. We should look into further improvements. |
|
This change is now in cumulus, closing here. |
|
I just made a new node based on polkadot-v0.9.42 and did a resync on my Azure VM (which stuck sync when reaching ~50% progress), I'll try record nperf tomorrow BTW, I see that node can't stop gracefully (so does previous) |
|
@bkchr I think txpool has trouble, here is the log, I only run the node < 5 min, that generates 8GB log https://storage.googleapis.com/phala-misc/trace_txpool.log.zip NOTE: I must confess in the early day Khala online, our pallet has serious bugs we have to clear our collators' txpool for mitigate. But we found sync Phala (on Polkadot) has the same trouble which old problems have already been fixed properly. For now I don't have Phala node so I can't share info yet, but I'll do next week |
|
The log is huge because There was a PR(paritytech/substrate#13004) to prevent this, but apparently it does not help much. |
|
In the logs we see the transaction pool act on finality notifications. Usually we should only see one finality justification for each incoming block with an attached justification. The justification should be attached every @jasl However I found that in khala the |
Yeah, we patched the |
|
I mean its not just the transaction pool, basically every location that listens for finality notifications in substrate will be notified. In addition we verify the justification, do extra operations in the database, state-db etc.. This brings extra overhead that we should not have for every single block. |
I can understand we patched But I still don't quite understand: PS: I'm too noob in this domain, is there any doc I can learn? |
There is a RPC to proof finality that you can use.
paritytech/substrate#14285 this will improve the situation. However, I also think that there is maybe still more to it. |
Thank you, I can backport your PR to our node to test |
Transaction pool listens for these notifications and does some maintenance work. We have logic in place to skip this based on block distances. However when the node is finalizing every block, this maintenance is triggered too often. Even if you disable this now, your existing nodes will have the justifications in their db. Ideally, the node would not finalize for every incoming justification during sync, so that will probably change. |
|
I've backported paritytech/substrate#14285 to our Khala node Short (run about 20 s) Long (run about 1.5 min) |
|
@jasl can you please share the exact CLI args you are using to spawn your node? This could still be a result of your relay chain node importing a justification every block. We need to wait for @andresilva to provide a fix that ensures that we don't import justifications every block as you have configured it (which is wrong and should be reverted!). |
Thank you, now I understand how bad it would be if we set a very short |
|
@jasl If you want you could try to run your node with |
Our collators are using But running 2 apps in one Docker container is not recommended, so I would like to test, for end-users I shall waiting the proper fix |
|
Having here the same behaviour on an Astar node. It's important to note that it happens only on RPC under high number of requests. |
|
@bLd75 Can you provide logs with |
|
This is still an issue on Polkadot 0.9.43: |
|
Additional information. It seems that the import is limited by the Disk IOPS (this is specially the case in Cloud services providing low default IOPS). I think something changed in recent version (probably around 0.9.37) which is significantly increasing the IOPS reaching a limit where it snowballs and block most of the processes. Ex: Increasing it (realtime) to 10k IOPS allows to restore some bps but it quickly goes down to 0.2 or 0.0 bps. I think something is inefficient and snowballing. === Experiment 1: rocksdb from scratch === (for 370 bps, IOPS is only ~100, however the chain/state was empty as it was the beginning of the sync) === Experiment 2: paritydb from scratch === (for 370 bps, IOPS is ~3000 which is a lot compared to rocksdb) |
paritytech/substrate#14285 seems not bundled in 0.9.43, but in 0.9.44. You have to backport it by yourself. we forked 0.9.43 and cherry-pick these changes. |
|
Thank you, I'll try those |
the-right-joyce
added
I10-unconfirmed
|
@jasl @crystalin Do you still get this issue with the latest release? |
Is there an existing issue?
Experiencing problems? Have you tried our Stack Exchange first?
Description of bug
When syncing a node the block import is very slow, to the point where block production is faster than block import.
Instead of
syncthe logs showsPreparing.The node is connected to peers with blocks we need.
There are also queued synced blocks (sync_queued_blocks metric)
Another interesting note is that the node does not know how far it needs to sync. Its sync_target is equal to best_block
Steps to reproduce
Start syncing a moonbem or moonriver node with archive parachain and pruned relay chain
We are running moonbeam version
0.30.3( using polkadot0.9.37)Main flags used
The text was updated successfully, but these errors were encountered: