besu: Besu block import an order of magnitude slower than Geth (side by side comparison)

Description

As a validator, I would like Besu to match Geth’s performance

Acceptance Criteria

Block import times should be comparable to Geth

Steps to Reproduce (Bug)

Install geth and besu, each with its own prysm instance as CL. Everything is installed on a single host. Fully sync all instances.
View syslog and compare block import times

Expected behavior: Besu import time is similiar to geth

Actual behavior: Besu block import is an order of magnitude slower than geth

Frequency: 100%

Versions (Add all that apply)

Software version: 22.7.7
Java version: openjdk 17.0.4 2022-07-19 OpenJDK Runtime Environment (build 17.0.4+8-Debian-1deb11u1) OpenJDK 64-Bit Server VM (build 17.0.4+8-Debian-1deb11u1, mixed mode, sharing)
OS Name & Version: Debian GNU/Linux 11
Kernel Version: Linux besu 5.18.0-0.deb11.3-amd64 #1 SMP PREEMPT_DYNAMIC Debian 5.18.14-1~bpo11+1 (2022-07-28) x86_64 GNU/Linux
Virtual Machine software & version: ESXi 6.5

Additional Information (Add any of the following or anything else that may be relevant)

Besu options: [Service]

Environment=“BESU_OPTS=-Xmx8g”

ExecStart=/opt/app/besu-22.7.7/bin/besu
–data-path=/opt/besu-data
–network=MAINNET
–rpc-http-host=127.0.0.1
–rpc-http-apis=“ADMIN,ETH,NET,WEB3”
–rpc-http-enabled=true
–host-allowlist=“*”
–engine-jwt-secret=/opt/jwtsecret
–engine-rpc-enabled=true
–engine-rpc-http-port=8552
–data-storage-format=BONSAI
–sync-mode=X_CHECKPOINT
–p2p-host=xxx.xxx.xxx.xxx
–max-peers=50
–p2p-port=xxxxx
–Xplugin-rocksdb-high-spec-enabled=true
–nat-method=UPNP

Colocated 1U Server, 50mbit combined; 10cpu Xeon + 64GB + 2.6TB SSD+RAID6

Besu block import times range from approximately 1 second to 4.5 seconds. This isn’t quite good enough to do validation with - too many incorrect voted head and missed attestations. We are showing blocks #15,788,198 to #15,788,204

Oct 20 10:44:50 besu besu[1167437]: 2022-10-20 10:44:50.610+02:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,788,198 / 130 tx / base fee 18.16 gwei / 18,250,609 (60.8%) gas / (0x3e0340d5c9681e76d9f99fc79304d0853063a754a7cd347b464101eff0e1c5f5) in 1.507s. Peers: 17
Oct 20 10:45:06 besu besu[1167437]: 2022-10-20 10:45:06.674+02:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,788,199 / 231 tx / base fee 18.65 gwei / 17,164,785 (57.2%) gas / (0x2f400525b113be21cb603e06e815983ce4133805198cbc52613e2d762d6b8475) in 2.454s. Peers: 17
Oct 20 10:45:13 besu besu[1167437]: 2022-10-20 10:45:13.753+02:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,788,200 / 216 tx / base fee 18.99 gwei / 17,701,657 (59.0%) gas / (0xe08755702d2f3fbd259950e9c33aacf623df8c3c81b6c00205409f601688c5e7) in 1.683s. Peers: 19
Oct 20 10:45:26 besu besu[1167437]: 2022-10-20 10:45:26.131+02:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,788,201 / 127 tx / base fee 19.42 gwei / 12,427,824 (41.4%) gas / (0x4f320bc9493a1e1ebd73183bc7795d0d08ce34275c6571798bfd0dee276352f7) in 1.183s. Peers: 19
Oct 20 10:45:36 besu besu[1167437]: 2022-10-20 10:45:36.738+02:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,788,202 / 47 tx / base fee 19.00 gwei / 3,158,948 (10.5%) gas / (0x2b1c811b344646a67572586b338c8cba5861896d05879e0d03b2638ab186b29c) in 0.447s. Peers: 18
Oct 20 10:45:36 besu besu[1167437]: 2022-10-20 10:45:36.971+02:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x2b1c811b344646a67572586b338c8cba5861896d05879e0d03b2638ab186b29c, finalized: 0xc5e61d0ca30aa4b6ef3208ce5bbd08ff95a7d0fb1834a686452da32305da30d7, safeBlockHash: 0xfa9018961f2e271e371de2452ac92804e185d7c0fbf56a22e6a6021371d85edf
Oct 20 10:45:52 besu besu[1167437]: 2022-10-20 10:45:52.682+02:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,788,203 / 321 tx / base fee 17.13 gwei / 29,982,755 (99.9%) gas / (0x274bb253b46347722f2d989d878b1ec130317528671a7ddd2cb9df92fb3b4c84) in 3.809s. Peers: 21
Oct 20 10:46:01 besu besu[1167437]: 2022-10-20 10:46:01.719+02:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,788,204 / 170 tx / base fee 19.26 gwei / 13,173,061 (43.9%) gas / (0x7b2fb0abefe139c95b5c77970491129e5d8f11ce5b4464392620309e07b414e4) in 1.358s. Peers: 22

