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

Besu block import an order of magnitude slower than Geth (side by side comparison) #4549

Closed
kayagoban opened this issue Oct 20, 2022 · 24 comments
Assignees

Comments

@kayagoban
Copy link

kayagoban commented Oct 20, 2022

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)

  1. Install geth and besu, each with its own prysm instance as CL. Everything is installed on a single host. Fully sync all instances.
  2. 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 Update Jenkins Build for Pantheon → Besu considerations #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.

@ahamlat
Copy link
Contributor

ahamlat commented Oct 22, 2022

Thanks @kayagoban, we're looking into optimizing block processing time, let me just check those results on similar hardware setup.

@yorickdowne
Copy link

yorickdowne commented Oct 23, 2022

Some anecdotal stuff from the rocketpool discord: Storage IOPS may matter. Users who report issues with Besu 22.7 are on SATA SSDs, maybe 40k read / 11k write IOPS on a 150G file with rw-mix ratio 75%. NVMe is roughly 4x that, 175k/60k or thereabouts.

Raid6 in this case is not well suited for DB workloads for example, so I’d expect somewhat lower IOPS there because of the raid6 write amplification. It also matters which generation raid controller this is: Anything before 9400/9500 does not pass through TRIM and so SSD performance suffers over time.

Hypothesis: Besu needs more IOPS than Geth, and so on storage that is “in between” performance wise - plenty for Geth but a little tight for Besu - this causes the block import time issues seen.

The performance anecdotes are with TLC and DRAM drives, Samsung 860/870 EVO.

I am syncing a Besu on NVMe and will check import block processing times. I can also do it on SATA but that’ll take time - the SATA box is running some worst-case Erigon tests right now. Worst case as in SATA SSD not NVMe 😅

IF this bears out to be a major contributing factor, this then begs the question of what Besu can do to reduce its IOPS use, and whether it’s worth tuning Besu for use on “middling” storage - SATA, VPS, AWS gp3, sub-optimal raid layouts - or it should just be documented that Besu is an NVMe, no QLC no DRAMless, mirrors (RAID1) are fine, raid5/6 are not play.

@ahamlat
Copy link
Contributor

ahamlat commented Oct 24, 2022

@kayagoban I have similar results on one of our nodes

{"@timestamp":"2022-10-20T08:44:50,003","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #15,788,198 / 130 tx / base fee 18.16 gwei / 18,250,609 (60.8%) gas / (0x3e0340d5c9681e76d9f99fc79304d0853063a754a7cd347b464101eff0e1c5f5) in 1.348s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-20T08:45:05,730","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #15,788,199 / 231 tx / base fee 18.65 gwei / 17,164,785 (57.2%) gas / (0x2f400525b113be21cb603e06e815983ce4133805198cbc52613e2d762d6b8475) in 1.858s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-20T08:45:13,421","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #15,788,200 / 216 tx / base fee 18.99 gwei / 17,701,657 (59.0%) gas / (0xe08755702d2f3fbd259950e9c33aacf623df8c3c81b6c00205409f601688c5e7) in 1.685s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-20T08:45:25,544","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #15,788,201 / 127 tx / base fee 19.42 gwei / 12,427,824 (41.4%) gas / (0x4f320bc9493a1e1ebd73183bc7795d0d08ce34275c6571798bfd0dee276352f7) in 1.011s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-20T08:45:36,269","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #15,788,202 / 47 tx / base fee 19.00 gwei / 3,158,948 (10.5%) gas / (0x2b1c811b344646a67572586b338c8cba5861896d05879e0d03b2638ab186b29c) in 0.327s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-20T08:45:51,025","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #15,788,203 / 321 tx / base fee 17.13 gwei / 29,982,755 (99.9%) gas / (0x274bb253b46347722f2d989d878b1ec130317528671a7ddd2cb9df92fb3b4c84) in 2.848s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-20T08:46:00,935","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #15,788,204 / 170 tx / base fee 19.26 gwei / 13,173,061 (43.9%) gas / (0x7b2fb0abefe139c95b5c77970491129e5d8f11ce5b4464392620309e07b414e4) in 1.066s. Peers: 25","throwable":""}

We're looking into this to improve block processing time.

