Blocks syncing at a rate of 1 block every 1-5 minutes.

vkoskiv commented 6 years ago

Hello! First of all, big props to the geth dev team. You guys are doing amazing work!

A few weeks ago I managed to sync the full state, and keep it up for a day or so, but over the last two weeks, my full node has fallen behind more and more. I'm currently around a block depth of 4.97mill when the latest block is ~5.06mill. I am running geth 24/7 to try and keep up.

I just pulled the latest changes and tried again, but this didn't resolve my problem.

System information

Geth version: 1.8.0-unstable OS & Version: macOS 10.12.6 Sierra Commit hash : 42628ba7eda25830653763ced060f702861d0887

Speedtest stats Network speed: 91Mbps down, 90Mbps up Network latency: 1ms

Expected behaviour

Node syncing at a rate faster than or equal to average block time of ~15s

Actual behaviour

Node syncing at a rate of one block every 1-5 minutes.

Steps to reproduce the behaviour

Build with make all Run Geth with following args: ./geth --datadir=/my/mechanical/hard/disk --fast (I realize the --fast argument may be redundant given I've already got a large portion of the state synced)

I tried running on an SSD before, but that didn't seem to have any effect on the syncing speed.

Update:

I attempted to speed up the sync with the following args: ./geth --datadir=/my/mechanical/hard/disk --cache=2048 --cache.database=256 --cache.gc=128 Doing this had no effect on sync speed.

Also, I've been consistently getting the following errors and warnings: WARN [timestamp] Trie timing at dangerous levels ERROR [timestamp] Trie timing critical, forcing to disk I tried researching those, but I have no idea what they mean.

jcklpe commented 6 years ago

If you get any help let me know. I'm having similar issues. And it seems a lot of people on the gitter are too

larcai commented 6 years ago

+1 i have same issue

stepanhack commented 6 years ago

+1 Same issues with latest version :/

holiman commented 6 years ago

Some data that would be interesting to have, related to these reports:

When blocks are processed, what mgas/s is reported? Please provide snippets of the logs.
The disk speed. Can be checked by e.g. dd if=/dev/zero of=/tmp/output conv=fdatasync bs=384k count=1k; rm -f /tmp/output
Naturaly, the version. If you're running master, then also the commit hash. The original reporter reported 42628ba7eda25830653763ced060f702861d0887, which was committed on feb 9 and contains the intermediate memory pruning and sync fixes.

In the case of the original report, I am guessing the mgas/s value are quite low due to disk IO; but I can't really make a guess for the other reports.

vkoskiv commented 6 years ago

@holiman

Here's some logs:

INFO [02-15|10:54:18] Regenerated local transaction journal    transactions=0 accounts=0
INFO [02-15|10:54:54] Imported new chain segment               blocks=1 txs=79  mgas=7.966  elapsed=55.351s   mgasps=0.144 number=4985586 hash=6ed80d…bf0f8b cache=82.30mB
INFO [02-15|10:55:19] Imported new chain segment               blocks=1 txs=115 mgas=7.793  elapsed=25.106s   mgasps=0.310 number=4985587 hash=cbec5c…ff9150 cache=82.64mB
INFO [02-15|10:55:50] Imported new chain segment               blocks=1 txs=185 mgas=7.942  elapsed=31.582s   mgasps=0.251 number=4985588 hash=0c11b4…b1a3e3 cache=82.98mB
INFO [02-15|10:56:09] Imported new chain segment               blocks=1 txs=130 mgas=5.715  elapsed=18.211s   mgasps=0.314 number=4985589 hash=dce350…c747a6 cache=83.04mB
INFO [02-15|10:57:01] Imported new chain segment               blocks=2 txs=246 mgas=7.207  elapsed=52.132s   mgasps=0.138 number=4985591 hash=0f6197…e5d380 cache=83.65mB
INFO [02-15|10:57:59] Imported new chain segment               blocks=1 txs=230 mgas=7.974  elapsed=58.632s   mgasps=0.136 number=4985592 hash=24a594…94d499 cache=84.63mB
INFO [02-15|10:58:34] Imported new chain segment               blocks=1 txs=161 mgas=7.966  elapsed=34.632s   mgasps=0.230 number=4985593 hash=014693…b5adac cache=84.99mB
INFO [02-15|10:59:02] Imported new chain segment               blocks=1 txs=147 mgas=7.974  elapsed=28.077s   mgasps=0.284 number=4985594 hash=72e2db…c210d0 cache=85.33mB
INFO [02-15|10:59:47] Imported new chain segment               blocks=1 txs=130 mgas=7.980  elapsed=45.371s   mgasps=0.176 number=4985595 hash=cb81fc…9db3ee cache=85.69mB
INFO [02-15|11:00:26] Imported new chain segment               blocks=1 txs=292 mgas=7.994  elapsed=38.571s   mgasps=0.207 number=4985596 hash=a1969c…56137b cache=86.68mB
INFO [02-15|11:01:07] Imported new chain segment               blocks=1 txs=254 mgas=7.995  elapsed=41.269s   mgasps=0.194 number=4985597 hash=e7bf43…660ec4 cache=87.30mB
INFO [02-15|11:02:04] Imported new chain segment               blocks=1 txs=214 mgas=7.991  elapsed=56.595s   mgasps=0.141 number=4985598 hash=d087fa…938d49 cache=88.03mB
INFO [02-15|11:02:33] State in memory for too long, committing time=10m30.427340333s allowance=5m0s optimum=0.141
INFO [02-15|11:02:33] Persisted trie from memory database      nodes=19053 size=6.86mB   time=107.142312ms     gcnodes=10427 gcsize=4.56mB   gctime=22.453763ms livenodes=214047 livesize=81.68mB
INFO [02-15|11:02:34] Imported new chain segment               blocks=1 txs=116 mgas=7.976  elapsed=29.643s   mgasps=0.269 number=4985599 hash=6c3be6…de81b6 cache=81.68mB
INFO [02-15|11:03:03] Imported new chain segment               blocks=1 txs=190 mgas=7.997  elapsed=29.088s   mgasps=0.275 number=4985600 hash=25b76b…070d0b cache=82.04mB
INFO [02-15|11:03:40] Imported new chain segment               blocks=1 txs=34  mgas=7.996  elapsed=37.099s   mgasps=0.216 number=4985601 hash=952efc…696411 cache=81.98mB
INFO [02-15|11:04:35] Imported new chain segment               blocks=1 txs=83  mgas=7.922  elapsed=55.566s   mgasps=0.143 number=4985602 hash=3d5cd2…a22b91 cache=82.33mB
INFO [02-15|11:05:03] Imported new chain segment               blocks=1 txs=122 mgas=7.155  elapsed=27.354s   mgasps=0.262 number=4985603 hash=a861fd…133ef6 cache=82.34mB
INFO [02-15|11:05:32] Imported new chain segment               blocks=1 txs=43  mgas=4.384  elapsed=29.121s   mgasps=0.151 number=4985604 hash=38baf6…98d8c0 cache=82.28mB
INFO [02-15|11:06:08] Imported new chain segment               blocks=1 txs=162 mgas=7.990  elapsed=35.822s   mgasps=0.223 number=4985605 hash=fc80ca…fd267c cache=82.82mB
INFO [02-15|11:06:18] Imported new chain segment               blocks=1 txs=39  mgas=1.094  elapsed=10.123s   mgasps=0.108 number=4985606 hash=cf1461…0580a8 cache=82.67mB
INFO [02-15|11:06:50] Imported new chain segment               blocks=1 txs=89  mgas=3.263  elapsed=32.786s   mgasps=0.100 number=4985607 hash=accbe1…32ac7c cache=82.76mB
INFO [02-15|11:07:33] Imported new chain segment               blocks=1 txs=89  mgas=6.680  elapsed=42.710s   mgasps=0.156 number=4985608 hash=ff2a5f…b9994f cache=82.95mB
INFO [02-15|11:08:25] Imported new chain segment               blocks=1 txs=169 mgas=6.161  elapsed=51.851s   mgasps=0.119 number=4985609 hash=43e27e…95536a cache=83.66mB
INFO [02-15|11:08:37] Imported new chain segment               blocks=2 txs=101 mgas=2.436  elapsed=12.225s   mgasps=0.199 number=4985611 hash=95610f…8a04c1 cache=83.40mB
INFO [02-15|11:09:09] Imported new chain segment               blocks=1 txs=132 mgas=7.947  elapsed=31.711s   mgasps=0.251 number=4985612 hash=2a553b…76fc6d cache=83.50mB
INFO [02-15|11:10:00] Imported new chain segment               blocks=1 txs=142 mgas=7.970  elapsed=51.376s   mgasps=0.155 number=4985613 hash=f037fb…47ab51 cache=83.42mB
INFO [02-15|11:10:43] Imported new chain segment               blocks=1 txs=77  mgas=7.977  elapsed=42.332s   mgasps=0.188 number=4985614 hash=92d6a1…2f0f6c cache=83.43mB
INFO [02-15|11:10:51] Imported new chain segment               blocks=1 txs=65  mgas=1.858  elapsed=8.584s    mgasps=0.216 number=4985615 hash=4952f0…8617ae cache=83.18mB
INFO [02-15|11:11:39] Imported new chain segment               blocks=1 txs=237 mgas=6.769  elapsed=47.492s   mgasps=0.143 number=4985616 hash=7ebe58…1d8aae cache=83.53mB
INFO [02-15|11:12:01] Imported new chain segment               blocks=1 txs=65  mgas=2.973  elapsed=22.743s   mgasps=0.131 number=4985617 hash=873f88…43c147 cache=83.70mB
INFO [02-15|11:13:03] Imported new chain segment               blocks=1 txs=106 mgas=7.959  elapsed=1m1.121s  mgasps=0.130 number=4985618 hash=25f9e6…c0f01f cache=83.72mB
INFO [02-15|11:14:14] State in memory for too long, committing time=10m56.453822366s allowance=5m0s optimum=0.156
INFO [02-15|11:14:15] Persisted trie from memory database      nodes=25257 size=9.03mB   time=1.412785853s     gcnodes=16711 gcsize=7.26mB   gctime=33.457501ms livenodes=198859 livesize=75.84mB
INFO [02-15|11:14:15] Imported new chain segment               blocks=1 txs=230 mgas=7.973  elapsed=1m12.734s mgasps=0.110 number=4985619 hash=efe6f8…707ce4 cache=75.84mB
INFO [02-15|11:15:13] Imported new chain segment               blocks=1 txs=262 mgas=8.000  elapsed=57.164s   mgasps=0.140 number=4985620 hash=1c33fc…0070d3 cache=76.63mB
INFO [02-15|11:16:18] Imported new chain segment               blocks=1 txs=191 mgas=7.954  elapsed=1m5.599s  mgasps=0.121 number=4985621 hash=38540d…ff5f04 cache=77.53mB
INFO [02-15|11:17:16] Imported new chain segment               blocks=1 txs=245 mgas=7.912  elapsed=58.299s   mgasps=0.136 number=4985622 hash=3df3cd…f5371b cache=78.25mB
INFO [02-15|11:17:29] Imported new chain segment               blocks=1 txs=58  mgas=4.223  elapsed=12.320s   mgasps=0.343 number=4985623 hash=615f8c…fd8a75 cache=78.28mB
INFO [02-15|11:17:39] Imported new chain segment               blocks=1 txs=59  mgas=7.998  elapsed=9.990s    mgasps=0.801 number=4985624 hash=3e6c94…18604d cache=78.36mB
INFO [02-15|11:17:58] Imported new chain segment               blocks=1 txs=115 mgas=6.804  elapsed=19.688s   mgasps=0.346 number=4985625 hash=0388a6…9fa39b cache=78.49mB
INFO [02-15|11:18:09] Imported new chain segment               blocks=1 txs=38  mgas=1.417  elapsed=11.035s   mgasps=0.128 number=4985626 hash=40980d…f62f14 cache=78.39mB
INFO [02-15|11:18:18] Imported new chain segment               blocks=1 txs=32  mgas=1.271  elapsed=8.767s    mgasps=0.145 number=4985627 hash=01b220…b9cea6 cache=78.38mB
INFO [02-15|11:18:51] Imported new chain segment               blocks=1 txs=103 mgas=7.929  elapsed=33.207s   mgasps=0.239 number=4985628 hash=f2be09…83a68f cache=78.89mB
INFO [02-15|11:19:14] Imported new chain segment               blocks=1 txs=95  mgas=7.802  elapsed=22.717s   mgasps=0.343 number=4985629 hash=822db6…6019af cache=79.21mB
INFO [02-15|11:19:51] Imported new chain segment               blocks=2 txs=139 mgas=9.876  elapsed=37.299s   mgasps=0.265 number=4985631 hash=1f75dc…6164f3 cache=79.60mB
INFO [02-15|11:21:30] Imported new chain segment               blocks=3 txs=266 mgas=8.751  elapsed=1m38.080s mgasps=0.089 number=4985634 hash=bb78db…02c36a cache=79.04mB
INFO [02-15|11:22:38] Imported new chain segment               blocks=1 txs=188 mgas=7.974  elapsed=1m8.321s  mgasps=0.117 number=4985635 hash=e84223…f0e807 cache=79.44mB
INFO [02-15|11:23:12] Imported new chain segment               blocks=1 txs=103 mgas=7.944  elapsed=34.344s   mgasps=0.231 number=4985636 hash=4bb6b6…b8104c cache=79.68mB
INFO [02-15|11:24:08] State in memory for too long, committing time=10m6.843867183s  allowance=5m0s optimum=0.141
INFO [02-15|11:24:18] Persisted trie from memory database      nodes=20503 size=7.34mB   time=9.703933861s     gcnodes=11607 gcsize=5.05mB   gctime=24.673133ms livenodes=191216 livesize=73.08mB
INFO [02-15|11:24:19] Imported new chain segment               blocks=1 txs=192 mgas=7.933  elapsed=1m6.332s  mgasps=0.120 number=4985637 hash=9d90f3…fcd57c cache=73.08mB
INFO [02-15|11:24:39] Imported new chain segment               blocks=1 txs=72  mgas=2.154  elapsed=20.223s   mgasps=0.107 number=4985638 hash=9b8379…c852b4 cache=73.39mB
INFO [02-15|11:25:32] Imported new chain segment               blocks=1 txs=75  mgas=7.986  elapsed=53.575s   mgasps=0.149 number=4985639 hash=838c39…8a4b8f cache=73.70mB
INFO [02-15|11:26:50] Imported new chain segment               blocks=1 txs=107 mgas=7.899  elapsed=1m17.355s mgasps=0.102 number=4985640 hash=2ae96d…52ad17 cache=74.42mB
INFO [02-15|11:27:31] Imported new chain segment               blocks=1 txs=117 mgas=7.836  elapsed=41.499s   mgasps=0.189 number=4985641 hash=fa38b0…a0326f cache=74.85mB
INFO [02-15|11:27:52] Imported new chain segment               blocks=1 txs=58  mgas=2.608  elapsed=20.511s   mgasps=0.127 number=4985642 hash=7a0e17…6a74c6 cache=75.15mB
INFO [02-15|11:28:33] Imported new chain segment               blocks=2 txs=138 mgas=7.843  elapsed=41.243s   mgasps=0.190 number=4985644 hash=24e6da…dfcc35 cache=75.41mB
INFO [02-15|11:29:21] Imported new chain segment               blocks=1 txs=124 mgas=5.636  elapsed=48.021s   mgasps=0.117 number=4985645 hash=c59051…63aabf cache=75.78mB
INFO [02-15|11:29:36] Imported new chain segment               blocks=1 txs=44  mgas=3.046  elapsed=15.144s   mgasps=0.201 number=4985646 hash=ad0015…3c8960 cache=75.81mB

Currently running commit hash 0544a43c1332871405b260432db4bfe6a591feee

I couldn't get your dd command working, so I just ran the BlackMagic disk speed test. I got 23MB/s write, and 32MB/s write. I think the drive is a Seagate barracuda of some sort.

holiman commented 6 years ago

Yep, you have a way too low mgasps, in the 0.1 area. That basically means that the computer can only process about 100K gas per second. The current gas limit is ~8M, so processing one such block takes very long time on your machine (times vary between 20s and over one minute). Thus, with a blocktime of 14 seconds, you're not catching up.

At least we can rule out p2p-issues -- the problem is not getting blocks, it's processing them.

And the reason, I'd guess, is disk IO. For reference, on my pretty new:ish SSD, I get:

#dd if=/dev/zero of=/tmp/output conv=fdatasync bs=384k count=1k; rm -f /tmp/output
1024+0 records in
1024+0 records out
402653184 bytes (403 MB, 384 MiB) copied, 0,974342 s, 413 MB/s

That's one order of magnitude faster. 23/32 is about what you would get over USB, so that's very likely the bottleneck in this case.

I had similar (low) numbers on my previous SSD disk -- they degrade quite heavily over time (technically degrade by writes). So, unfortunately, if it's SSD - time to replace it. If it's HDD - time to swap it for an SSD.

jcklpe commented 6 years ago

I am also having a similar problem @holiman Do I just copy paste this? dd if=/dev/zero of=/tmp/output conv=fdatasync bs=384k count=1k; rm -f /tmp/output into my terminal and run it? I'm on windows but I've got Bash for Windows running in Hyperterm so I can do any bash commands, but I just wanted to make sure if this would also work for windows etc.

holiman commented 6 years ago

No, won't work on windows...

holiman commented 6 years ago

At least not afaik

csknk commented 6 years ago

For what it's worth I spent quite a bit of time trying to sync onto a HDD, but the disk IO just doesn't cut it. As @holiman says USB connected disks have much slower IO. I tried geth 1.8.0 but this didn't make much difference. I have a new 1TB SSD on order - hopefully this will future proof my node for a while!

I think SATA connected SSD is the only way to go - unfortunate since it adds quite a bit of expense.

Good luck

paigeweber13 commented 6 years ago

@thedonquixotic this won't work in bash for windows, as bash for windows has well-documented issues with disk I/O. Basically it'll just report a very, very slow speed, even if applications run natively in windows would have a much higher speed. You could try using dd with cygwin or mingwin, but I can't speak to the disk I/O speed using those tools.

paigeweber13 commented 6 years ago

@holiman excuse my ignorance... what is processing a block? I mined some ethereum last year and never did anything with it. I want to transfer it to an exchange now. I have a small SSD and might be able to clear up enough space for the blockchain, but I don't want to if it isn't necessary. Do I have to process the blocks to access my balance and make the transfer?

jcklpe commented 6 years ago

@brianweber13

Yes that's true but I'm running geth.exe inside command line, not through WSL. So that I/O issue shouldn't really apply.

On Mon, Feb 19, 2018 at 1:29 PM brianweber13 notifications@github.com wrote:

@thedonquixotic https://github.com/thedonquixotic this won't work in bash for windows, as it has well-documented issues https://github.com/Microsoft/WSL/issues/873 with disk I/O. Basically it'll just report a very, very slow speed, even if applications run natively in windows would have a much higher speed. You could try using dd with cygwin or mingwin, but I can't speak to the disk I/O speed using those tools.

— You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub https://github.com/ethereum/go-ethereum/issues/16053#issuecomment-366784116, or mute the thread https://github.com/notifications/unsubscribe-auth/AJA4zmDqcPKXB5gpuPbF0LkhixChtVAsks5tWcumgaJpZM4SApcH .

vkoskiv commented 6 years ago

@brianweber13 You can sync in light mode with the argument --syncmode="light" In any case, you can transact without syncing the entire blockchain. Your funds are tied to your private key.

paigeweber13 commented 6 years ago

@thedonquixotic you asked

Do I just copy paste this? dd if=/dev/zero of=/tmp/output conv=fdatasync bs=384k count=1k; rm -f /tmp/output into my terminal and run it? I'm on windows but I've got Bash for Windows running in Hyperterm so I can do any bash commands, but I just wanted to make sure if this would also work for windows etc.

I was responding to your question about dd. Running dd in WSL will give you no useful information in your case.

paigeweber13 commented 6 years ago

@VKoskiv so even if geth displays my balances incorrectly, I can still make a transaction?

vkoskiv commented 6 years ago

@brianweber13 You should be able to, yes. It's up to the other (hopefully up to date) nodes to actually verify your transaction. If there's more recent inputs that your geth instance isn't aware of however, then it can't include those in the transaction.

holiman commented 6 years ago

@brianweber13 yes. The only thing you'll need that a fully synced node would give you is

The account nonce (number of previous outgoing transactions made)
An estimated gas price
An estimated gas amount

If you want to make a simpel transfer of ether, you can do e.g.

> personal.signTransaction({ to : "0x..<toaddress>", from "0x..<from>", nonce: 1, gas: 21000, gasPrice : <gasPrice>}, "yourpassword" )

You can lookup a good gasprice on https://ethgasstation.info/ (currently 2 Gwei is 'safe low', so 2000000000).

That will give you a signed transaction, ready to be broadcast. You can do that on e.g. MEW offline transaction https://www.myetherwallet.com/#offline-transaction .

NOTE: I may have mistyped something above, please verify all details. And remember that you are responsible for your funds.

paigeweber13 commented 6 years ago

@holiman @VKoskiv thank you both for all your help.

jcklpe commented 6 years ago

Ah but if there is a geth.exe for windows shouldn't there be a CLI equivalent syntax for cmd.exe?

On Mon, Feb 19, 2018 at 2:12 PM brianweber13 notifications@github.com wrote:

@thedonquixotic https://github.com/thedonquixotic you asked

Do I just copy paste this? dd if=/dev/zero of=/tmp/output conv=fdatasync bs=384k count=1k; rm -f /tmp/output into my terminal and run it? I'm on windows but I've got Bash for Windows running in Hyperterm so I can do any bash commands, but I just wanted to make sure if this would also work for windows etc.

I was responding to your question about dd. Running dd in WSL will give you no useful information in your case.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/ethereum/go-ethereum/issues/16053#issuecomment-366792338, or mute the thread https://github.com/notifications/unsubscribe-auth/AJA4zk1STNQY8kmiMbebG7ICYRme1tP-ks5tWdWngaJpZM4SApcH .

paigeweber13 commented 6 years ago

@thedonquixotic dd is entirely unrelated to geth. It is part of the GNU coreutils, and in this case, it is being used to measure your disk speed. There are surely many programs you can use on windows to measure disk speed, just do a quick google search.

jcklpe commented 6 years ago

Ah gotcha thanks.

On Mon, Feb 19, 2018 at 2:42 PM brianweber13 notifications@github.com wrote:

@thedonquixotic https://github.com/thedonquixotic dd is entirely unrelated to geth. It is part of the GNU coreutils, and in this case, it is being used to measure your disk speed. There are surely many programs you can use on windows to measure disk speed, just do a quick google search.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/ethereum/go-ethereum/issues/16053#issuecomment-366798131, or mute the thread https://github.com/notifications/unsubscribe-auth/AJA4zvdbbinBcdypfFY8izniL9RYqNmdks5tWdzGgaJpZM4SApcH .

randydu commented 6 years ago

I've the same issue running geth v1.8.1 on a EC2 t2.small instance (1CPU, 2G RAM + 120G SSD), after upgrading to t2.medium (2CPU, 4G RAM + 120G SSD) it syncs very quickly. Out of curiosity to know how the data access speed could make any difference, I copy the sync data to a 500G HD and continue syncing on the HD, then the issue occurs again, the mgasps value becomes so small (~ 0.xxx) that it will never catch up with the latest blocks ----- so the minimum spec for geth syncing is: 4G RAM + SSD. Hopefully my experience can save your time playing with geth.

CryptoKiddies commented 6 years ago

geth v1.8.10 is running very efficiently everyone. I recommend the update. Handles high txn loads well.

holiman commented 5 years ago

Seems resolved

ethereum / go-ethereum