Generating snapshots makes geth slow

[elsampsa]

I'm experiencing a slow-down due to snapshot generation. Snapshot generation takes ages (the estimated time just keeps growing) and the blockchain sync slows down as well.

System information

Geth version: Geth/v1.10.10-stable-bb74230f/linux-amd64/go1.15.6
OS & Version: Linux
Commit hash : (not develop)

Expected behaviour

• Sync not starting to lag behind
• Snapshot generated in a matter of few days

Actual behaviour

• When snapshot gen is enabled, the synchronization starts to creep and lag behind.
• Estimated time for snaphot completion keeps on creeping up

Steps to reproduce the behaviour

Run geth in a laptop with:

• 8 x Intel(R) Core(TM) i7-4700HQ CPU @ 2.40GHz
• 2TB SSD drive: "Crucial BX500"
• 12 GB RAM (& all the swap you could wish for)

nice -n 5 go-ethereum/build/bin/geth --datadir.ancient=/mnt/hdd/ancient --syncmode=full --gcmode=full --cache=2048 --maxpeers=50 --snapshot=true --txlookuplimit=0

Backtrace

INFO [11-08|20:21:25.087] Resuming state snapshot generation       root=85b967..037d98 at=004c78..040c78 accounts=177,869 slots=974,903 storage=77.78MiB elapsed=38m11.550s eta=544h52m33.234s
INFO [11-08|20:21:25.090] Imported new chain segment               blocks=1 txs=375  mgas=30.028 elapsed=28.038s    mgasps=1.071   number=13,577,264 hash=2bdcca..8de18c age=11m29s   dirty=226.78MiB

ETA for snapshots keeps on growing, so does the "age" for the chain segments.

[elsampsa]

found a related issue: #23114

..compared to that (& if I got it right), in my case the blocks complete faster.

I set cache to 4096 & now the log look slightly different.. no crazy estimated times anymore, but block sync still lags behind.

...
INFO [11-08|21:10:09.900] Aborting state snapshot generation       root=636f6c..0c4588 at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=17m19.062s
INFO [11-08|21:10:09.900] Resuming state snapshot generation       root=77d32e..ad8b9f at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=17m19.063s
INFO [11-08|21:10:09.903] Imported new chain segment               blocks=1 txs=102 mgas=7.904  elapsed=13.063s    mgasps=0.605 number=13,577,449 hash=07903f..a5952f age=19m52s   dirty=132.63MiB
INFO [11-08|21:10:23.116] Aborting state snapshot generation       root=77d32e..ad8b9f at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=17m32.279s
INFO [11-08|21:10:23.117] Resuming state snapshot generation       root=307b7a..e6c5ed at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=17m32.279s
INFO [11-08|21:10:23.119] Imported new chain segment               blocks=1 txs=89  mgas=9.522  elapsed=13.216s    mgasps=0.720 number=13,577,450 hash=e9db7a..6e5fc4 age=20m1s    dirty=133.68MiB
INFO [11-08|21:10:36.312] Aborting state snapshot generation       root=307b7a..e6c5ed at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=17m45.475s
INFO [11-08|21:10:36.313] Resuming state snapshot generation       root=9262ac..f1e5ef at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=17m45.475s
INFO [11-08|21:10:36.315] Imported new chain segment               blocks=1 txs=271 mgas=20.193 elapsed=13.196s    mgasps=1.530 number=13,577,451 hash=0f544d..78b9b4 age=20m8s    dirty=136.15MiB
INFO [11-08|21:10:46.009] Deep froze chain segment                 blocks=4 elapsed=18.185ms   number=13,487,451 hash=e7d321..322636
INFO [11-08|21:10:49.548] Aborting state snapshot generation       root=9262ac..f1e5ef at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=17m58.710s
INFO [11-08|21:10:49.548] Resuming state snapshot generation       root=459a7b..dba245 at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=17m58.711s
INFO [11-08|21:10:49.550] Imported new chain segment               blocks=1 txs=149 mgas=10.399 elapsed=13.234s    mgasps=0.786 number=13,577,452 hash=e5bc8e..ca52bb age=20m9s    dirty=137.43MiB
ERROR[11-08|21:10:55.620] Snapshot extension registration failed   peer=1d11e356 err="peer connected on snap without compatible eth support"
INFO [11-08|21:11:02.484] Aborting state snapshot generation       root=459a7b..dba245 at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=18m11.646s
INFO [11-08|21:11:02.484] Resuming state snapshot generation       root=f6b577..b0533f at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=18m11.647s
INFO [11-08|21:11:02.487] Imported new chain segment               blocks=1 txs=96  mgas=5.837  elapsed=12.936s    mgasps=0.451 number=13,577,453 hash=7d4bae..16a8f0 age=20m4s    dirty=138.30MiB
INFO [11-08|21:11:15.597] Aborting state snapshot generation       root=f6b577..b0533f at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=18m24.760s
INFO [11-08|21:11:15.598] Resuming state snapshot generation       root=54890b..926f33 at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=18m24.760s
INFO [11-08|21:11:15.600] Imported new chain segment               blocks=1 txs=396 mgas=29.742 elapsed=13.113s    mgasps=2.268 number=13,577,454 hash=56d5a2..1f9873 age=20m12s   dirty=141.64MiB
INFO [11-08|21:11:28.861] Aborting state snapshot generation       root=54890b..926f33 at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=18m38.023s
INFO [11-08|21:11:28.861] Resuming state snapshot generation       root=851418..8d0544 at=004c78..040c78 accounts=177,869 slots=987,154 storage=78.61MiB elapsed=18m38.023s
INFO [11-08|21:11:28.866] Imported new chain segment               blocks=1 txs=495 mgas=30.005 elapsed=13.265s    mgasps=2.262 number=13,577,455 hash=580940..cd1c17 age=20m7s    dirty=144.90MiB
...