@yorickdowne Thanks for your sharing, your feedback is helpfull as always.
If my understanding is correct, you're talking about block importing time during sync, especially on SATA SSDs, which is different from block processing time. I totally agree that we also have to improve that part where Disk IO is the big bottleneck. Besu's behaviour during sync and post sync is quite different, we have more room after sync to do more work in parallel, where during sync, we should find a way to do less work (reduce write and/or read amplification).

Disk IO
image

CPU Usage
image

@yorickdowne
Copy link

@ahamlat I was talking about post sync. Something causes some systems to have block processing times in excess of 1s while others are doing well: It doesn't appear to be CPU or memory, that's why I'm suspecting disk. And, more testing needed.

@ahamlat
Copy link
Contributor

ahamlat commented Oct 24, 2022

I agree with you, CPU and memory are not the bottleneck post sync, and we can use memory to reduce the number of IO (RocksDB cache).

We already identified RocksDB.get method as one of the most consuming methods (almost half of block processing time without high spec flag). This is mainly due to getting different World state storage and account nodes from Merkle Patricia trie.

These account and storage nodes should be already stored in the flat databases at the end of Sync, which is one of the benefits from using Bonsai as a database layer. Our current implementation is not optimized because at the end of the sync, there are some gaps in these two flat databases. We're working to optimize this implementation to have a complete database and thus reduce read amplification.

@kayagoban
Copy link
Author

If I understand correctly, using the Forest strategy would probably be faster on my machine than Bonsai - do you think that’s correct?

@ahamlat
Copy link
Contributor

ahamlat commented Oct 25, 2022

Good question, even with these gaps in the flat databases, Bonsai is still faster than Forest implementation.

@kayagoban
Copy link
Author

I am syncing a Besu on NVMe and will check import block processing times. I can also do it on SATA but that’ll take time - the SATA box is running some worst-case Erigon tests right now. Worst case as in SATA SSD not NVMe sweat_smile

IF this bears out to be a major contributing factor, this then begs the question of what Besu can do to reduce its IOPS use, and whether it’s worth tuning Besu for use on “middling” storage - SATA, VPS, AWS gp3, sub-optimal raid layouts - or it should just be documented that Besu is an NVMe, no QLC no DRAMless, mirrors (RAID1) are fine, raid5/6 are not play.

A clarification - this is about already-synced block import times. (I hear you guys calling it block processing, but the logs actually say " Imported #15,788,19" so I'm using your own terminology here).

I can see how it doesn't seem like an issue on faster storage, but if geth is usable on these slower storage systems and besu is not, with a 10x difference, simply saying "wontfix" doesn't bode well for client diversity.

@yorickdowne
Copy link

yorickdowne commented Oct 25, 2022

simply saying "wontfix" doesn't bode well for client diversity.

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 expect this won't get solved overnight. I agree that running on "whatever" is core to Ethereum's mission, and running well on "middling" storage is highly desirable.

That said, RAID6 is close to a worst-case scenario for DB storage. Is this a hardware RAID controller, and if so, which make and model?

@ahamlat
Copy link
Contributor

ahamlat commented Oct 25, 2022

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).

@kayagoban
Copy link
Author

simply saying "wontfix" doesn't bode well for client diversity.

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 expect this won't get solved overnight. I agree that running on "whatever" is core to Ethereum's mission, and running well on "middling" storage is highly desirable.

That said, RAID6 is close to a worst-case scenario for DB storage. Is this a hardware RAID controller, and if so, which make and model?

It's a PERC H701P Mini hw raid controller with 8x 1TB SSD drives. I didn't know it was a worst case when I set it up as RAID6, although I thought there would be a performance hit. I'm colocated, so letting the drives failover cleanly was a priority for me. Collecting that beast and reformatting the drives and reinstalling ESXi is not on my to-do list, even if it would get me more IOPS.

@yorickdowne
Copy link

yorickdowne commented Oct 25, 2022

The H710P (is that the one you meant?) does not pass through TRIM. Performance will suffer as the drives get older. I had a PERC H710P with RAID1 and performance on its SATA SSDs got so bad I couldn't even sync Geth any more. Writeup here: https://gist.github.com/yorickdowne/fd36009c19fdbee0337bffc0d5ad8284

I think this is good, if also anecdotal, evidence that IOPS is the bottleneck. That Besu can do something about, and as ahamlat says the team is focusing on that right now.

