Zebra full mainnet sync is very slow or hangs

[teor2345]

Version

Zebra main branch, after #1709, #1721, and #1764 (incomplete).

Platform

Linux

Description

Zebra is slow to sync on mainnet, taking multiple days to reach 300,000 - 500,000 blocks.

I see a lot of ConnectionClosed and Timeout errors that weren't in the logs before #1721.

But it's also possible that #1709 didn't entirely fix the peer set. Or that the incomplete change in #1764 is causing these hangs.

This issue might also be caused by the starvation issues in FuturesUnordered (rust-lang/futures-rs#2333).

Commands

zebrad start on mainnet

Logs

The SharedPeerError(ConnectionClosed) logs are a lot more frequent. We also see more SharedPeerError(ClientRequestTimeout)s.

Feb 23 11:00:22.536  INFO {zebrad="a6a8fde4" net="Main"}:sync:obtain_tips: zebrad::components::sync: trying to obtain new chain tips tip=block::Hash("0000000000765bea37664fcec9a55cc3252ce077d83402e6eb6145c8e0501d6e")                                                                                                                                                                                              
Feb 23 11:00:27.591  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=499 lookahead_limit=2000
Feb 23 11:00:27.591  INFO {zebrad="a6a8fde4" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1                                                          
Feb 23 11:00:33.151  WARN {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: error downloading and verifying block e=SharedPeerError(ClientRequestTimeout)
Feb 23 11:00:33.151  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: waiting to restart sync timeout=61s  

Feb 23 11:02:14.205  INFO {zebrad="a6a8fde4" net="Main"}:peer{addr=184.72.241.255:8233}:msg_as_req{msg=inv}:inbound:download_and_verify{hash=00000000010af29d89b40bc84348fce9f3c11ab2b0edea5b7cf214a971358fb4}: zebra_state::service: pruned utxo requests old_len=5861 new_len=185 prune_count=5676 tip=Some((Height(529427), block::Hash("0000000000765bea37664fcec9a55cc3252ce077d83402e6eb6145c8e0501d6e")))
Feb 23 11:02:40.946  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: starting sync, obtaining new tips
Feb 23 11:02:40.946  INFO {zebrad="a6a8fde4" net="Main"}:sync:obtain_tips:state: zebra_state::util: created block locator tip_height=Height(529427) min_locator_height=529328 locators=[Height(529427), Height(529426), Height(529425), Height(529423), Height(529419), Height(529411), Height(529395), Height(529363), Height(529328)]
Feb 23 11:02:40.946  INFO {zebrad="a6a8fde4" net="Main"}:sync:obtain_tips: zebrad::components::sync: trying to obtain new chain tips tip=block::Hash("0000000000765bea37664fcec9a55cc3252ce077d83402e6eb6145c8e0501d6e")
Feb 23 11:02:44.204  INFO {zebrad="a6a8fde4" net="Main"}:sync:obtain_tips: zebra_state::service: pruned utxo requests old_len=2497 new_len=2468 prune_count=29 tip=Some((Height(529427), block::Hash("0000000000765bea37664fcec9a55cc3252ce077d83402e6eb6145c8e0501d6e")))
Feb 23 11:02:45.826  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=499 lookahead_limit=2000
Feb 23 11:02:45.826  INFO {zebrad="a6a8fde4" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Feb 23 11:02:51.384  WARN {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: error downloading and verifying block e=SharedPeerError(ConnectionClosed)
Feb 23 11:02:51.384  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: waiting to restart sync timeout=61s

Feb 23 11:02:11.067  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=373 lookahead_limit=2000
Feb 23 11:02:11.067  INFO {zebrad="a6a8fde4" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Feb 23 11:02:20.279  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=747 lookahead_limit=2000
Feb 23 11:02:20.279  INFO {zebrad="a6a8fde4" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Feb 23 11:02:21.970  INFO {zebrad="a6a8fde4" net="Main"}:sync:extend_tips:checkpoint: zebra_consensus::checkpoint: verified checkpoint range block_count=400 current_range=(Excluded(Height(297235)), Included(Height(297635)))
Feb 23 11:02:29.021  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=1119 lookahead_limit=2000
Feb 23 11:02:29.021  INFO {zebrad="a6a8fde4" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Feb 23 11:02:30.446  INFO {zebrad="a6a8fde4" net="Main"}:sync:extend_tips:checkpoint: zebra_consensus::checkpoint: verified checkpoint range block_count=400 current_range=(Excluded(Height(297635)), Included(Height(298035)))
Feb 23 11:02:36.884  WARN {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: error downloading and verifying block e=SharedPeerError(ConnectionClosed)
Feb 23 11:02:36.884  INFO {zebrad="a6a8fde4" net="Main"}:sync: zebrad::components::sync: waiting to restart sync timeout=61s

[teor2345]

Closed by #1803, follow up in #1817