Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Light node using too much storage, doing fast sync? (after 1.9.17) #22151

Closed
joeytwiddle opened this issue Jan 9, 2021 · 15 comments
Closed

Light node using too much storage, doing fast sync? (after 1.9.17) #22151

joeytwiddle opened this issue Jan 9, 2021 · 15 comments
Labels

Comments

@joeytwiddle
Copy link
Contributor

joeytwiddle commented Jan 9, 2021

Related: #22128

Situation

Starting from scratch (completely removed ~/.ethereum* folders)

Command: geth --syncmode light

The full setup I am using (probably not relevant):

  cpulimit -i -l 5 \
  trickle -d 20 -u 20 \
  geth --syncmode light \
    --datadir "$HOME/.ethereum-mainnet" \
    --port 20202 \
    --rpc --rpcaddr XX.XX.XX.XX --rpcport 28545 --rpcapi personal,web3,eth \
    --ws --wsaddr XX.XX.XX.XX --wsport 28546 --wsapi personal,web3,eth \
  | tee geth-output.log

I'm actually limiting the process somewhat, to reduce my AWS bill.

Behaviour with geth v1.9.17

The node syncs up in under 3 hours. Disk usage is 500MB. 👍

(9 hours later, the usage has dropped to 324 MB.)

Behaviour with geth v1.9.25

Sync takes longer. After many hours (maybe 24) the disk usage is 1.9GB. 👎

I see in the logs Imported new block headers. But we should only see that for fast/full nodes, right? Edit: Disregard. As Marius pointed out, the logs are expected for light nodes too.

(I see those same logs with v1.9.22 and v1.9.23, but I haven't checked to see if they also consume a lot of disk space.)

Possible regression?

Has there been a regression, whereby the light node now uses more disk space than it used to, more than it needs? Is it doing a full or fast sync?

If so, I suspect the regression was introduced > v1.9.19 and <= v1.9.22.

(I am guessing that v1.9.19 is also working fine, because I recall I used to use that version happily. But I haven't actually tested to confirm that.)

@MariusVanDerWijden
Copy link
Member

I synced a les node this week with the current master in 8 minutes and 300MB.
The LES node downloads the headers since the last checkpoint, so the imported new block headers is expected

@holiman
Copy link
Contributor

holiman commented Jan 10, 2021 via email

@joeytwiddle
Copy link
Contributor Author

joeytwiddle commented Jan 10, 2021

Sorry for the confusion holiman, but yes I have been wiping the correct folder ~/.ethereum-mainnet (not as root).

Thanks for testing Marius, that's good to know. You are right, those logs appear in both the old and new versions. Never mind those logs then, I was mistaken.

It still seems to me that v1.9.17 is using less disk space than v1.9.25. In fact the disk usage sometimes shrinks over time. Could it be that v1.9.17 is collecting garbage more efficiently than v1.9.25 is?

I will run against the github version 89030ec now, and see how that goes.

Startup with 89030ec looks like:

INFO [01-10|11:16:49.250] Starting Geth on Ethereum mainnet...
INFO [01-10|11:16:49.251] Dropping default light client cache      provided=1024 updated=128
INFO [01-10|11:16:49.252] Maximum peer count                       ETH=0 LES=10 total=50
WARN [01-10|11:16:49.252] The flag --rpc is deprecated and will be removed in the future, please use --http
WARN [01-10|11:16:49.253] The flag --rpcaddr is deprecated and will be removed in the future, please use --http.addr
WARN [01-10|11:16:49.253] The flag --rpcport is deprecated and will be removed in the future, please use --http.port
WARN [01-10|11:16:49.253] The flag --rpcapi is deprecated and will be removed in the future, please use --http.api
WARN [01-10|11:16:49.253] The flag --wsaddr is deprecated and will be removed in the future, please use --ws.addr
WARN [01-10|11:16:49.253] The flag --wsport is deprecated and will be removed in the future, please use --ws.port
WARN [01-10|11:16:49.254] The flag --wsapi is deprecated and will be removed in the future, please use --ws.api
INFO [01-10|11:16:49.254] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
ERROR[01-10|11:16:49.254] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|11:16:49.255] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|11:16:49.255] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|11:16:49.255] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|11:16:49.255] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|11:16:49.256] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
INFO [01-10|11:16:49.256] Set global gas cap                       cap=25000000
INFO [01-10|11:16:49.256] Allocated cache and file handles         database=/home/geth-lite/.ethereum-mainnet/geth/lightchaindata cache=64.00MiB handles=2048
INFO [01-10|11:16:49.264] Allocated cache and file handles         database=/home/geth-lite/.ethereum-mainnet/geth/lespay cache=16.00MiB handles=16
INFO [01-10|11:16:49.270] Writing default main-net genesis block
ERROR[01-10|11:16:50.567] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|11:16:50.568] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|11:16:50.568] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
INFO [01-10|11:16:53.598] Persisted trie from memory database      nodes=12356 size=1.78MiB time=1.151461504s gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
INFO [01-10|11:16:53.598] Initialised chain configuration          config="{ChainID: 1 Homestead: 1150000 DAO: 1920000 DAOSupport: true EIP150: 2463000 EIP155: 2675000 EIP158: 2675000 Byzantium: 4370000 Constantinople: 7280000 Petersburg: 7280000 Istanbul: 9069000, Muir Glacier: 9200000, YOLO v2: <nil>, Engine: ethash}"
INFO [01-10|11:16:53.599] Disk storage enabled for ethash caches   dir=/home/geth-lite/.ethereum-mainnet/geth/ethash count=3
INFO [01-10|11:16:53.599] Disk storage enabled for ethash DAGs     dir=/home/geth-lite/.ethash count=2
INFO [01-10|11:16:53.791] Added trusted checkpoint                 block=11337727 hash="5453ba…d0ef28"
INFO [01-10|11:16:53.791] Loaded most recent local header          number=0 hash="d4e567…cb8fa3" td=17179869184 age=51y9mo1w
INFO [01-10|11:16:53.792] Configured checkpoint registrar          address=0x9a9070028361F7AAbeB3f2F2Dc07F82C4a98A02a signers=5 threshold=2
WARN [01-10|11:16:53.792] Error reading unclean shutdown markers   error="leveldb: not found"
INFO [01-10|11:16:53.792] Starting peer-to-peer node               instance=Geth/v1.9.26-unstable-89030ec0-20210109/linux-amd64/go1.15.5
INFO [01-10|11:16:54.101] UDP listener up                          net=enode://6b472b857d3c0e093d984c089d56c870fb0367414fd01b2053699c44f4523735ed1b0e8d1dc1937e1203e538371a4c9a434526ca46d752b3f4b7383dc1bff4fa@[::]:20202
INFO [01-10|11:16:54.104] IPC endpoint opened                      url=/home/geth-lite/.ethereum-mainnet/geth.ipc
INFO [01-10|11:16:54.199] HTTP server started                      endpoint=172.31.42.120:28545 cors= vhosts=localhost
INFO [01-10|11:16:54.205] WebSocket enabled                        url=ws://172.31.42.120:28546
WARN [01-10|11:16:54.205] Light client mode is an experimental feature
INFO [01-10|11:16:54.205] New local node record                    seq=1 id=9443111b6684df24 ip=127.0.0.1 udp=20202 tcp=20202
INFO [01-10|11:16:54.206] Started P2P networking                   self=enode://6b472b857d3c0e093d984c089d56c870fb0367414fd01b2053699c44f4523735ed1b0e8d1dc1937e1203e538371a4c9a434526ca46d752b3f4b7383dc1bff4fa@127.0.0.1:20202
INFO [01-10|11:17:05.083] Looking for peers                        peercount=0 tried=11 static=0