Your personal setup may never run particularly well until that's a RAID10 on mdadm (or whatever ESXI's software RAID equivalent is) with the PERC710P as just an HBA, but that's neither here nor there with regards to the discussion of Besu's IOPS hunger relative to Geth. I think everyone's agreed that the desired state is that Besu runs as well as Geth on any given storage platform.

@kayagoban
Copy link
Author

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.

@yorickdowne
Copy link

yorickdowne commented Oct 27, 2022

Going to try 4568 on my test setup here. It's a 24-core 512 GiB RAM NVME baremetal, but no high perf flag that'd trade RAM for speed. So I have a baseline. And it definitely spikes to just under 2s on that machine:

execution_1                  | 2022-10-27 18:32:02.365+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,216 / 312 tx / base fee 23.42 gwei / 23,681,264 (78.9%) gas / (0xd45d6cef93eb323f2827b6fdcba7cce5be279692001d220454f0f79d4b2b2b9c) in 1.600s. Peers: 25
execution_1                  | 2022-10-27 18:32:02.748+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xd45d6cef93eb323f2827b6fdcba7cce5be279692001d220454f0f79d4b2b2b9c, finalized: 0x413f7a6b2094ca29efc279422cb2f3a1ae4093be4e8733d58317c721124735f7, safeBlockHash: 0x86c3c44c2c0b3a20625f132276e8476fedeae182365dfec58eb62470b7a29d2b
execution_1                  | 2022-10-27 18:32:13.807+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,217 / 231 tx / base fee 25.12 gwei / 20,504,300 (68.3%) gas / (0xf40c2b5d74e425023262167f97d71d286f8e3514489a0a98742714df06a1483d) in 1.098s. Peers: 25
execution_1                  | 2022-10-27 18:32:24.707+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,218 / 166 tx / base fee 26.27 gwei / 13,851,615 (46.2%) gas / (0x9fc905cc6fa8ce2a3e523d8cc2270792a152bf2b26a5a5e02cf6c2cb0211f5e9) in 0.717s. Peers: 25
execution_1                  | 2022-10-27 18:32:39.035+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,219 / 224 tx / base fee 26.02 gwei / 18,429,640 (61.4%) gas / (0x9eccda2493830f1a035151ec79887a4aafa38fb399e172e616ad34b87bb1c8d8) in 0.704s. Peers: 25
execution_1                  | 2022-10-27 18:32:49.162+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,220 / 128 tx / base fee 26.76 gwei / 13,358,155 (44.5%) gas / (0x59d2de1170798398d92f2da91651dc6f00c1ac752c0936e4d636c15ab9491c02) in 0.560s. Peers: 25
execution_1                  | 2022-10-27 18:33:00.082+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,221 / 25 tx / base fee 26.40 gwei / 2,205,341 (7.4%) gas / (0x6afd055d4d82444c0eeb12bfb56718df6c77db0c6e92a72621af2e49c63ba30c) in 0.121s. Peers: 25
execution_1                  | 2022-10-27 18:33:14.020+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,222 / 351 tx / base fee 23.58 gwei / 29,980,866 (99.9%) gas / (0xb27b91955dd797d320fab05df1acad46e10a86e52cf3b094aa7f7fef20bed7c2) in 1.488s. Peers: 25
execution_1                  | 2022-10-27 18:33:14.310+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xb27b91955dd797d320fab05df1acad46e10a86e52cf3b094aa7f7fef20bed7c2, finalized: 0x413f7a6b2094ca29efc279422cb2f3a1ae4093be4e8733d58317c721124735f7, safeBlockHash: 0x86c3c44c2c0b3a20625f132276e8476fedeae182365dfec58eb62470b7a29d2b
execution_1                  | 2022-10-27 18:33:25.171+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,223 / 191 tx / base fee 26.53 gwei / 15,958,539 (53.2%) gas / (0xb67d2e401650d8b39b1664766cc0f7a27d33db37a6b8daf45a3589b47752862e) in 0.775s. Peers: 25
execution_1                  | 2022-10-27 18:33:37.210+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,224 / 200 tx / base fee 26.74 gwei / 14,784,707 (49.3%) gas / (0xb868e8ba876829961313e7c9bf2df6a49343955dcc51e4374df62626134ed4de) in 0.689s. Peers: 25
execution_1                  | 2022-10-27 18:33:48.265+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,225 / 120 tx / base fee 26.69 gwei / 9,188,217 (30.6%) gas / (0xa996135611f894116e8d01c1acf18d561851aaaf81b03380a647d3f04154f7d8) in 0.372s. Peers: 25
execution_1                  | 2022-10-27 18:34:00.310+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,226 / 50 tx / base fee 25.40 gwei / 5,280,357 (17.6%) gas / (0xf979865a8aebce5e3666d07ba8e774ea4494665e42a16995dd32476475269261) in 0.194s. Peers: 25
execution_1                  | 2022-10-27 18:34:14.364+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,227 / 362 tx / base fee 23.34 gwei / 29,975,672 (99.9%) gas / (0x49636f83868259a86de5fae215df2d62fd759b200eacd761d307141d441f77be) in 1.748s. Peers: 25

