besu
besu copied to clipboard
hyperledger
Excessive memory consumption on initial sync
Description
After 23h of syncing, Besu starts the world state healing process - I see an excessive mem usage of 26G and a very busy CPU.
CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS
8b3616a0c196 besu 241.31% 25.96GiB / 29.24GiB 88.79% 62.8GB / 6.84GB 455GB / 1.27TB 138
After several attempts, Besu has not yet managed to fully sync and crashed for memory issues, every time. It seems to be worse with versions > 22.7.4
Expected behavior: Mem usage within acceptable/documented bounds. A system crash after several days of syncing should be avoided, especially because the initial sync will have to restart all over again.
Frequency: Seems to occur every time
Versions (Add all that apply)
- Besu-22.7.4-openjdk-11
- CentOS Stream release 8
- Linux vpsl01 4.18.0-365.el8.x86_64
- Docker version 20.10.13
Additional Information (Add any of the following or anything else that may be relevant)
I'm using -XX:MaxRAMPercentage=80, so it should have 24G
docker run --detach \
--name=besu \
--user=0:0 \
--restart=no \
-p 8545:8545 \
-p 8551:8551 \
-p 30303:30303/tcp \
-p 30303:30303/udp \
-v besu-data:/var/besu/data \
-v besu-config:/var/besu/config \
-e BESU_OPTS=-XX:MaxRAMPercentage=80 \
hyperledger/besu:${BESU_VERSION:-latest} \
--network=mainnet \
--data-path=/var/besu/data \
--data-storage-format=bonsai \
--sync-mode=x_checkpoint
https://discord.com/channels/697535391594446898/888098626264502302/1030171074052235325
@tdiesler : The first thing we can check is either this is related to on-heap memory consumption or native memory consumption. For both cases have fixes and workarounds for both cases. For heap usage, could you share heap usage and GC pause time graph ? For native memory usage, have you already enabled Jemalloc lib ? it allows Besu to have less fragmentation when allocating objects in memory.
@ahamlat AFAICS, there is no mention of jemalloc at startup ...
2022-10-13 06:36:40.972+00:00 | main | INFO | Besu | Using LibEthPairings native alt bn128
2022-10-13 06:36:40.976+00:00 | main | INFO | Besu | Using the native implementation of the signature algorithm
2022-10-13 06:36:40.997+00:00 | main | INFO | Besu | Using the native implementation of the blake2bf algorithm
2022-10-13 06:36:41.004+00:00 | main | INFO | Besu | Starting Besu version: besu/v22.7.4/linux-x86_64/openjdk-java-11
2022-10-13 06:36:41.495+00:00 | main | WARN | Besu | --graphql-http-host has been ignored because --graphql-http-enabled was not defined on the command line.
2022-10-13 06:36:41.496+00:00 | main | WARN | Besu | --rpc-ws-host has been ignored because --rpc-ws-enabled was not defined on the command line.
2022-10-13 06:36:41.498+00:00 | main | INFO | Besu | Static Nodes file = /var/besu/data/static-nodes.json
2022-10-13 06:36:41.499+00:00 | main | INFO | StaticNodesParser | StaticNodes file /var/besu/data/static-nodes.json does not exist, no static connections will be created.
2022-10-13 06:36:41.499+00:00 | main | INFO | Besu | Connecting to 0 static nodes.
2022-10-13 06:36:41.502+00:00 | main | INFO | Besu | Security Module: localfile
2022-10-13 06:36:41.526+00:00 | main | INFO | DatabaseMetadata | Lookup database metadata file in data directory: /var/besu/data
2022-10-13 06:36:41.609+00:00 | main | INFO | RocksDBKeyValueStorageFactory | Existing database detected at /var/besu/data. Version 2
2022-10-13 06:36:44.794+00:00 | main | WARN | Besu | --tx-pool-future-max-by-account has been deprecated, use --tx-pool-limit-by-account-percentage instead.
2022-10-13 06:36:44.816+00:00 | main | INFO | KeyPairUtil | Loaded public key 0x0ae8afc65f4eb662171fd5634e841e0ecff73d4e06f4f3de0222656176c1f75edc8c3bce90c6afd689c0de5ba9d6120832e21dbf783aefb7344c54a1cfde5918 from /var/besu/data/key
2022-10-13 06:36:45.035+00:00 | main | INFO | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Frontier: 0, Homestead: 1150000, DaoRecoveryInit: 1920000, DaoRecoveryTransition: 1920001, Homestead: 1920010, TangerineWhistle: 2463000, SpuriousDragon: 2675000, Byzantium: 4370000, Petersburg: 7280
000, Istanbul: 9069000, MuirGlacier: 9200000, Berlin: 12244000, London: 12965000, ArrowGlacier: 13773000, GrayGlacier: 15050000]
2022-10-13 06:36:45.066+00:00 | main | INFO | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Frontier: 0, Homestead: 1150000, DaoRecoveryInit: 1920000, DaoRecoveryTransition: 1920001, Homestead: 1920010, TangerineWhistle: 2463000, SpuriousDragon: 2675000, Byzantium: 4370000, Petersburg: 7280
000, Istanbul: 9069000, MuirGlacier: 9200000, Berlin: 12244000, London: 12965000, ArrowGlacier: 13773000, GrayGlacier: 15050000]
2022-10-13 06:36:45.704+00:00 | main | INFO | EthPeers | Updating the default best peer comparator
2022-10-13 06:36:45.734+00:00 | main | INFO | BesuControllerBuilder | TTD difficulty is present, creating initial sync phase with transition to PoS support
2022-10-13 06:36:45.766+00:00 | main | INFO | CheckpointDownloaderFactory | Checkpoint sync start with block 11052984 and hash 0x44bca881b07a6a09f83b130798072441705d9a665c5ac8bdf2f39a3cdf3bee29
2022-10-13 06:36:46.087+00:00 | main | INFO | TransitionBesuControllerBuilder | TTD present, creating DefaultSynchronizer that stops propagating after finalization
2022-10-13 06:36:46.115+00:00 | main | INFO | RunnerBuilder | Detecting NAT service.
2022-10-13 06:36:46.401+00:00 | main | INFO | Runner | Starting external services ...
2022-10-13 06:36:46.402+00:00 | main | INFO | JsonRpcHttpService | Starting JSON-RPC service on 0.0.0.0:8545
2022-10-13 06:36:46.515+00:00 | main | INFO | JsonRpcService | Starting JSON-RPC service on 0.0.0.0:8551
2022-10-13 06:36:46.514+00:00 | vert.x-eventloop-thread-1 | INFO | JsonRpcHttpService | JSON-RPC service started and listening on 0.0.0.0:8545
2022-10-13 06:36:46.525+00:00 | vert.x-eventloop-thread-1 | INFO | JsonRpcService | JSON-RPC service started and listening on 0.0.0.0:8551
2022-10-13 06:36:46.530+00:00 | main | INFO | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
2022-10-13 06:36:46.532+00:00 | main | INFO | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /var/besu/data/caches
2022-10-13 06:36:46.541+00:00 | main | INFO | Runner | Starting Ethereum main loop ...
2022-10-13 06:36:46.541+00:00 | main | INFO | DockerNatManager | Starting docker NAT manager.
2022-10-13 06:36:46.548+00:00 | main | INFO | NetworkRunner | Starting Network.
2022-10-13 06:36:46.552+00:00 | main | INFO | DefaultP2PNetwork | Starting DNS discovery with URL enrtree://AKA3AM6LPBYEUDMVNU3BSVQJ5AD45Y7YPOHJLEF6W26QOE4VTUDPE@all.mainnet.ethdisco.net
2022-10-13 06:36:46.662+00:00 | nioEventLoopGroup-2-1 | INFO | RlpxAgent | P2P RLPx agent started and listening on /0.0.0.0:30303.
2022-10-13 06:36:46.664+00:00 | main | INFO | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=30303
2022-10-13 06:36:46.725+00:00 | vert.x-eventloop-thread-1 | INFO | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0.0.0.0 and port=30303
2022-10-13 06:36:46.727+00:00 | vert.x-eventloop-thread-1 | INFO | PeerDiscoveryAgent | P2P peer discovery agent started and listening on /0.0.0.0:30303
2022-10-13 06:36:46.830+00:00 | vert.x-eventloop-thread-1 | INFO | PeerDiscoveryAgent | Writing node record to disk. NodeRecord{seq=37, publicKey=0x020ae8afc65f4eb662171fd5634e841e0ecff73d4e06f4f3de0222656176c1f75e, udpAddress=Optional[/127.0.0.1:30303], tcpAddress=Optional[/127.0.0.1:30303], asBase64=-Je4QJB_CLhN
dRJpTxJItXvzw1qQiZ-cV3-yCoZdyxRj8xezZoc0d8baYJ4zZXRCuFmPRwOnNCDPtz2g_UyLpHIH2vglg2V0aMfGhPCv0OOAgmlkgnY0gmlwhH8AAAGJc2VjcDI1NmsxoQIK6K_GX062Yhcf1WNOhB4Oz_c9Tgb0894CImVhdsH3XoN0Y3CCdl-DdWRwgnZf, nodeId=0x532470b557b8c4e3bc78de09812dcf4dfc82f8a88ac4dd59130fa765e3f1b048, customFields={tcp=30303, udp=30303, ip=0x7f0000
01, eth=[[0xf0afd0e3, 0x]], id=V4, secp256k1=0x020ae8afc65f4eb662171fd5634e841e0ecff73d4e06f4f3de0222656176c1f75e}}
2022-10-13 06:36:46.913+00:00 | main | INFO | DefaultP2PNetwork | Enode URL enode://0ae8afc65f4eb662171fd5634e841e0ecff73d4e06f4f3de0222656176c1f75edc8c3bce90c6afd689c0de5ba9d6120832e21dbf783aefb7344c54a1cfde5918@127.0.0.1:30303
2022-10-13 06:36:46.914+00:00 | main | INFO | DefaultP2PNetwork | Node address 0x812dcf4dfc82f8a88ac4dd59130fa765e3f1b048
2022-10-13 06:36:46.918+00:00 | main | INFO | DefaultSynchronizer | Starting synchronizer.
2022-10-13 06:36:46.920+00:00 | main | INFO | SnapSyncDownloader | Starting sync.
2022-10-13 06:36:46.923+00:00 | main | INFO | WaitForPeersTask | Waiting for 1 total peers to connect. 0 peers currently connected.
2022-10-13 06:36:46.933+00:00 | main | INFO | Runner | Ethereum main loop is up.
This suggests there should be a message about it. In any case, it would have to be enabled by the besu docker image, right? Here is a related post about a ruby image.
How would I get these mem stats from a running docker container?
This suggests that jemalloc is getting installed in hyperledger/besu:22.7.4-openjdk-11, but BESU_USING_JEMALLOC is not getting set by the startup script
root@09f08bdfc84a:/opt/besu# set | grep BESU
BESU_GRAPHQL_HTTP_HOST=0.0.0.0
BESU_OPTS=-XX:MaxRAMPercentage=80
BESU_PID_PATH=/tmp/pid
BESU_RPC_HTTP_HOST=0.0.0.0
BESU_RPC_WS_HOST=0.0.0.0
I can load the library in container
$ docker exec -it besu bash
LD_PRELOAD=libjemalloc.so sh -c true
Now, is it using it or not?
@ahamlat Could you please share your workarounds? What do other folks use in their docker BESU_OPTS?
Now, is it using it or not?
You can use this command inside your docker container to be sure that Jemalloc is actually loaded : sudo lsof -n -p [PID] | fgrep jem
@ahamlat Could you please share your workarounds? What do other folks use in their docker BESU_OPTS?
For BESU_OPTS, you can replace the one you're using currently with this one : BESU_OPTS=-Xmx8g.
If you still have this excessive memory consumption, please share the result of this command : jcmd [PID] GC.class_histogram
ok, it is using jemalloc
root@456e6c4d7f81:/opt/besu# lsof -n -p 1 | grep jem
java 1 root mem REG 8,2 1444124 /usr/lib/x86_64-linux-gnu/libjemalloc.so.2 (path dev=0,45)
jcmd is not available in the openjdk image by default. If needed, I'll try to get it from elsewhere
In this case, you can just let it run and see if Jemalloc helps to reduce memory consumption.
I manually installed jcmd in the running container and found that by running it mem drops by 1G - probably GC. Now that we verified that the process is indeed using jemalloc, I assume it was always there
Here you go ...
This is after 8h, currently @ Worldstate download in progress synced=30.36%
CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS
aa78adccf96d besu 255.21% 6.664GiB / 20GiB 33.32% 74.2GB / 2.48GB 305GB / 1.22TB 144
With previous attempts, I could always get passed the worldstate download phase. Memory consumption shot up during healing and the furthest I got was 20m nodes
From the histogram, we can see that we have a lot of Transaction's objects in memory. We already fixed this issue in Besu 22.7.6 and one other similar issue that happens during backward sync in 22.10.0-RC1.
This is hyperledger/besu:22.7.6-openjdk-11. After 20h it got to Worldstate download in progress synced=49.02% - this seems (a lot) slower than on previous attempts (with -Xmx > 16g). Now, for 3h no worldstate download progress
Do you have metrics to share to see why this is so slow ? (block time import, number of connected peers, GC activity, CPU usage, ...etc. If you don't have a Besu Dashboard, you can take a look to this one : https://grafana.com/grafana/dashboards/10273-besu-overview/
The worldstate download stage completed after 42h with hyperledger/besu:22.7.6-openjdk-11.
- memory usage at the time 15G (with -Xmx=16g)
- 6.8TB written to disk
- 2m core transaction kept in memory
CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS
e5e684197070 besu 148.87% 15.14GiB / 26GiB 58.23% 322GB / 15GB 2.73TB / 6.75TB 148
root@e5e684197070:/opt/besu# jcmd 1 GC.class_histogram | more
1:
num #instances #bytes class name (module)
-------------------------------------------------------
1: 2269717 1054792440 [B ([email protected])
2: 11913052 948593616 [I ([email protected])
3: 6144888 245795520 java.math.BigInteger ([email protected])
4: 2051226 180507888 org.hyperledger.besu.ethereum.core.Transaction
5: 9450372 151205952 java.util.Optional ([email protected])
6: 5758156 138195744 org.apache.tuweni.units.bigints.UInt256
7: 5757807 138187368 org.hyperledger.besu.datatypes.Wei
8: 3718265 118984480 org.apache.tuweni.bytes.ArrayWrappingBytes
9: 2051231 65639392 org.hyperledger.besu.crypto.SECPSignature
10: 2148159 51555816 org.hyperledger.besu.datatypes.Address
11: 2077249 49853976 com.google.common.base.Suppliers$NonSerializableMemoizingSupplier
12: 1748787 41970888 java.util.ArrayList ([email protected])
13: 2051227 32819632 org.hyperledger.besu.crypto.SECPSignature$$Lambda$491/0x000000084043d840
14: 565769 18104608 org.apache.tuweni.bytes.ArrayWrappingBytes32
15: 120635 17225456 [Ljava.lang.Object; ([email protected])
16: 97882 3915280 java.lang.ref.Finalizer ([email protected])
17: 86573 2077752 org.hyperledger.besu.evm.AccessListEntry
18: 77219 1853256 java.lang.String ([email protected])
19: 69647 1671528 org.hyperledger.besu.datatypes.Hash
20: 100059 1600944 java.util.concurrent.atomic.AtomicBoolean ([email protected])
21: 48877 1564064 org.rocksdb.Transaction
22: 47499 1519968 java.util.HashMap$Node ([email protected])
23: 13000 1456000 org.hyperledger.besu.ethereum.core.BlockHeader
24: 11355 1346784 java.lang.Class ([email protected])
25: 48882 1173168 org.rocksdb.WriteOptions
26: 36155 1156960 java.util.concurrent.ConcurrentHashMap$Node ([email protected])
27: 387 909336 [C ([email protected])
28: 3780 789648 [Ljava.util.HashMap$Node; ([email protected])
29: 15822 759456 java.nio.HeapByteBuffer ([email protected])
30: 17775 711000 java.util.LinkedHashMap$Entry ([email protected])
31: 960 645120 io.netty.util.internal.shaded.org.jctools.queues.MpscArrayQueue
32: 26811 643464 java.util.concurrent.CompletableFuture ([email protected])
33: 642 608880 [Ljava.util.concurrent.ConcurrentHashMap$Node; ([email protected])
34: 1956 603552 [J ([email protected])
35: 12780 511200 java.util.concurrent.CompletableFuture$UniExceptionally ([email protected])
Now, onward to the node healing stage. Let's hope this time it completes before the process dies with OOME Currently nodes heal at a rate of 60k / min
Ok, besu is done
2022-10-21 13:13:31.731+00:00 | EthScheduler-Services-28 (requestCompleteTask) | INFO | SnapsyncMetricsManager | Finished worldstate snapsync with nodes 1390002633 (healed=8613992) duration 1:20:0,970.
2022-10-21 13:13:31.998+00:00 | EthScheduler-Services-666 (importBlock) | INFO | PipelineChainDownloader | PipelineChain download complete
2022-10-21 13:13:32.043+00:00 | EthScheduler-Services-666 (importBlock) | INFO | DefaultSynchronizer | Sync completed successfully with pivot block 15796599
2022-10-21 13:13:32.043+00:00 | EthScheduler-Services-666 (importBlock) | INFO | BesuControllerBuilder | Initial sync done, unsubscribe finalized block hash supplier
Does this mean I can upgrade besu without having to do the initial sync again?