Update: I have not been getting any problem with the recent github version 89030ec. 👍

Still testing to confirm whether 1.9.25 really does have a problem.

@joeytwiddle
Copy link
Contributor Author

joeytwiddle commented Jan 11, 2021

My colleague says his v1.9.25 grows to about 2.1GB and then stabilises (but I suspect it will slowly grow in future).

My v1.9.25 reaches 1.3GB. (And then stops, because my disk is full. The geth build used up some space.)

$ du -sh ~/.ethereum-mainnet
1.3G    /home/geth-lite/.ethereum-mainnet

$ du -sh ~/.ethereum-mainnet/geth/*
194M    /home/geth-lite/.ethereum-mainnet/geth/ethash
2.7M    /home/geth-lite/.ethereum-mainnet/geth/lespay
1.1G    /home/geth-lite/.ethereum-mainnet/geth/lightchaindata
...

$ du -sk ~/.ethereum-mainnet/geth/*/* | sort -n -k 1
...
2128    /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/000747.ldb
2128    /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/000748.ldb
2748    /home/geth-lite/.ethereum-mainnet/geth/lespay/000001.log
10696   /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/002714.ldb
10784   /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/002720.ldb
10912   /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/002718.ldb
11236   /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/002716.ldb
65792   /home/geth-lite/.ethereum-mainnet/geth/ethash/cache-R23-86eecd14e1f53d92
65920   /home/geth-lite/.ethereum-mainnet/geth/ethash/cache-R23-dae9dab1d0e68d7d
66048   /home/geth-lite/.ethereum-mainnet/geth/ethash/cache-R23-ba7432405e69c5bf

Also, syncing seems to take longer with this version.

Logfile:

INFO [01-10|19:18:01.592] Starting Geth on Ethereum mainnet... 
INFO [01-10|19:18:01.594] Dropping default light client cache      provided=1024 updated=128
INFO [01-10|19:18:01.596] Maximum peer count                       ETH=0 LES=10 total=50
WARN [01-10|19:18:01.596] The flag --rpc is deprecated and will be removed in the future, please use --http 
WARN [01-10|19:18:01.596] The flag --rpcaddr is deprecated and will be removed in the future, please use --http.addr 
WARN [01-10|19:18:01.596] The flag --rpcport is deprecated and will be removed in the future, please use --http.port 
WARN [01-10|19:18:01.596] The flag --rpcapi is deprecated and will be removed in the future, please use --http.api 
WARN [01-10|19:18:01.597] The flag --wsaddr is deprecated and will be removed in the future, please use --ws.addr 
WARN [01-10|19:18:01.597] The flag --wsport is deprecated and will be removed in the future, please use --ws.port 
WARN [01-10|19:18:01.597] The flag --wsapi is deprecated and will be removed in the future, please use --ws.api 
INFO [01-10|19:18:01.597] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
ERROR[01-10|19:18:01.598] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|19:18:01.598] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|19:18:01.598] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|19:18:01.599] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|19:18:01.599] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|19:18:01.599] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
INFO [01-10|19:18:01.599] Set global gas cap                       cap=25000000
INFO [01-10|19:18:01.600] Allocated cache and file handles         database=/home/geth-lite/.ethereum-mainnet/geth/lightchaindata cache=64.00MiB handles=2048
INFO [01-10|19:18:01.606] Allocated cache and file handles         database=/home/geth-lite/.ethereum-mainnet/geth/lespay cache=16.00MiB handles=16
INFO [01-10|19:18:01.611] Writing default main-net genesis block 
INFO [01-10|19:18:01.913] Persisted trie from memory database      nodes=12356 size=1.78MiB time=78.67764ms gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
INFO [01-10|19:18:01.914] Initialised chain configuration          config="{ChainID: 1 Homestead: 1150000 DAO: 1920000 DAOSupport: true EIP150: 2463000 EIP155: 2675000 EIP158: 2675000 Byzantium: 4370000 Constantinople: 7280000 Petersburg: 7280000 Istanbul: 9069000, Muir Glacier: 9200000, YOLO v2: <nil>, Engine: et
hash}"
INFO [01-10|19:18:01.914] Disk storage enabled for ethash caches   dir=/home/geth-lite/.ethereum-mainnet/geth/ethash count=3
INFO [01-10|19:18:01.914] Disk storage enabled for ethash DAGs     dir=/home/geth-lite/.ethash count=2
INFO [01-10|19:18:01.915] Added trusted checkpoint                 block=11337727 hash="5453ba…d0ef28"
INFO [01-10|19:18:01.915] Loaded most recent local header          number=0 hash="d4e567…cb8fa3" td=17179869184 age=51y9mo1w
INFO [01-10|19:18:01.916] Configured checkpoint registrar          address=0x9a9070028361F7AAbeB3f2F2Dc07F82C4a98A02a signers=5 threshold=2
INFO [01-10|19:18:01.916] Starting peer-to-peer node               instance=Geth/v1.9.25-stable-e7872729/linux-amd64/go1.15.6
INFO [01-10|19:18:01.921] UDP listener up                          net=enode://bf56851112dde712e717f491872cb3d6928989948da149ca5e95c40047c1ececba649d38915125d94c4fc95db4450ca0e54cb92dacc2a0ffc4441ba77b9b2007@[::]:20202
INFO [01-10|19:18:01.949] IPC endpoint opened                      url=/home/geth-lite/.ethereum-mainnet/geth.ipc
INFO [01-10|19:18:01.949] HTTP server started                      endpoint=172.31.42.120:28545 cors= vhosts=localhost
INFO [01-10|19:18:01.950] WebSocket enabled                        url=ws://172.31.42.120:28546
WARN [01-10|19:18:01.950] Light client mode is an experimental feature 
INFO [01-10|19:18:01.951] New local node record                    seq=1 id=ed2efede9ee187be ip=127.0.0.1 udp=20202 tcp=20202
INFO [01-10|19:18:01.951] Started P2P networking                   self=enode://bf56851112dde712e717f491872cb3d6928989948da149ca5e95c40047c1ececba649d38915125d94c4fc95db4450ca0e54cb92dacc2a0ffc4441ba77b9b2007@127.0.0.1:20202
ERROR[01-10|19:18:02.601] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|19:18:02.601] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-10|19:18:02.601] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
INFO [01-10|19:18:11.996] Looking for peers                        peercount=0 tried=11 static=0
INFO [01-10|19:18:22.003] Looking for peers                        peercount=0 tried=12 static=0
INFO [01-10|19:18:27.822] Updated latest header based on CHT       number=11337727 hash="5453ba…d0ef28" age=1mo2w17h
INFO [01-10|19:18:27.822] Block synchronisation started 
WARN [01-10|19:18:27.823] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [01-10|19:18:32.011] Looking for peers                        peercount=1 tried=19 static=0
INFO [01-10|19:18:42.017] Looking for peers                        peercount=1 tried=12 static=0
INFO [01-10|19:18:52.019] Looking for peers                        peercount=1 tried=5  static=0
INFO [01-10|19:19:02.024] Looking for peers                        peercount=1 tried=8  static=0
INFO [01-10|19:19:12.027] Looking for peers                        peercount=1 tried=11 static=0
INFO [01-10|19:19:22.029] Looking for peers                        peercount=1 tried=5  static=0
INFO [01-10|19:19:32.031] Looking for peers                        peercount=1 tried=11 static=0
WARN [01-10|19:19:35.325] Synchronisation failed, dropping peer    peer=8d1da4c5bc682f8f8ad141f60d2889fa4232144c7d2b29b88f81ca33e586ef9d err=timeout
INFO [01-10|19:19:42.033] Looking for peers                        peercount=1 tried=13 static=0
INFO [01-10|19:19:52.036] Looking for peers                        peercount=1 tried=11 static=0
INFO [01-10|19:20:02.040] Looking for peers                        peercount=1 tried=8  static=0
INFO [01-10|19:20:12.043] Looking for peers                        peercount=1 tried=9  static=0
INFO [01-10|19:20:22.045] Looking for peers                        peercount=1 tried=14 static=0
INFO [01-10|19:20:32.047] Looking for peers                        peercount=1 tried=8  static=0
WARN [01-10|19:20:41.760] Served eth_getBlockByNumber              reqid=1306890 t=15.817801068s err="no suitable peers available"
WARN [01-10|19:20:41.792] Synchronisation failed, retrying         err="no peers to keep download active"