@yorickdowne
Copy link

Feels a little better, though not night and day, with that PR.

execution_1                  | 2022-10-27 18:58:59.691+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,350 / 26 tx / base fee 33.96 gwei / 1,795,837 (6.0%) gas / (0xece301147cb31f620d903766b66e9e2ae988eda2a1d2c2650078631bb746e9ef) in 0.098s. Peers: 23
execution_1                  | 2022-10-27 18:59:14.396+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,351 / 381 tx / base fee 30.22 gwei / 27,890,175 (93.0%) gas / (0xb6a3dbcf99b07744d152dbdf2611a4aeac728cc3e53efd20e2ecac951b8d9345) in 1.492s. Peers: 18
execution_1                  | 2022-10-27 18:59:24.825+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,352 / 104 tx / base fee 33.47 gwei / 11,467,615 (38.2%) gas / (0xdc185142ce9928f43d69a3a7a381235595d9b40727adb5d6b9f8b20e00e9ce20) in 0.545s. Peers: 18
execution_1                  | 2022-10-27 18:59:37.752+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,353 / 206 tx / base fee 32.48 gwei / 17,882,373 (59.6%) gas / (0x971da6070f193abfc905dfb0770e3d1dbd99559f238229263a61bd8437d9bf40) in 0.850s. Peers: 21
execution_1                  | 2022-10-27 18:59:48.468+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,354 / 119 tx / base fee 33.26 gwei / 10,164,357 (33.9%) gas / (0x759b3f3d12cc68153fa086a5f0d2f4e995cdf2209f6793184c15eabddaa25beb) in 0.518s. Peers: 19
execution_1                  | 2022-10-27 19:00:00.707+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,355 / 166 tx / base fee 31.92 gwei / 13,747,202 (45.8%) gas / (0x4b66ce67f64e97b2a19f9c30c08fa9b372fd11cb39006777ef4d497d42718cb2) in 0.600s. Peers: 20
execution_1                  | 2022-10-27 19:00:00.912+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x4b66ce67f64e97b2a19f9c30c08fa9b372fd11cb39006777ef4d497d42718cb2, finalized: 0x9dda6d2260772c262bfec355c89f9dfdb352911d63a93111f1510689eacc05b1, safeBlockHash: 0x07b7c3d1f838967c403091ac1fbe21251ab93e691da4a7b01e612a5e942bd2e6
execution_1                  | 2022-10-27 19:00:13.707+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,356 / 292 tx / base fee 31.59 gwei / 17,141,587 (57.1%) gas / (0x227416eb502c67f0a9c400fb91e25af72cfde1b35b5a89f4ef0ffced29b322af) in 0.883s. Peers: 19
execution_1                  | 2022-10-27 19:00:26.333+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,357 / 556 tx / base fee 32.15 gwei / 26,668,683 (88.9%) gas / (0x12bbeb60ac5431129dca1317820c77b152adbe5a1a9e872e1f634cffa09e8311) in 1.658s. Peers: 18
execution_1                  | 2022-10-27 19:00:37.423+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,358 / 278 tx / base fee 35.28 gwei / 18,563,541 (61.9%) gas / (0x359b7a6f25505792d2b4449b858d591236e535096374f170e8fe98a54d35255d) in 1.178s. Peers: 20
execution_1                  | 2022-10-27 19:00:48.809+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,359 / 141 tx / base fee 36.33 gwei / 13,609,422 (45.4%) gas / (0x2c04b0512caa0b99cc39443a1d4cff03985aabecf15ab0070b4f101b696e5e4b) in 0.607s. Peers: 20
execution_1                  | 2022-10-27 19:01:00.565+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,360 / 119 tx / base fee 35.91 gwei / 10,664,780 (35.5%) gas / (0xed7fac24be5cc4a381eadb16db4796e679f41db1013fb63e6bc9976dfcc123ea) in 0.456s. Peers: 24
execution_1                  | 2022-10-27 19:01:11.880+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,361 / 36 tx / base fee 34.61 gwei / 4,525,376 (15.1%) gas / (0xd241b4b8c768d5dd4f356814458f8ab42cb0fdd817b1697035ce9b49985b4d54) in 0.131s. Peers: 25
execution_1                  | 2022-10-27 19:01:11.943+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xd241b4b8c768d5dd4f356814458f8ab42cb0fdd817b1697035ce9b49985b4d54, finalized: 0x9dda6d2260772c262bfec355c89f9dfdb352911d63a93111f1510689eacc05b1, safeBlockHash: 0x07b7c3d1f838967c403091ac1fbe21251ab93e691da4a7b01e612a5e942bd2e6
execution_1                  | 2022-10-27 19:01:26.523+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,362 / 465 tx / base fee 31.59 gwei / 29,450,918 (98.2%) gas / (0x90314c404f144cd92c4453ec094f6fc11506d0748c6631a7c60ad0484b7b698a) in 1.552s. Peers: 25