Now, we see Geth, which is running side by side with Besu, importing the exact same blocks.

Oct 20 10:44:49 besu geth[1512700]: INFO [10-20|10:44:49.250] Chain head was updated                   number=15,788,198 hash=3e0340..e1c5f5 root=8886e4..7052f8 elapsed=8.445409ms
Oct 20 10:44:49 besu geth[1512700]: INFO [10-20|10:44:49.255] Unindexed transactions                   blocks=1 txs=132  tail=13,438,199 elapsed=4.471ms
Oct 20 10:45:04 besu geth[1512700]: INFO [10-20|10:45:04.290] Imported new potential chain segment     blocks=1 txs=231  mgas=17.165 elapsed=236.691ms    mgasps=72.520  number=15,788,199 hash=2f4005..6b8475 dirty=1.46GiB
Oct 20 10:45:04 besu geth[1512700]: INFO [10-20|10:45:04.412] Chain head was updated                   number=15,788,199 hash=2f4005..6b8475 root=b58f3d..e3e10f elapsed=7.411554ms
Oct 20 10:45:04 besu geth[1512700]: INFO [10-20|10:45:04.418] Unindexed transactions                   blocks=1 txs=326  tail=13,438,200 elapsed=4.935ms
Oct 20 10:45:12 besu geth[1512700]: INFO [10-20|10:45:12.084] Imported new potential chain segment     blocks=1 txs=216  mgas=17.702 elapsed=179.019ms    mgasps=98.881  number=15,788,200 hash=e08755..88c5e7 dirty=1.46GiB
Oct 20 10:45:12 besu geth[1512700]: INFO [10-20|10:45:12.201] Chain head was updated                   number=15,788,200 hash=e08755..88c5e7 root=0f5cc3..8e6b78 elapsed=7.978155ms
Oct 20 10:45:12 besu geth[1512700]: INFO [10-20|10:45:12.205] Unindexed transactions                   blocks=1 txs=140  tail=13,438,201 elapsed=3.020ms
Oct 20 10:45:24 besu geth[1512700]: INFO [10-20|10:45:24.870] Imported new potential chain segment     blocks=1 txs=127  mgas=12.428 elapsed=120.492ms    mgasps=103.142 number=15,788,201 hash=4f320b..6352f7 dirty=1.46GiB
Oct 20 10:45:24 besu geth[1512700]: INFO [10-20|10:45:24.965] Chain head was updated                   number=15,788,201 hash=4f320b..6352f7 root=e1a0b6..c95cf2 elapsed=5.226733ms
Oct 20 10:45:24 besu geth[1512700]: INFO [10-20|10:45:24.968] Unindexed transactions                   blocks=1 txs=141  tail=13,438,202 elapsed=2.616ms
Oct 20 10:45:36 besu geth[1512700]: INFO [10-20|10:45:36.247] Imported new potential chain segment     blocks=1 txs=47   mgas=3.159  elapsed=71.086ms     mgasps=44.438  number=15,788,202 hash=2b1c81..86b29c dirty=1.46GiB
Oct 20 10:45:36 besu geth[1512700]: INFO [10-20|10:45:36.327] Chain head was updated                   number=15,788,202 hash=2b1c81..86b29c root=fdf30c..ae3bbe elapsed=1.831447ms
Oct 20 10:45:36 besu geth[1512700]: INFO [10-20|10:45:36.327] Unindexed transactions                   blocks=1 txs=32   tail=13,438,203 elapsed="643.1µs"
Oct 20 10:45:48 besu geth[1512700]: INFO [10-20|10:45:48.945] Imported new potential chain segment     blocks=1 txs=321  mgas=29.983 elapsed=323.584ms    mgasps=92.658  number=15,788,203 hash=274bb2..3b4c84 dirty=1.46GiB
Oct 20 10:45:49 besu geth[1512700]: INFO [10-20|10:45:49.052] Chain head was updated                   number=15,788,203 hash=274bb2..3b4c84 root=74bc27..c37910 elapsed=10.591427ms
Oct 20 10:45:49 besu geth[1512700]: INFO [10-20|10:45:49.054] Unindexed transactions                   blocks=1 txs=68   tail=13,438,204 elapsed=1.206ms
Oct 20 10:46:00 besu geth[1512700]: INFO [10-20|10:46:00.453] Imported new potential chain segment     blocks=1 txs=170  mgas=13.173 elapsed=218.985ms    mgasps=60.155  number=15,788,204 hash=7b2fb0..b414e4 dirty=1.46GiB
Oct 20 10:46:00 besu geth[1512700]: INFO [10-20|10:46:00.544] Chain head was updated                   number=15,788,204 hash=7b2fb0..b414e4 root=33598c..24d343 elapsed=7.780758ms
Oct 20 10:46:00 besu geth[1512700]: INFO [10-20|10:46:00.551] Unindexed transactions                   blocks=1 txs=403  tail=13,438,205 elapsed=6.527ms