...

INFO [01-10|19:33:02.227] Looking for peers                        peercount=1 tried=13 static=0
WARN [01-10|19:33:06.466] Synchronisation failed, dropping peer    peer=8d1da4c5bc682f8f8ad141f60d2889fa4232144c7d2b29b88f81ca33e586ef9d err=timeout
INFO [01-10|19:33:12.229] Looking for peers                        peercount=1 tried=9  static=0
INFO [01-10|19:33:22.276] Looking for peers                        peercount=1 tried=7  static=0
INFO [01-10|19:33:22.701] Generating ethash verification cache     epoch=377 percentage=91 elapsed=3.022s
INFO [01-10|19:33:23.003] Generated ethash verification cache      epoch=377 elapsed=3.324s
INFO [01-10|19:33:24.658] Imported new block headers               count=192 elapsed=4.980s number=11337919 hash="55b269…4d3b75" age=1mo2w16h
INFO [01-10|19:33:26.108] Generating ethash verification cache     epoch=378 percentage=42 elapsed=3.031s
INFO [01-10|19:33:26.232] Imported new block headers               count=192 elapsed=1.574s number=11338111 hash="2d336e…48e859" age=1mo2w16h
INFO [01-10|19:33:29.109] Generating ethash verification cache     epoch=378 percentage=82 elapsed=6.032s
INFO [01-10|19:33:30.360] Generated ethash verification cache      epoch=378 elapsed=7.284s
INFO [01-10|19:33:32.391] Looking for peers                        peercount=1 tried=7  static=0
INFO [01-10|19:33:37.983] Imported new block headers               count=2048 elapsed=11.750s number=11340159 hash="ea05dd…ddc934" age=1mo2w8h
INFO [01-10|19:33:39.568] Generating ethash verification cache     epoch=379 percentage=40 elapsed=3.036s
INFO [01-10|19:33:42.492] Looking for peers                        peercount=1 tried=11 static=0
INFO [01-10|19:33:42.573] Generating ethash verification cache     epoch=379 percentage=79 elapsed=6.041s
INFO [01-10|19:33:44.135] Generated ethash verification cache      epoch=379 elapsed=7.603s
INFO [01-10|19:33:49.412] Imported new block headers               count=1984 elapsed=11.428s number=11342143 hash="cef505…eb888a" age=1mo2w1h
INFO [01-10|19:33:52.592] Looking for peers                        peercount=1 tried=12 static=0
INFO [01-10|19:33:55.316] Imported new block headers               count=1344 elapsed=5.904s  number=11343487 hash="f1fa3d…7eb336" age=1mo1w6d
INFO [01-10|19:34:02.618] Looking for peers                        peercount=2 tried=10 static=0
INFO [01-10|19:34:12.649] Looking for peers                        peercount=1 tried=9  static=0
INFO [01-10|19:34:19.232] Imported new block headers               count=2048 elapsed=8.897s  number=11345535 hash="93dfe6…bca477" age=1mo1w6d
INFO [01-10|19:34:22.739] Looking for peers                        peercount=1 tried=11 static=0
INFO [01-10|19:34:28.232] Imported new block headers               count=2048 elapsed=8.999s  number=11347583 hash="e4fa07…e94f61" age=1mo1w6d
INFO [01-10|19:34:32.853] Looking for peers                        peercount=1 tried=8  static=0
INFO [01-10|19:34:37.451] Imported new block headers               count=2048 elapsed=9.218s  number=11349631 hash="57330d…16e6fd" age=1mo1w5d
INFO [01-10|19:34:42.924] Looking for peers                        peercount=1 tried=9  static=0
INFO [01-10|19:34:46.566] Imported new block headers               count=2048 elapsed=9.114s  number=11351679 hash="2f5e60…af3d7e" age=1mo1w5d
INFO [01-10|19:34:53.007] Looking for peers                        peercount=1 tried=10 static=0
INFO [01-10|19:34:55.845] Imported new block headers               count=2048 elapsed=9.278s  number=11353727 hash="644eee…288e51" age=1mo1w5d
INFO [01-10|19:35:03.068] Looking for peers                        peercount=1 tried=6  static=0
INFO [01-10|19:35:04.911] Imported new block headers               count=2048 elapsed=9.064s  number=11355775 hash="2e38dc…54d98e" age=1mo1w4d
INFO [01-10|19:35:13.112] Looking for peers                        peercount=1 tried=7  static=0
INFO [01-10|19:35:13.977] Imported new block headers               count=2048 elapsed=9.065s  number=11357823 hash="1f8a33…53bfde" age=1mo1w4d
INFO [01-10|19:35:22.990] Imported new block headers               count=2048 elapsed=9.012s  number=11359871 hash="566cdc…ba498a" age=1mo1w4d
INFO [01-10|19:35:23.178] Looking for peers                        peercount=1 tried=10 static=0
INFO [01-10|19:35:32.039] Imported new block headers               count=2048 elapsed=9.049s  number=11361919 hash="04fdcf…33c949" age=1mo1w4d
INFO [01-10|19:35:33.274] Looking for peers                        peercount=1 tried=8  static=0
INFO [01-10|19:35:33.716] Imported new block headers               count=384  elapsed=1.676s  number=11362303 hash="1945bc…7c9b8f" age=1mo1w3d
INFO [01-10|19:35:34.601] Imported new block headers               count=192  elapsed=884.537ms number=11362495 hash="f5e460…ab916e" age=1mo1w3d
INFO [01-10|19:35:43.358] Looking for peers                        peercount=1 tried=10 static=0
INFO [01-10|19:35:43.624] Imported new block headers               count=2048 elapsed=9.022s    number=11364543 hash="8a18a9…63fff6" age=1mo1w3d
INFO [01-10|19:35:52.634] Imported new block headers               count=2048 elapsed=9.009s    number=11366591 hash="203650…1cbf8e" age=1mo1w3d
INFO [01-10|19:35:53.422] Looking for peers                        peercount=1 tried=10 static=0
INFO [01-10|19:36:01.839] Imported new block headers               count=2048 elapsed=9.204s    number=11368639 hash="ae49c4…e8b6e4" age=1mo1w2d
INFO [01-10|19:36:03.520] Looking for peers                        peercount=1 tried=11 static=0
INFO [01-10|19:36:11.039] Generating ethash verification cache     epoch=380 percentage=44 elapsed=3.039s
INFO [01-10|19:36:13.610] Looking for peers                        peercount=1 tried=3  static=0
INFO [01-10|19:36:13.832] Imported new block headers               count=2048 elapsed=11.992s   number=11370687 hash="80caee…9c95b2" age=1mo1w2d
INFO [01-10|19:36:14.041] Generating ethash verification cache     epoch=380 percentage=83 elapsed=6.041s
INFO [01-10|19:36:15.255] Generated ethash verification cache      epoch=380 elapsed=7.255s
INFO [01-10|19:36:23.572] Imported new block headers               count=2048 elapsed=9.739s    number=11372735 hash="ad1446…15bc3f" age=1mo1w2d
INFO [01-10|19:36:23.708] Looking for peers                        peercount=1 tried=6  static=0
INFO [01-10|19:36:28.785] Storing CHT                              section=346 head=98a279bacc4345557db155ef4aae5760aa2900b09118d5110dfcdec62521bbce root=82297e8143b956992806e724023598a55ac6d2772b544d5d916ccab4e250a265
INFO [01-10|19:36:33.878] Looking for peers                        peercount=1 tried=8  static=0
INFO [01-10|19:36:36.217] Imported new block headers               count=2048 elapsed=12.644s   number=11374783 hash="fa1a58…d323a2" age=1mo1w2d
INFO [01-10|19:36:43.994] Looking for peers                        peercount=1 tried=13 static=0
INFO [01-10|19:36:45.705] Imported new block headers               count=2048 elapsed=9.488s    number=11376831 hash="b53b95…738cd0" age=1mo1w1d
INFO [01-10|19:36:52.158] Storing bloom trie                       section=346 head=98a279bacc4345557db155ef4aae5760aa2900b09118d5110dfcdec62521bbce root=f0321bb7919997d0972ed327ac539c49bfb8007c9f08c313efbe929c02cc63f1 compression=0.998