EDIT I take that back, same error still:

INFO [11-08|22:43:58.177] Aborting state snapshot generation       root=197318..64ce2b at=004cdc..828cd9 accounts=178,779 slots=994,256 storage=79.13MiB elapsed=1h51m7.340s  eta=311773h42m50.901s                                          
INFO [11-08|22:43:58.177] Resuming state snapshot generation       root=719dd2..aefe56 at=004cdc..828cd9 accounts=178,779 slots=994,256 storage=79.13MiB elapsed=1h51m7.340s  eta=311773h42m50.901s                                          
INFO [11-08|22:43:58.183] Imported new chain segment               blocks=1 txs=201 mgas=13.956 elapsed=17.332s      mgasps=0.805 number=13,577,814 hash=ccc70e..fba304 age=27m44s   dirty=403.20MiB

[rjl493456442]

@elsampsa Looks like you are running an archive node. Since you are upgrading from a legacy database(by enable the snapshot), so it's extremely slow for regeneration.

In order to speedup the snapshot generation, one trick you can apply is:

• sync a new geth node in syncmode=snap mode.
• export the snapshot data from that synced node by command geth db export --datadir <path_to_your_fresh_synced_node> snapshot snapshot.data.gz
• import the exported snapshot data into your archive node by command geth db import --datadir <path_to_your_archive_node> snapshot.data.gz

After that your snapshot will be rebuilt. However with the help of existent snapshot data it can save you a lot of time for regeneration.

[elsampsa]

My geth cli arguments are:

--syncmode=full --gcmode=full

According to geth:

--gcmode value       Blockchain garbage collection mode ("full", "archive") (default: "full")

So I'd need to use "archive" to have an archive node..? I think my node is just a regular "full" node, not an archive node..?

But anyway, thanks for the tip. I will try it for sure.

[rjl493456442]

Ah right. It's a normal full node. My bad.

[holiman]

INFO [11-08|21:10:09.903] Imported new chain segment               blocks=1 txs=102 mgas=7.904  elapsed=13.063s    mgasps=0.605 number=13,577,449 hash=07903f..a5952f age=19m52s   dirty=132.63MiB
INFO [11-08|21:10:23.119] Imported new chain segment               blocks=1 txs=89  mgas=9.522  elapsed=13.216s    mgasps=0.720 number=13,577,450 hash=e9db7a..6e5fc4 age=20m1s    dirty=133.68MiB
INFO [11-08|21:10:36.315] Imported new chain segment               blocks=1 txs=271 mgas=20.193 elapsed=13.196s    mgasps=1.530 number=13,577,451 hash=0f544d..78b9b4 age=20m8s    dirty=136.15MiB
INFO [11-08|21:10:49.550] Imported new chain segment               blocks=1 txs=149 mgas=10.399 elapsed=13.234s    mgasps=0.786 number=13,577,452 hash=e5bc8e..ca52bb age=20m9s    dirty=137.43MiB
INFO [11-08|21:11:02.487] Imported new chain segment               blocks=1 txs=96  mgas=5.837  elapsed=12.936s    mgasps=0.451 number=13,577,453 hash=7d4bae..16a8f0 age=20m4s    dirty=138.30MiB
INFO [11-08|21:11:15.600] Imported new chain segment               blocks=1 txs=396 mgas=29.742 elapsed=13.113s    mgasps=2.268 number=13,577,454 hash=56d5a2..1f9873 age=20m12s   dirty=141.64MiB
INFO [11-08|21:11:28.866] Imported new chain segment               blocks=1 txs=495 mgas=30.005 elapsed=13.265s    mgasps=2.262 number=13,577,455 hash=580940..cd1c17 age=20m7s    dirty=144.90MiB

This is interesting -- block import times are 12-13 seconds per block. There is a thrashing-component when doing snapshot generation simultaneously as importing blocks, which I tried to address in #23728 . However, that PR is incomplete and would not help you.

So blocks are being imported really slowly. A few things would be interesting to know:

• What is the size of your leveldb data?
• Do you know anything about the effective disk IO speeds? Done any speed-checks?

