Algod syncing very slowly - General - Algorand
Algod syncing very slowly
post by d13co on Jan 23, 2022
Hi,
I am trying to sync a full archival node for mainnet in order to run my own indexer. It is going very slowly. At first I was on a slow Oracle cloud instance but I have since moved to a dedicated server where network/compute/disk resources should not be a bottleneck.
The sync process has been going on since mid November and I am still at block 14736614.
At times it seems to hang and sync very, very slowly. I get these errors intermittently:
{"file":"bootstrap.go","function":"github.com/algorand/go-algorand/tools/network.ReadFromSRV","level":"info","line":43,"msg":"ReadFromBootstrap: DNS LookupSRV failed when using system resolver: no signature in DNS response for _algobootstrap._tcp.mainnet.algorand.network","time":"2022-01-23T11:08:25.289766+01:00"}
I saw elsewhere on the forums that access to 8.8.8.8 may be an issue, but this doesn’t seem to be the case for me:
root@k43 ~ # dig @8.8.8.8 _algobootstrap._tcp.testnet.algorand.network srv
; <<>> DiG 9.16.1-Ubuntu <<>> @8.8.8.8 _algobootstrap._tcp.testnet.algorand.network srv
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 1903
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 8, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 512
;; QUESTION SECTION:
;_algobootstrap._tcp.testnet.algorand.network. IN SRV
;; ANSWER SECTION:
_algobootstrap._tcp.testnet.algorand.network. 300 IN SRV 1 1 4161 relay-virginia-testnet-algorand.algorand-testnet.network.
_algobootstrap._tcp.testnet.algorand.network. 300 IN SRV 1 1 80 relay-switzerland1-testnet-algorand.algorand-testnet.network.
_algobootstrap._tcp.testnet.algorand.network. 300 IN SRV 1 1 4161 londong-algorand-test-2.algorand-testnet.network.
_algobootstrap._tcp.testnet.algorand.network. 300 IN SRV 1 1 4161 r19.algorand-testnet.network.
_algobootstrap._tcp.testnet.algorand.network. 300 IN SRV 1 1 4161 singaporeg-algorand-test-1.algorand-testnet.network.
_algobootstrap._tcp.testnet.algorand.network. 300 IN SRV 1 1 4161 singaporeg-algorand-test-2.algorand-testnet.network.
_algobootstrap._tcp.testnet.algorand.network. 300 IN SRV 1 1 4161 oregong-algorand-test-1.algorand-testnet.network.
_algobootstrap._tcp.testnet.algorand.network. 300 IN SRV 1 1 4161 londong-algorand-test-1.algorand-testnet.network.
;; Query time: 12 msec
;; SERVER: 8.8.8.8#53(8.8.8.8)
;; WHEN: So Jan 23 11:10:43 CET 2022
;; MSG SIZE rcvd: 623
I am on Ubuntu 20.04 and I have both global and interface DNS servers set to 8.8.8.8 with DNSSEC enabled:
root@k43 ~ # systemd-resolve --status | grep DNS
MulticastDNS setting: no
DNSOverTLS setting: no
DNSSEC setting: yes
DNSSEC supported: yes
Current DNS Server: 8.8.8.8
Possibly worth noting that I have an indexer running against algod while it is syncing (via HTTP as it is on another server). Is this recommended? Do I need "IsIndexerActive": true in config.json in this case?
IPv4 and v6 connectivity seems to be stable.
My config.json file can be found here
Last lines of node.log (excluding indexer GET requests) can be found here
algod version is 3.2.3.stable
Is there anything obviously wrong with my setup?
Thanks in advance,
Bit
post by tsachi on Jan 23, 2022
Regarding the IsIndexerActive :
You’d like to set it to false. This option is practically deprecated.
Also, if the catchup is making any progress, than leave the DNS messages alone; that’s not the droid you’re looking for.
post by d13co on Jan 23, 2022
Thanks, I figured it is a leftover from when algod had the indexer integrated. I have it as false.
Also, if the catchup is making any progress, than leave the DNS messages alone; that’s not the droid you’re looking for.
It is making some progress but it seems to stall for tens of minutes at a time.
Any thoughts on what I should prod? At this rate I don’t think it will catch up
post by tsachi on Jan 23, 2022
Could you post here the latest 50 lines from the node.log file that contains the word ‘catchup’ ?
post by d13co on Jan 23, 2022
Thanks for the attention! Uploaded here.
post by tsachi on Jan 23, 2022
I havn’t seen anything bad going on there… could you share with the forum what type of storage and compute you’re using ?
post by d13co on Jan 23, 2022
Sure,
CPU: Intel(R) Core™ i7-4770 CPU @ 3.40GHz
RAM: 32GB ECC
HDD: 2x WD WD2000FYYZ-0 2GB 7200RPM in md/raid 1
post by d13co on Jan 23, 2022
Sorry to press the DNS issue again, but are the “no such host” errors common/to be expected? Getting a lot of these:
ReadFromBootstrap: DNS LookupSRV failed when using system resolver: lookup _archive._tcp.mainnet.algorand.network on 8.8.8.8:53: no such host
According to goal node status, right now it seems to be stuck:
$ goal node status
Last committed block: 14740128
Time since last block: 13011.7s
Sync Time: 24677.5s
Current logs here
edit: current telemetry metrics pretty-printed are here. Do these look right?
post by tsachi on Jan 23, 2022
regarding _archive._tcp.mainnet.algorand.network, yes, this is expected. It’s part of the algod support for block archivers, which have not been enabled yet. The only negative consequence is that your node might be emitting these benign log messages from time to time.
As for your hardware spec, I suspect that the HDD is the culprit. Regardless of the raid 1 configuration, HDD are generally far too slow to support the current load on mainnet. I’d suggest you’d select a hosting service that support a local nvme drive.
post by d13co on Jan 23, 2022
I understand that the HDD is not ideal and performance may be somewhat degraded but in this case it seems to have been stuck not getting a new block for ~4 hrs (15431 sec).
I looped goal node status every 10 minutes after I saw it getting stuck and I saw this (clipped to include relevant info):
So 23. Jan 19:38:37 CET 2022
Last committed block: 14740128
Time since last block: 13631.0s
So 23. Jan 19:48:37 CET 2022
Last committed block: 14740128
Time since last block: 14231.0s
So 23. Jan 19:58:37 CET 2022
Last committed block: 14740128
Time since last block: 14831.1s
Sync Time: 26496.9s
So 23. Jan 20:08:37 CET 2022
Last committed block: 14740128
Time since last block: 15431.1s
Sync Time: 27096.9s
So 23. Jan 20:21:50 CET 2022
Cannot contact Algorand node: Get "http://[::]:$myport/v2/status": EOF
So 23. Jan 20:33:18 CET 2022
Last committed block: 14740503
Time since last block: 687.8s
Sync Time: 28577.6s
I should have mentioned that the architecture of the original algod node was different (aarch64) than the current one (x86) - I switched after ~12M blocks or so - if memory serves. Could this be contributing to these issues?
post by d13co on Jan 25, 2022
Looks like it is syncing, albeit slowly. Not sure why it got stuck before but it seems over it. I wrote a script to monitor progress:
#!/bin/bash
sleep_duration=20m
while true; do
block=$(goal node status | grep Last\ commit | awk '{print $4}')
if [ -z "$block" ]; then
echo "no block"
sleep $sleep_duration
continue;
fi
epoch=$(date +%s)
date=$(date --utc)
if [ -z "$lastblock" ]; then
diff=0
speed=0
else
diff=$((block - lastblock))
elapsed=$((epoch - lastepoch))
speed=$((60 * diff / elapsed))
fi
echo "$epoch $date $block +$diff $speed/minute"
lastblock=$block
lastepoch=$epoch
sleep $sleep_duration
done
in case it is useful to anyone else.
My output is:
$ bash print-algod-progress.sh | tee -a algod-progress.log
1643121207 Di 25. Jan 14:33:27 UTC 2022 15014661 +0 0/minute
1643122417 Di 25. Jan 14:53:37 UTC 2022 15017662 +3001 148/minute
1643123619 Di 25. Jan 15:13:39 UTC 2022 15020677 +3015 150/minute
1643124823 Di 25. Jan 15:33:43 UTC 2022 15024672 +3995 199/minute
1643126057 Di 25. Jan 15:54:17 UTC 2022 15027858 +3186 154/minute
1643127262 Di 25. Jan 16:14:22 UTC 2022 15030774 +2916 145/minute
1643128471 Di 25. Jan 16:34:31 UTC 2022 15033943 +3169 157/minute
1643129675 Di 25. Jan 16:54:35 UTC 2022 15037121 +3178 158/minute
1643130876 Di 25. Jan 17:14:36 UTC 2022 15040375 +3254 162/minute
1643132076 Di 25. Jan 17:34:36 UTC 2022 15043735 +3360 168/minute
1643133280 Di 25. Jan 17:54:40 UTC 2022 15047366 +3631 180/minute
1643134484 Di 25. Jan 18:14:44 UTC 2022 15050383 +3017 150/minute
1643135688 Di 25. Jan 18:34:48 UTC 2022 15053128 +2745 136/minute
With algo at ~13 blocks/min it seems that it will finish sync in ~19 days. I can live with that but gosh, wasn’t expecting this endeavour to last from November to February!
Maybe a warning about HDD/SSD/NVMe would be helpful in the algod docs.
post by quentin101 on Jan 27, 2022
Since you are syncing an indexer at the same time (also since November?), did you see the announcement to update the indexer to 2.8.0, which requires reindexing everything from scratch? That’ll take weeks probably (it does for me) and I can’t wrap my head around the fact that there is just no way to speed this up (like, you know, have several instances to distribute the work for example).
post by d13co on Jan 27, 2022
Yes I was, but stopping the indexer had negligible effects on algod performance.
Thanks for the heads up! I did indeed restart indexing with 2.8.0 as it promises “Enhancements to import performance.”
With the previous indexer I could only manage 10-15 blocks a minute (at block height ~15M). So it would take me between 1-2 standard Eras to complete.
Regarding speeding up algod on slow disks:
A good option to save disk I/O is
"CadaverSizeTarget": 0,
This disables the cadaver file, which is only useful to debug the agreement protocol, per this question
Another tip that helped me a bit (I think - hard to say as there is variance in the speed between blocks anyhow) was to move the node.log file to a ramdisk and symlink it to the data dir, so that the log is written to RAM and doesn’t compete for I/O.
Something else I changed that I hope won’t bite me in the behind:
LedgerSynchronousMode: 0
This does:
// LedgerSynchronousMode defines the synchronous mode used by the ledger database. The supported options are:
// 0 - SQLite continues without syncing as soon as it has handed data off to the operating system.
// 1 - SQLite database engine will still sync at the most critical moments, but less often than in FULL mode.
// 2 - SQLite database engine will use the xSync method of the VFS to ensure that all content is safely written to the disk surface prior to continuing. On Mac OS, the data is additionally synchronized via fullfsync.
// 3 - In addition to what being done in 2, it provides additional durability if the commit is followed closely by a power loss.
// for further information see the description of SynchronousMode in dbutil.go
My full config can be found here
… the things we do.