Are Storing CHT and Storing bloom tree relevant? (Probably not. They are also logged in the "good" version.)


The good news is that my build from master 89030ec doesn't have this problem!

The lightchaindata folder is much smaller with this version:

$ du -sh ~/.ethereum-mainnet/geth/*
194M    /home/geth-lite/.ethereum-mainnet/geth/ethash
1.1M    /home/geth-lite/.ethereum-mainnet/geth/lespay
492M    /home/geth-lite/.ethereum-mainnet/geth/lightchaindata
...

$ du -sk ~/.ethereum-mainnet/geth/*/* | sort -n -k 1
...
2128    /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/000723.ldb
2128    /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/000724.ldb
2128    /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/000726.ldb
16320   /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/000862.log
65792   /home/geth-lite/.ethereum-mainnet/geth/ethash/cache-R23-86eecd14e1f53d92
65920   /home/geth-lite/.ethereum-mainnet/geth/ethash/cache-R23-dae9dab1d0e68d7d
66048   /home/geth-lite/.ethereum-mainnet/geth/ethash/cache-R23-ba7432405e69c5bf

Although those files don't appear to be much larger. So I guess there must be more of them.

It's actually growing and shrinking (but luckily it never exceeds 1.3GB).

# A few hours later
$ du -sh ~/.ethereum-mainnet/
801M    /home/geth-lite/.ethereum-mainnet
$ find ~/.ethereum-mainnet/geth/lightchaindata/ | wc -l
308

