downloader: restart in the middle of download causing speed drop

[AskAlexSharov]

bor-mainnet

1. restart in the middle of download (--torrent.download.slots=32) - see small hash-rate for long time and until it done download-rate is super small and users think "why erigon downloading is so slow? I have good network interface". I think we need: 3.1 change logging of this part to something like "verifying..." and don't show download rate here 3.2 hash-rate is very low (I have 128core machine with nvme raid). 3.3 unclear when verification part will be over (in %) 3.4 now it looks like restart in the middle of downloading significantly reduce download speed for hours and unclear "do I need wait?" "do I need restart?"

INFO[07-18|03:32:48.646] [1/1 OtterSync] Requesting header-chain from downloader
INFO[07-18|03:32:49.647] [snapshots] initializing downloads       torrents=0/1397
INFO[07-18|03:32:49.886] [snapshots] initializing downloads       torrents=1397/1397
INFO[07-18|03:32:49.893] [1/1 OtterSync] Downloader completed header-chain
INFO[07-18|03:32:50.848] [1/1 OtterSync] Synced header-chain
INFO[07-18|03:32:50.940] [1/1 OtterSync] Checking remaining snapshots
INFO[07-18|03:33:23.940] [1/1 OtterSync] Requesting remaining snapshots from downloader
INFO[07-18|03:33:24.941] [snapshots] initializing downloads       torrents=4806/7061
INFO[07-18|03:33:26.941] [snapshots] initializing downloads       torrents=4806/7061
INFO[07-18|03:33:30.942] [snapshots] initializing downloads       torrents=4806/7061
INFO[07-18|03:33:38.942] [snapshots] initializing downloads       torrents=4806/7061
INFO[07-18|03:33:54.944] [snapshots] initializing downloads       torrents=4806/7061
INFO[07-18|03:34:18.604] [p2p] GoodPeers                          eth68=6 eth67=19
INFO[07-18|03:34:26.945] [snapshots] initializing downloads       torrents=4806/7061
INFO[07-18|03:35:07.909] [snapshots] no metadata yet              files=1 list=v1.0-058300-058400-borevents.seg
INFO[07-18|03:35:24.282] [1/1 OtterSync] Syncing                  file-metadata=5536/5537 files=2571/5537 data=37.9GB time-left=101h35m47s total-time=0s download-rate=0B/s hashing-rate=65.0MB/s alloc=2.5GB sys=5.1GB
INFO[07-18|03:35:30.945] [snapshots] initializing downloads       torrents=4808/7061
INFO[07-18|03:35:33.168] [snapshots] no metadata yet              files=1 list=v1.0-058300-058400-borspans.idx
INFO[07-18|03:35:45.398] [1/1 OtterSync] Syncing                  file-metadata=5537/5538 files=2572/5538 data=41.2GB time-left=11h50m54s total-time=21s download-rate=202.7KB/s hashing-rate=268.0MB/s alloc=2.3GB sys=5.1GB
INFO[07-18|03:35:48.732] [mem] memory stats                       Rss=6.0GB Size=0B Pss=6.0GB SharedClean=3.9MB SharedDirty=0B PrivateClean=954.3MB PrivateDirty=5.1GB Referenced=6.0GB Anonymous=5.1GB Swap=0B alloc=2.9GB sys=5.1GB
INFO[07-18|03:36:36.203] [1/1 OtterSync] Syncing                  file-metadata=5540/5540 files=2572/5540 data="0.82% - 45.1GB/5.4TB" time-left=15h7m4s total-time=1m11s download-rate=198.4KB/s hashing-rate=92.3MB/s alloc=3.2GB sys=5.1GB
INFO[07-18|03:37:11.988] [snapshots] no metadata yet              files=1 list=v1.0-058400-058500-borcheckpoints.seg
INFO[07-18|03:37:32.711] [1/1 OtterSync] Syncing                  file-metadata=5543/5544 files=2572/5544 data=48.0GB time-left=30h57m40s total-time=2m8s download-rate=187.4KB/s hashing-rate=47.5MB/s alloc=3.2GB sys=5.1GB
INFO[07-18|03:37:38.945] [snapshots] initializing downloads       torrents=4820/7061
INFO[07-18|03:38:07.828] [snapshots] no metadata yet              files=1 list=v1.0-058400-058500-borspans.seg
INFO[07-18|03:38:26.433] [1/1 OtterSync] Syncing                  file-metadata=5547/5548 files=2572/5548 data=50.1GB time-left=42h4m55s total-time=3m2s download-rate=275.1KB/s hashing-rate=35.2MB/s alloc=4.3GB sys=5.1GB
SharedDirty=0B PrivateClean=956.1MB PrivateDirty=5.1GB Referenced=6.0GB Anonymous=5.1GB Swap=0B alloc=2.4GB sys=5.1GB
INFO[07-18|03:39:08.422] [snapshots] no metadata yet              files=1 list=v1.0-058500-058600-borcheckpoints.seg
INFO[07-18|03:39:19.938] [1/1 OtterSync] Syncing                  file-metadata=5552/5553 files=2572/5553 data=51.8GB time-left=52h15m36s total-time=3m55s download-rate=329.5KB/s hashing-rate=29.4MB/s alloc=3.7GB sys=5.1GB
INFO[07-18|03:40:06.194] [1/1 OtterSync] Syncing                  file-metadata=5559/5559 files=2572/5559 data="0.95% - 52.6GB/5.4TB" time-left=116h18m40s total-time=4m41s download-rate=408.4KB/s hashing-rate=12.1MB/s alloc=2.5GB sys=5.1GB
INFO[07-18|03:41:15.038] [1/1 OtterSync] Syncing                  file-metadata=5566/5566 files=2572/5566 data="0.95% - 52.6GB/5.4TB" time-left=3569h51m31s total-time=5m50s download-rate=430.7KB/s hashing-rate=608.1KB/s alloc=2.5GB sys=5.1GB
INFO[07-18|03:41:48.728] [mem] memory stats                       Rss=6.1GB Size=0B Pss=6.1GB SharedClean=3.9MB SharedDirty=0B PrivateClean=1.0GB PrivateDirty=5.1GB Referenced=6.1GB Anonymous=5.1GB Swap=0B alloc=2.5GB sys=5.1GB
INFO[07-18|03:41:54.945] [snapshots] initializing downloads       torrents=4859/7061
INFO[07-18|03:42:09.922] [1/1 OtterSync] Syncing                  file-metadata=5573/5573 files=2572/5573 data="0.95% - 52.6GB/5.4TB" time-left=3254h25m39s total-time=6m45s download-rate=491.2KB/s hashing-rate=363.9KB/s alloc=3.4GB sys=5.1GB
INFO[07-18|03:43:11.297] [1/1 OtterSync] Syncing                  file-metadata=5581/5581 files=2572/5581 data="0.95% - 52.7GB/5.4TB" time-left=3264h45m48s total-time=7m47s download-rate=502.5KB/s hashing-rate=402.0KB/s alloc=4.0GB sys=5.1GB