Will try same PR with high perf spec

@yorickdowne
Copy link

With high performance flag and 8 GiB heap

execution_1                  | 2022-10-27 19:07:01.608+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,390 / 310 tx / base fee 26.89 gwei / 27,817,486 (92.7%) gas / (0x89922eb648eebb69d7479d687eb5bf063d2ff419491443dbeb9c6040de21d1d2) in 1.632s. Peers: 10
execution_1                  | 2022-10-27 19:07:12.605+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,391 / 157 tx / base fee 29.76 gwei / 18,091,376 (60.3%) gas / (0x6fb3d488b4f7d7eb423df11ef99986848c6ad299a2a7ca6042ec1fdff7117c1f) in 0.607s. Peers: 7
execution_1                  | 2022-10-27 19:07:25.132+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,392 / 173 tx / base fee 30.53 gwei / 14,668,258 (48.9%) gas / (0xe29619eb58e52ff811f7b44ebc4263cbe74a2c26daa86c4d895924c1d1f2cece) in 0.695s. Peers: 9
execution_1                  | 2022-10-27 19:07:38.057+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,393 / 191 tx / base fee 30.44 gwei / 17,560,650 (58.5%) gas / (0x9f63fff790df4165bfffa8088555de110d695d5a17364ab312cffd58ed302077) in 0.803s. Peers: 11
execution_1                  | 2022-10-27 19:07:49.100+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,394 / 126 tx / base fee 31.09 gwei / 13,580,916 (45.3%) gas / (0x63f7c90f8d3f6367d465f385476565b00074b69333df09806cb1e6c95817cd1b) in 0.584s. Peers: 12
execution_1                  | 2022-10-27 19:07:49.340+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x63f7c90f8d3f6367d465f385476565b00074b69333df09806cb1e6c95817cd1b, finalized: 0x07b7c3d1f838967c403091ac1fbe21251ab93e691da4a7b01e612a5e942bd2e6, safeBlockHash: 0x1f7a6d3def5a0f3b020392063b556dc71c557931aa1c152caecec4de8979423b
execution_1                  | 2022-10-27 19:08:00.582+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,395 / 126 tx / base fee 30.72 gwei / 12,194,224 (40.6%) gas / (0x645c290a9cd9a5f9de4b3e6ed5b860c08b0f1c382123e5f2585e1540b24879ba) in 0.510s. Peers: 11
execution_1                  | 2022-10-27 19:08:12.806+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,396 / 216 tx / base fee 30.01 gwei / 15,364,716 (51.2%) gas / (0x09f23c43855e771e9b6ec2028bfea6889af199643e91568e04307aac2348f98a) in 0.703s. Peers: 15
execution_1                  | 2022-10-27 19:08:24.775+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,397 / 150 tx / base fee 30.10 gwei / 12,369,149 (41.2%) gas / (0xf4ff30182be28cd7a5cbd298da44726f28e7833afd9f6c8b00e29eb1c82e7495) in 0.539s. Peers: 15
execution_1                  | 2022-10-27 19:08:37.574+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,398 / 168 tx / base fee 29.44 gwei / 16,062,157 (53.5%) gas / (0x015e1bdfde7e3dfeb0b439a184291dcfb3f82dffe77d263546df40b8509c3bea) in 0.685s. Peers: 17
execution_1                  | 2022-10-27 19:08:49.213+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,399 / 221 tx / base fee 29.70 gwei / 16,240,594 (54.1%) gas / (0xef463d9d801877e853ddb95451ebc33ea4e43a3881d2c3d050cff11846a18951) in 0.763s. Peers: 16
execution_1                  | 2022-10-27 19:08:49.488+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xef463d9d801877e853ddb95451ebc33ea4e43a3881d2c3d050cff11846a18951, finalized: 0x07b7c3d1f838967c403091ac1fbe21251ab93e691da4a7b01e612a5e942bd2e6, safeBlockHash: 0x1f7a6d3def5a0f3b020392063b556dc71c557931aa1c152caecec4de8979423b
execution_1                  | 2022-10-27 19:08:59.966+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,400 / 7 tx / base fee 30.01 gwei / 438,685 (1.5%) gas / (0x91c8bb93d7d3d81cc7f86bb38fc54ef4a29f022980e4cd7807b7f4db0c0cee42) in 0.031s. Peers: 18
execution_1                  | 2022-10-27 19:09:14.114+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,401 / 324 tx / base fee 26.36 gwei / 28,010,942 (93.4%) gas / (0x97ee78c67bac53a58e150286b1bdbe1cddbb1e813cb74fb4538b54301558b5b2) in 1.233s. Peers: 15
execution_1                  | 2022-10-27 19:09:24.949+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,841,402 / 261 tx / base fee 29.22 gwei / 17,501,281 (58.3%) gas / (0xa3e6fc368f8f85fd92fcf1e0f4b66221f2bb0f822e8a66513e0600eec14940a6) in 0.562s. Peers: 15