# A few hours later
$ du -sh ~/.ethereum-mainnet/
436M    /home/geth-lite/.ethereum-mainnet
$ find ~/.ethereum-mainnet/geth/lightchaindata/ | wc -l
116

@holiman
Copy link
Contributor

holiman commented Jan 11, 2021

Could you try a

./build/bin/geth inspect --datadir /home/geth-lite/.ethereum-mainnet/geth/lightchaindata

from the "large" run

@joeytwiddle
Copy link
Contributor Author

joeytwiddle commented Jan 12, 2021

Sure thing @holiman. Sorry it took a while, had to start it from scratch again.

$ du -sh ~/.ethereum-mainnet
1.1G    /home/geth-lite/.ethereum-mainnet

$ du -sh ~/.ethereum-mainnet/geth/lightchaindata/                                                                                                                                                        
841M    /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/

$ ./geth-linux-amd64-1.9.25-e7872729/geth inspect --datadir ~/.ethereum-mainnet/geth/lightchaindata                                                                                              
INFO [01-12|08:04:40.471] Maximum peer count                       ETH=50 LES=0 total=50
INFO [01-12|08:04:40.472] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
ERROR[01-12|08:04:40.475] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-12|08:04:40.476] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-12|08:04:40.477] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-12|08:04:40.477] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-12|08:04:40.477] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-12|08:04:40.478] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
INFO [01-12|08:04:40.478] Set global gas cap                       cap=25000000
INFO [01-12|08:04:40.501] Allocated cache and file handles         database=/home/geth-lite/.ethereum-mainnet/geth/lightchaindata/geth/chaindata cache=512.00MiB handles=2048
INFO [01-12|08:04:40.519] Opened ancient database                  database=/home/geth-lite/.ethereum-mainnet/geth/lightchaindata/geth/chaindata/ancient
INFO [01-12|08:04:40.519] Writing default main-net genesis block 
INFO [01-12|08:04:40.834] Persisted trie from memory database      nodes=12356 size=1.78MiB time=68.795895ms gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
INFO [01-12|08:04:40.835] Disk storage enabled for ethash caches   dir=/home/geth-lite/.ethereum-mainnet/geth/lightchaindata/geth/ethash count=3
INFO [01-12|08:04:40.836] Disk storage enabled for ethash DAGs     dir=/home/geth-lite/.ethash count=2
INFO [01-12|08:04:40.837] Loaded most recent local header          number=0 hash="d4e567…cb8fa3" td=17179869184 age=51y9mo1w
INFO [01-12|08:04:40.837] Loaded most recent local full block      number=0 hash="d4e567…cb8fa3" td=17179869184 age=51y9mo1w
INFO [01-12|08:04:40.838] Loaded most recent local fast block      number=0 hash="d4e567…cb8fa3" td=17179869184 age=51y9mo1w
+-----------------+--------------------+------------+-------+
|    DATABASE     |      CATEGORY      |    SIZE    | ITEMS |
+-----------------+--------------------+------------+-------+
| Key-Value store | Headers            | 576.00 B   |     1 |
| Key-Value store | Bodies             | 44.00 B    |     1 |
| Key-Value store | Receipt lists      | 42.00 B    |     1 |
| Key-Value store | Difficulties       | 48.00 B    |     1 |
| Key-Value store | Block number->hash | 42.00 B    |     1 |
| Key-Value store | Block hash->number | 41.00 B    |     1 |
| Key-Value store | Transaction index  | 0.00 B     |     0 |
| Key-Value store | Bloombit index     | 0.00 B     |     0 |
| Key-Value store | Contract codes     | 0.00 B     |     0 |
| Key-Value store | Trie nodes         | 1.79 MiB   | 12356 |
| Key-Value store | Trie preimages     | 547.13 KiB |  8893 |
| Key-Value store | Account snapshot   | 0.00 B     |     0 |
| Key-Value store | Storage snapshot   | 0.00 B     |     0 |
| Key-Value store | Clique snapshots   | 0.00 B     |     0 |
| Key-Value store | Singleton metadata | 123.00 B   |     3 |
| Ancient store   | Headers            | 6.00 B     |     0 |
| Ancient store   | Bodies             | 6.00 B     |     0 |
| Ancient store   | Receipt lists      | 6.00 B     |     0 |
| Ancient store   | Difficulties       | 6.00 B     |     0 |
| Ancient store   | Block number->hash | 6.00 B     |     0 |
| Light client    | CHT trie nodes     | 0.00 B     |     0 |
| Light client    | Bloom trie nodes   | 0.00 B     |     0 |
+-----------------+--------------------+------------+-------+
|                         TOTAL        |  2.33 MIB  |       |
+-----------------+--------------------+------------+-------+
ERROR[01-12|08:04:40.854] Database contains unaccounted data       size=423.00B count=1