2. initializing downloads is slow (but it always was) - on bor-mainnet - and probably it impacting download-rate (until initializing is done). also from logs unclear - is initializing done or not. Maybe we should separate this 2 stages - add everything first and then start downloading - maybe it will shift bottlenecks and we can optimize each stage better? Can slow adding be because of DL_HASHERS is small for large .kv files?

INFO[07-18|03:25:10.177] [snapshots] initializing downloads       torrents=2529/6933
INFO[07-18|03:25:12.177] [snapshots] initializing downloads       torrents=2529/6933
INFO[07-18|03:25:16.177] [snapshots] initializing downloads       torrents=2536/6933
INFO[07-18|03:25:24.177] [snapshots] initializing downloads       torrents=2575/6933

probably same bottleneck

3. seems mutex contention:

4. We have .partial files - maybe then no much reason to re-hash everything at startup?

[VBulikov]

VBulikov added Imp2 as Importance

[AskAlexSharov]

even without restart, first 10min (not header-chain step) I see 1mb/s download rate (rclone shows 600mb/s from same server). on bor-mainnet.

[anacrolix]

I chatted with Alex about this. After the initialization completes, speeds return to normal. It occurs more often with very large torrent counts, like archive nodes and bor-mainnet.

[VBulikov]

anacrolix changed Importance from Imp2 to Imp1

[anacrolix]

Should be addressed in #16328. There can still be some slowdown for pathological cases, but the downloader will try to avoid those.

[anacrolix]

I consider this fixed. See also #16317, which is specific to high latency storage devices.