@ahamlat
Copy link
Contributor

ahamlat commented Oct 28, 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

@yorickdowne
Copy link

yorickdowne commented Oct 31, 2022

PR-4568

besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.2",} 0.576032692
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.5",} 0.941966907
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.8",} 1.325138276
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.95",} 1.703886547
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.99",} 1.973158954
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="1.0",} 2.305456674

Results without the PR on the same machine

besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.2",} 0.521787035
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.5",} 0.762127346
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.8",} 1.001419786
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.95",} 1.381477849
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.99",} 1.384336823
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="1.0",} 1.559825475

@yorickdowne
Copy link

Results with current 22.10.0 release

besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.2",} 0.551778338
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.5",} 0.734721314
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.8",} 0.906638342
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.95",} 1.696711798
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.99",} 1.728851189
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="1.0",} 1.737720906

@ahamlat
Copy link
Contributor

ahamlat commented Nov 9, 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).

image

We're still working on other optimizations.

@yorickdowne
Copy link

Huge improvement with the latest release. I need to test this again on a less beefy machine and, this looks great.

besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.2",} 0.242180321
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.5",} 0.327935817
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.8",} 0.424606676
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.95",} 0.614580991
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.99",} 0.691020564
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="1.0",} 0.705726215

@yorickdowne
Copy link

On a machine with 6 cores instead of 24, it's still good. Getting that 0.5 down to under 500ms would be great and, progress.

besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.2",} 0.553036181
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.5",} 0.736695146
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.8",} 1.03679112
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.95",} 1.449287504
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.99",} 1.478367941
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="1.0",} 1.623572103

@yorickdowne
Copy link

Same setup but with --Xplugin-rocksdb-high-spec-enabled

besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.2",} 0.291115869
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.5",} 0.396865192
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.8",} 0.528696181
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.95",} 0.625766636
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="0.99",} 0.744676603
besu_rpc_request_time{methodName="engine_newPayloadV1",quantile="1.0",} 2.214892495

@non-fungible-nelson
Copy link
Contributor

closing for tracking of performance issues in #4625

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

No branches or pull requests

7 participants