At this point I stopped the process, so my disk would not fill up.


Edit: Wow, after restarting it, the usage eventually dropped to 266MB!

So it can discard the unused data, it just isn't doing it often enough. (At least not for my needs.)

Limiting the bandwidth the node can use seems to help. Since restarting with trickle -d 6 -u 6 the storage has not exceeded 1.1GB. But that limit would make the initial sync very slow.


I monitor the usage over time with:

while true; do echo "[$(date)] $(du -sh ~/.ethereum-mainnet)"; sleep 300; done | tee du.log 

@ligi
Copy link
Member

ligi commented Jan 14, 2021

can you run

./geth-linux-amd64-1.9.25-e7872729/geth inspect --datadir ~/.ethereum-mainnet/ --syncmode light

@fjl
Copy link
Contributor

fjl commented Jan 14, 2021

Bit more context about that: we noticed that your --datadir flag for the geth inspect command is ~/.ethereum-mainnet/geth/lightchaindata, but this is incorrect and inspects an empty database. The command given by @ligi above will inspect the correct database.

@joeysino
Copy link

joeysino commented Jan 15, 2021

Good news (sort of). For some reason, the space grew to 1.3GB again (and then my disk filled). So it's the right conditions to do an inspection!

CRIT [01-14|22:51:17.451] Failed to store block body               err="write /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/014787.log: no space left on device"
Exit code was: 1

$ ls -l /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/014787.log
-rw-r--r-- 1 geth-lite geth-lite 2719744 Jan 14 22:51 /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/014787.log

# Now I need a little disk space to do the inspection, so I'll remove that 2.7MB file

$ rm /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/014787.log

$ du -sh ~/.ethereum-mainnet/
1.2G    /home/geth-lite/.ethereum-mainnet/

$ du -sh ~/.ethereum-mainnet/geth/lightchaindata/
1013M   /home/geth-lite/.ethereum-mainnet/geth/lightchaindata/