As we see, Geth is importing blocks about 10 times faster than Besu. Hundreds of ms instead of one to several seconds.

About this issue

Original URL
State: closed
Created 2 years ago
Comments: 24 (8 by maintainers)

Most upvoted comments

I haven’t heard “wontfix”. Right now it’s about figuring out where the slowdown is from an operator perspective, and the Besu team can figure out where it happens in code and design. Design as in “DB layout”, broadly, if that’s where the issue lies.

I can confirm that we’re working on this currently, it is our top priority. We’re working on a fix on the account and storage flat database, and we’re investigating other optimizations (RocksDB bloom filters, parallelize calculateRootHash method, …etc).

ahamlat on Oct 25, 2022

Sharing here the results over four days of execution between version 22.7.7 and 22.10.0, synced from scratch on the same hardware with the same Besu options. It’s more than 20% improvement on block processing time for the median value (50th percentile).

We’re still working on other optimizations.

ahamlat on Nov 9, 2022

Thanks @yorickdowne for testing PR #4568, it is hard to see the impact just by displaying the logs. What I do usually to evaluate the impact of new PRs is to :

Have another baseline node with exactly the same configuration and the same hardware setup. It is even better to have 2 nodes with new PR and 2 nodes without this PR.
Wait at least one hour (and two hours with high spec flag) for RocksDB cache warmup
Compare block processing time (median and 95th percentile) for the same blocks on these two nodes

ahamlat on Oct 28, 2022

I read your post about the 710P degrading SSD drives. It didn’t exactly make me cry, but I’m reaching for some alcohol and I’ll just be rocking back and forth in a corner if anybody wants something.

kayagoban on Oct 25, 2022