Also, @rjl493456442 's trick is good. Another thing you might try is to run it in --nodiscover --maxpeers 0, making it do only snapshot generation, and not simultaneously import any blocks.

A third thing we could test is to hook it up to our graphing endpoint, and see there if we can detect what the anomaly comes from.

[elsampsa]

Chaindata in dev/sdb, ancient data in dev/sda

Read speed test:

sampsa@sampsa-asus:~$ sudo hdparm -Tf /dev/sdb
/dev/sdb:
 Timing cached reads:   21648 MB in  1.99 seconds = 10880.31 MB/sec

sampsa@sampsa-asus:~$ sudo hdparm -Tf /dev/sda
/dev/sda:
 Timing cached reads:   20190 MB in  1.99 seconds = 10140.64 MB/sec

Write speed test I'd rather not do..

Disk usage:

sampsa@sampsa-asus:~$ du -S -h .ethereum/geth/chaindata
1,4T    .ethereum/geth/chaindata
sampsa@sampsa-asus:~$ du -S -h /mnt/hdd/ancient
263G    /mnt/hdd/ancient

It's a "full" node that's been running for few years.. never did re-fast-sync or anything like that. Maybe that's the problem?

It's now doing that offline snapshot generation as you suggested. Will let you know then.

[holiman]

never did re-fast-sync or anything like that. Maybe that's the problem?

Yes, the size has grown to 1,4T . With a database that large, leveldb is doing a lot of work to keep up. A re-sync would likely solve the problems. You would lose a lot of state, naturally, but it seems that even with the current ssd speeds ( which seem pretty good), the disk IO isn't sufficient.

[elsampsa]

I wish I could connect with my own node to my own node for a fast re-sync (a slight pun intended). If I do that snapshot import trick as discussed above, that will solve all my performance issues I guess..?

[holiman]

If I do that snapshot import trick as discussed above, that will solve all my performance issues I guess..?

Unfortunately not.
It will make read-access faster, so the reads when executing blocks will increase. However, at the end of the block, the state trie root needs to be calculated/verified, and for this, the snapshot data is not sufficient - for this, trie data is needed. So that bloated 1.4T database will still cause problems.

[elsampsa]

So, the only way to keep the db "non-bloated" & fast, is to perform periodically a "fast sync". hmm.. if everyone does that, then it means that eventually the global network will only consist of fast-synced nodes. I guess that't not a problem..? I guess somebody has the complete state trie somewhere.. eeh.. what do I know. I'm just an old guy with an old laptop. :-)

[holiman]

I guess somebody has the complete state trie somewhere..

Just to clarify -- it doesn't matter if anybody does. If I want to know what the state was at block 5M, then I can always re-execute from genesis to obtain it. Might take me a few days (or a week for later >12M blocks), but it's not 'gone'. State is derived from block progression

[rjl493456442]

@elsampsa Yes it's not good for accumulating "junk" states all the time. However I am working a new state scheme recently, with the new scheme all the stale states will be pruned by default. It means you can enjoy a full node with low state growth rate. Unfortunately this big change still needs time to be finished/reviewed/tested. Hopefully we can ship it as soon as possible.

[rjl493456442]

@elsampsa In case you want to play my trick, don't forget to sync your new node with this mode "syncmode=snap", not the legacy fast sync! Also I don't think your node can serve the new snap sync since your snapshot is not generated yet.

But snap sync is faster than fast sync, so even sync with public network is supposed to be working.

[elsampsa]

Thank you for taking the time to explain me the basics.

Now I (sort of) get that..

Slowdown: when a new block arrives, it must be verified. For verification, we need the state. Geth needs to crunch throught the whole database to get the (partial?) state (i) for the accounts that are being permutated by the new block. However, if there is a snapshot of the complete state, then no need to crunch through the whole database (=fast).

Or (ii) alternatively to (i), for a full node that's been running for ages, there is a complete state trie, but it's been constructed in an unoptimal way..? So geth needs more time to crunch through it.

Looking forward to that new state scheme update..! Please feel free to close this ticket now. :) (woops.. I closed it accidentally myself)

[holiman]

My explanation was not fully correct.

Whenever we want to process a new block, we need to read a lot of state. Historically, we've looked up e.g. an account by iterating the trie, meaning that each account lookup takes maybe ~7 db lookups.

With snapshots, it's more of a O(1) db-lookup, so that's faster. However, when the trie root is calculated, we still need to lookup a lot of trie nodes.

So snapshots makes it faster, but if you have a very large DB, even if we reduce the number of lookups, it may still be too slow. Because the db becomes less efficient, basically - the trie keys are spread all over the disk, and the caches/bloomfilters aren't as effective as they would be on a smaller dataset.

[elsampsa]

"the trie keys are spread all over the disk".. this sound similar normal filesystem fragmentation.. could one make a "defrag" on the trie..?

[Kevostos]

Same issue: my snap node keeps getting behind since it is generating snapshots. The completion ETA is between 300h and 3000h on an i3.xlarge AWS machine, which seems odd. How to speed this up? Can the snapshot be downloaded?