$ ./geth-linux-amd64-1.9.25-e7872729/geth inspect --datadir ~/.ethereum-mainnet/ --syncmode light
INFO [01-15|13:20:37.081] Maximum peer count                       ETH=0 LES=10 total=50
INFO [01-15|13:20:37.081] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
ERROR[01-15|13:20:37.083] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-15|13:20:37.085] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-15|13:20:37.085] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=1 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-15|13:20:37.085] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-15|13:20:37.086] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-15|13:20:37.086] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=2 err="failed to initialize libusb: libusb: unknown error [code -99]"
INFO [01-15|13:20:37.086] Set global gas cap                       cap=25000000
INFO [01-15|13:20:37.087] Allocated cache and file handles         database=/home/geth-lite/.ethereum-mainnet/geth/lightchaindata cache=512.00MiB handles=2048
INFO [01-15|13:20:37.134] Disk storage enabled for ethash caches   dir=/home/geth-lite/.ethereum-mainnet/geth/ethash count=3
INFO [01-15|13:20:37.135] Disk storage enabled for ethash DAGs     dir=/home/geth-lite/.ethash count=2
INFO [01-15|13:20:37.154] Loaded most recent local header          number=11655975 hash="cf2446…2c6fa3" td=20171308626710843663550 age=14h30m53s
INFO [01-15|13:20:37.156] Loaded most recent local full block      number=0        hash="d4e567…cb8fa3" td=17179869184             age=51y9mo1w
INFO [01-15|13:20:37.156] Loaded most recent local fast block      number=0        hash="d4e567…cb8fa3" td=17179869184             age=51y9mo1w
ERROR[01-15|13:20:38.099] Failed to enumerate USB devices          hub=trezor vendor=4617  failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-15|13:20:38.112] Failed to enumerate USB devices          hub=ledger vendor=11415 failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
ERROR[01-15|13:20:38.112] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
INFO [01-15|13:20:45.292] Inspecting database                      count=585000 elapsed=8.132s
INFO [01-15|13:20:53.314] Inspecting database                      count=932000 elapsed=16.151s
+-----------------+--------------------+------------+--------+
|    DATABASE     |      CATEGORY      |    SIZE    | ITEMS  |
+-----------------+--------------------+------------+--------+
| Key-Value store | Headers            | 49.94 MiB  |  91261 |
| Key-Value store | Bodies             | 1.28 GiB   |  37683 |
| Key-Value store | Receipt lists      | 129.00 MiB |   2662 |
| Key-Value store | Difficulties       | 4.61 MiB   |  91263 |
| Key-Value store | Block number->hash | 3.64 MiB   |  90919 |
| Key-Value store | Block hash->number | 19.36 MiB  | 495173 |
| Key-Value store | Transaction index  | 0.00 B     |      0 |
| Key-Value store | Bloombit index     | 8.08 MiB   |   2048 |
| Key-Value store | Contract codes     | 10.85 KiB  |      1 |
| Key-Value store | Trie nodes         | 85.13 MiB  | 170878 |
| Key-Value store | Trie preimages     | 547.13 KiB |   8893 |
| Key-Value store | Account snapshot   | 0.00 B     |      0 |
| Key-Value store | Storage snapshot   | 0.00 B     |      0 |
| Key-Value store | Clique snapshots   | 0.00 B     |      0 |
| Key-Value store | Singleton metadata | 123.00 B   |      3 |
| Ancient store   | Headers            | 0.00 B     |      0 |
| Ancient store   | Bodies             | 0.00 B     |      0 |
| Ancient store   | Receipt lists      | 0.00 B     |      0 |
| Ancient store   | Difficulties       | 0.00 B     |      0 |
| Ancient store   | Block number->hash | 0.00 B     |      0 |
| Light client    | CHT trie nodes     | 3.81 MiB   |  34956 |
| Light client    | Bloom trie nodes   | 9.38 MiB   |  10377 |
+-----------------+--------------------+------------+--------+
|                         TOTAL        |  1.59 GIB  |        |
+-----------------+--------------------+------------+--------+
ERROR[01-15|13:20:54.400] Database contains unaccounted data       size=3.59KiB count=54

@rjl493456442
Copy link
Member

rjl493456442 commented Jan 21, 2021

Now I need a little disk space to do the inspection, so I'll remove that 2.7MB file

It's not a normal log, but it's the WAL file of the leveldb. So you definitely lose a lot of data. The real log is LOG

@rjl493456442
Copy link
Member

Also you are using the 1.9.25. This version has the default enabled light pruner which will be triggered every 32768 blocks.
Seems weird the pruner is not working.

@zsfelfoldi
Copy link
Contributor

Is your application doing a log history search? That seems like the most obvious reason that can justify downloading a lot of block bodies. Syncinc does not do that.

@joeytwiddle
Copy link
Contributor Author

joeytwiddle commented Jan 22, 2021

@zsfelfoldi For each block, we are reading every ETH transaction and every USDT 'Transfer' event. We do this not at the head block, but 10 blocks behind the head (for confirmation).

const events = await tokenContract.getPastEvents('Transfer', { fromBlock: blockNumber, toBlock: blockNumber });

(We also regularly fetch a bunch of balances, again 10 blocks behind the head.)

Based on what you said, I am guessing that the events could indeed be the cause.

Thanks. It had not occurred to me that the disk usage might come from the way we use the node, rather than the syncing.

@rjl493456442 Yes we are using 1.9.25.

If it is indeed the LevelDB cache eating the disk space, then it seems to be pruned more often than the sync data, but perhaps not regularly enough for our purposes.

However, the current implementation might be fine for most users.

If we are causing this growth by spamming the node, then we should probably just invest in more disk space! (We do have a fast node as well. Our light nodes are running as backups, in case the fast node breaks, and also for devs to use, which is why they are receiving requests.)

Thank you all for your info. If you think this is not a concern for most users, please feel free to close the issue.

@rjl493456442
Copy link
Member

rjl493456442 commented Feb 4, 2021

@joeytwiddle Yup, I will close it very soon.

Just a quick question, the pruner is triggered by every 12 hours by default. It will scan all the data(receipts, bodies, etc) that belong to the previous sections and delete them. Do you think it's useful that the trigger can somehow be configured from a user's perspective?

Yes, I think we can make it configurable. Close it now.

@joeytwiddle
Copy link
Contributor Author

joeytwiddle commented Feb 8, 2021

@rjl493456442 Yes I think that would be useful for my case. Either by time, or number of blocks, or space used.

Less important, but perhaps useful for recovery/testing/debugging, might be a command to trigger the pruner. (Or just run it automatically on startup.)

Or perhaps that exists already? As geth snapshot prune-state?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

8 participants