Tune RPS of eth_getTransactionReceipt

[tholcman]

System information

Erigon version: ./erigon --version
erigon version 2.60.3-1f73ed55

same behavior was in older versions
erigon version 2.59.x, 2.60.x

OS & Version: Windows/Linux/OSX
linux, docker image thorax/erigon:v2.60.3
erigon, prysm, rpcdaemon running in one pod in kubernetes as the only workload on the node (+ some system stuff)

Erigon Command (with flags/config):

erigon --datadir /data/erigon --authrpc.jwtsecret /data/shared/jwt_secret --private.api.addr 127.0.0.1:7458 --port 31782 --nat extip:x.x.x.x --p2p.allowed-ports yyyyy,zzzzz --batchSize 512M --chain mainnet --metrics --metrics.addr 0.0.0.0 --metrics.port 9005 --authrpc.port 8551 --db.size.limit 7TB --db.pagesize 16KB --bodies.cache 6GB --maxpeers 300 --prune=

RPCDaemon flags:

rpcdaemon  \
  --datadir /data/erigon \
  --db.read.concurrency=48 \ # we have tried many different values 1, 2, 16, 24, 256, 1000, 10000
  --http.addr 0.0.0.0 --http.api eth,erigon,web3,net,debug,trace,txpool --http.port 8335 --http.vhosts * --http.timeouts.read 65s --rpc.batch.limit 400 --rpc.batch.concurrency 4 --rpc.returndata.limit 100000000 --ws \
  --txpool.api.addr localhost:7458 \
  --verbosity=debug --pprof --pprof.port=6062 --pprof.addr=0.0.0.0 --metrics --metrics.addr 0.0.0.0 --metrics.port 9007 \
# we have also trie --private.api.addr localhost:7458

we have also tried to omit the db.read.concurrency and set GOMAXPROCS to many different values ... no change

Consensus Layer: prysm

Chain/Network: ethereum mainnet

HW Specs:
GCP n4-standard-16 = 16vCPUs, 64GB Ram
disk: 4TB, (hyperdisk balanced), 36000IOPS, 500MB/s

Actual behaviour

We are running some performance tests, calling eth_getTransactionReceipt with many different txids, it looks like rpcdaemon is doing something synchronously or in one thread only:

# we have list of transactionHashes in transactions.txt altogether 32k tx ids, some from the latest blocks & some from blocks from the last 1/3 of the chain

$ cat transactions.txt | shuf | jq --raw-input -rcM '{"id": 1,"jsonrpc": "2.0","method": "eth_getTransactionReceipt","params": [ . ]}' | jq -rscM 'map({method: "POST", url: "http://127.0.0.1:8335", body: . | @base64 , header: {"Content-Type": ["application/json"]}}) | .[]' | vegeta attack -format json -rate=0 -max-workers 1 -duration 30s -timeout 1s| vegeta report
Requests      [total, rate, throughput]         723, 24.05, 24.04
Duration      [total, attack, wait]             30.076s, 30.068s, 8.641ms
Latencies     [min, mean, 50, 90, 95, 99, max]  586.332µs, 41.594ms, 35.886ms, 83.867ms, 93.202ms, 116.626ms, 148.232ms
Bytes In      [total, mean]                     1490000, 2060.86
Bytes Out     [total, mean]                     101943, 141.00
Success       [ratio]                           100.00%
Status Codes  [code:count]                      200:723

to emphasize:

$ cat ... | vegeta ... -max-workers 1 ...
Requests      [total, rate, throughput]         723, 24.05, 24.04
Latencies     [min, mean, 50, 90, 95, 99, max]  586.332µs, 41.594ms, 35.886ms, 83.867ms, 93.202ms, 116.626ms, 148.232ms

= 24RPS

if we increase concurrency of the test the performance goes very slighly up but responses starts slow down significantly:

$ cat ... | vegeta attack ... -max-workers 5 ... 
Requests      [total, rate, throughput]         1029, 34.27, 34.09
Latencies     [min, mean, 50, 90, 95, 99, max]  500.26µs, 146.413ms, 142.153ms, 274.241ms, 312.796ms, 373.658ms, 483.553ms

= 34RPS

with more workers (10, 20, ...) it stays ~same 35

if we try to keep certain rate the API starts to slow down and eventually starts failing:

$ cat ... | vegeta attack ... -rate=200 -timeout 1s
Requests      [total, rate, throughput]         3000, 100.03, 6.61
Latencies     [min, mean, 50, 90, 95, 99, max]  848.307µs, 990.396ms, 1s, 1.001s, 1.001s, 1.001s, 1.002s
Success       [ratio]                           6.83%
Status Codes  [code:count]                      0:2795  200:205

The daemon is running 22 threads:

ps -T -p $RPCDAEMON_PID | wc -l
23

CPU utilization goes from 5% (idle) to ~10-14% during tests
Disk
peak write iops ~15k not changed during the test
peak read iops ~1.5k(idle) -> 3k(during tests)
^ far far away from the limit of 36k (actually have tried to run additional workload (fio) during tests and was able to achieve ~70k peak iops)

By far it is not using all available hardware...

Expected behaviour

with increasing clients concurrency I would expect increasing performance approximately linearly until the HW is saturated - to utilize parallelization.

pprof during the -max-workers 10 tests

[AskAlexSharov]

See: #9486

Try re-index files:
rm snapshots/*idx
erigon snapshots index

After re-indexing set: —db.read.concurrency=5000

see also: —rpc.batch.limit and —rpc.batch.concurrency

After this - will see.

You also can compare it with eth_getBlockByNumber - to exclude TxnLookup index use.

[tholcman]

eth_getBlockByNumber runs about 31k RPS with ~85% CPU utilization and almost no change in IOPS

our rpc daemon is configured to have

--rpc.batch.limit 400
--rpc.batch.concurrency 4

but in these test we are not using batches

we are running erigon --datadir /data/erigon snapshot index, but it is indexing only in 4 parts at a time, it is super slow (looks like it would index 20M blocks in 3 months!) oh 004500 means 004500k, so not so slow , and it even looks like it stopped progressing (see logs below):

are there any params to make it faster - use more threads, utilize the HW more(not using all CPUs, nor IOPS, nor disk bandwith)?

[INFO] [07-10|07:45:15.791] [Indexing] Indexing                      progress="v1-004500-005000-transactions.seg=40%, v1-005500-006000-transactions.seg=42%, v1-006000-006500-transactions.seg=50%, v1-006500-007000-transactions.seg=50%" total-indexing-time=3m40s alloc=4.1GB sys=5.3GB
[INFO] [07-10|07:45:35.794] [Indexing] Indexing                      progress="v1-004500-005000-transactions.seg=44%, v1-005500-006000-transactions.seg=46%, v1-006000-006500-transactions.seg=50%, v1-006500-007000-transactions.seg=50%" total-indexing-time=4m0s alloc=4.3GB sys=5.3GB
[INFO] [07-10|07:45:55.793] [Indexing] Indexing                      progress="v1-004500-005000-transactions.seg=47%, v1-005500-006000-transactions.seg=50%, v1-006000-006500-transactions.seg=50%, v1-006500-007000-transactions.seg=50%" total-indexing-time=4m20s alloc=3.4GB sys=5.3GB
[INFO] [07-10|07:46:15.792] [Indexing] Indexing                      progress="v1-004500-005000-transactions.seg=50%, v1-005500-006000-transactions.seg=50%, v1-006000-006500-transactions.seg=50%, v1-006500-007000-transactions.seg=50%" total-indexing-time=4m40s alloc=3.6GB sys=5.3GB
[INFO] [07-10|07:46:35.793] [Indexing] Indexing                      progress="v1-004500-005000-transactions.seg=50%, v1-005500-006000-transactions.seg=50%, v1-006000-006500-transactions.seg=50%, v1-006500-007000-transactions.seg=50%" total-indexing-time=5m0s alloc=3.7GB sys=5.3GB
[INFO] [07-10|07:46:55.791] [Indexing] Indexing                      progress="v1-004500-005000-transactions.seg=50%, v1-005500-006000-transactions.seg=50%, v1-006000-006500-transactions.seg=50%, v1-006500-007000-transactions.seg=50%" total-indexing-time=5m20s alloc=3.8GB sys=5.3GB
[INFO] [07-10|07:47:15.790] [Indexing] Indexing                      progress="v1-004500-005000-transactions.seg=50%, v1-005500-006000-transactions.seg=50%, v1-006000-006500-transactions.seg=50%, v1-006500-007000-transactions.seg=50%" total-indexing-time=5m40s alloc=4.0GB sys=5.3GB
[INFO] [07-10|07:47:35.793] [Indexing] Indexing                      progress="v1-004500-005000-transactions.seg=50%, v1-005500-006000-transactions.seg=50%, v1-006000-006500-transactions.seg=50%, v1-006500-007000-transactions.seg=50%" total-indexing-time=6m0s alloc=4.2GB sys=5.3GB

[AskAlexSharov]

Please avoid too emotional involvement: terrible, 3 months!, etc...

Indexing threads amount: choosing threads amount based on GOMAXPROCS/GOMEMLIMIT. Maybe you forgot remove this to env variables? Or you can try increase them to increase amount of indexing threads.

50% - it's normal to stop there - we don't have more granular progress logging. it will jump to 100% after long time. it's CPU-bounded.

eth_getBlockByNumber runs about 31k RPS - is it bad or need improve? I advise: first improve RPS of eth_getBlockByNumber to the level you like, then move to eth_getBlockReceipts and then to eth_getTransactionReceipt (if your APP can't use eth_getBlockReceipts by some reason).

[tholcman]

Sorry for being emotional, but already digging into it for almost week with no progress.

After re-indexing & --db.read.concurrency=4096:

eth_getBlockByNumber
runs about ~31000 RPS = perfectly fine

eth_getBlockReceipts
shuffled blocks 15M-20M

• 1 worker 24.68 RPS
• 2 workers 46.39 RPS
• 5 workers - 64.32 RPS
• 10 workers 68.34 RPS - not getting better with higher concurrency
  during test with ~68RPS - CPU went to 15-22%, disk far from full utilization, again we are not able to fully utilize the HW

eth_getTransactionReceipt

• 1 worker 59.45RPS
• 5 workers 79.29RPS
• 10 workers 51,78 RPS - not sure why it went so low
  Latencies [min, mean, 50, 90, 95, 99, max] 423.357µs, 193.385ms, 187.833ms, 357.982ms, 402.02ms, 483.233ms, 603.81ms
  = still the same
  looks like there is some lock / single threaded (or 2-threaded) thing which blocks - performance with concurrency of 2 and higher almost doesn't grow.

For comparison Geth eth_getTransactionReceipt
on comparable HW, slightly faster disks

• 1 worker 365.65
• 2 workers 733.73
• 9 workers 2108.79 with max latency (about max)
  Latencies [min, mean, 50, 90, 95, 99, max] 388.301µs, 4.264ms, 3.484ms, 7.966ms, 10.238ms, 16.374ms, 45.476ms
  ^ performance grows linearly until the HW is fully utilized

[AskAlexSharov]

nice.

1. let's try increase --db.read.concurrency to 20_000 (just to check if it's not our "some lock").

2. try git branch no_txhash_calc_before_cache. removed there some perf overhead - which is bad for random blocks read.

3. switch to git branch allow_madv_normal and start with evn variable SNAPSHOT_MADV_RND=false (maybe it will help for your type of disk).

4. with best result - try to draw new pprof image and add here. You can show:

go tool pprof -png http://127.0.0.1:6060/debug/pprof/profile/?seconds\=20 > cpu.png

go tool pprof -alloc_objects -png http://127.0.0.1:6060/debug/pprof/heap?seconds\=20 > mem.png

go tool pprof -png http://127.0.0.1:6060/debug/pprof/block?seconds\=20 > block.png

go tool pprof -png http://127.0.0.1:6060/debug/pprof/mutex?seconds\=20 > mutex.png

thank you

[tholcman]

add 1:

have tried same test with -max-workers 6 and different db.read.concurrency:

--db.read.concurrency 1

Requests [total, rate, throughput] 662, 22.04, 21.91
Latencies [min, mean, 50, 90, 95, 99, max] 56.805ms, 273.064ms, 233.573ms, 482.105ms, 551.368ms, 642.475ms, 728.431ms

--db.read.concurrency 2 RPS 38.58 (+75%)

Requests [total, rate, throughput] 1158, 38.58, 38.37
Latencies [min, mean, 50, 90, 95, 99, max] 2.735ms, 155.825ms, 151.598ms, 234.42ms, 259.295ms, 314.545ms, 370.432ms

--db.read.concurrency 5 RPS 43.99 (+14%)

Requests [total, rate, throughput] 1321, 43.99, 43.85
Latencies [min, mean, 50, 90, 95, 99, max] 1.148ms, 136.657ms, 132.176ms, 246.403ms, 284.107ms, 348.165ms, 424.301ms

--db.read.concurrency 20000 53.56

--db.read.concurrency 200000 58.56

A change between 1 and 2 is reasonable, but later the performance doesn't grow as expected - it looks like it is waiting for something being executed in 2 threads (very likely just some part of processing). And HW even in the highest configuration is pretty calm (CPU 10%, peak read IOPS at most on 3k + 20k write, we should have 36k available 72k in peak).

I have tried profiling with release version 2.60.3-1f73ed55, but mem, block and mutex are empty, are the commands you have shared ok?

[tholcman]

I have identified the problem ...
call stack:

(api *APIImpl) GetBlockReceipts -> (r *BlockReader) TxnLookup -> (s *RoSnapshots) View() -> (s *RoSnapshots) lockSegments -> (rw *RWMutex) Lock

// Lock locks rw for writing.
// If the lock is already locked for reading or writing,
// Lock blocks until the lock is available.
func (rw *RWMutex) Lock() {
  ...

What I have tried is not locking for TxnLookup:
in https://github.com/ledgerwatch/erigon/blob/release/2.60/turbo/snapshotsync/freezeblocks/block_reader.go#L1018

	view := r.sn.View(false)
	defer view.Close(false)

and on https://github.com/ledgerwatch/erigon/blob/release/2.60/turbo/snapshotsync/freezeblocks/block_snapshots.go#L2043-L2055

func (s *RoSnapshots) View(params ...bool) *View {
        ...
	if len(params) < 1 || params[0] {
		s.lockSegments()
	}
        ...

func (v *View) Close(params ...bool) {
       ...
	if len(params) < 1 || params[0] {
		v.s.unlockSegments()
	}
        ...

The perf rocketed to sky, we had 800+ RPS and HW is finally getting utilized (CPU 75%, peak read IOPs 25k).

Is the locking for read-only (rpcdaemon) necessary? Is it necessary even for historical segments? Or can it lock segments one-by-one? And I have noticed that "View" is using read/write lock, would it improve perf if we would use RLock (I guess it is read-only lock)?

[tholcman]

Ok, I dug a bit deeper into it, this is what I have tried

tholcman@d677685#diff-72924d5ce1ba1962b50ba71cd48ca3c4ac4c54c1322e7db1bbac2108f760e517

Instead of using r.sn.View(), which locks all segment types from the call until the defer (return)

• I lock only the segments which are actually used
• instead of RWMutex.Lock() which is, as far I understand, ReadWrite, I have used RWMutex.RLock() and corresponding RUnlock()
• instead of defer I call RUnlock() immediately after reading the data (I hope I did this right and haven't forgotten any "returns")

$ ... | vegeta attack  ... -max-workers 20 -duration 20s  ... | vegeta report
Requests      [total, rate, throughput]         13031, 651.52, 650.27
Latencies     [min, mean, 50, 90, 95, 99, max]  894.124µs, 30.711ms, 25.305ms, 61.246ms, 73.086ms, 104.579ms, 351.289ms

RPS: 651.52 while keeping all necessary locks (I hope), with some tuning I guess we can get even better.

Can anyone, more experienced than me, review my approach or properly review the Locking in turbo/snapshotsync/freezeblocks/block_reader.go ?

[AskAlexSharov]

@tholcman yes. I can do it today.

• for sure there must be RLock
• about "lock not all Types" - probably i also make sense (files are enough independent. even if 1 type of files was merged to bigger segment - it's still will return valid block)
  Here is the PR: rpc bottleneck: block files mutex (e2) #11155

only open question is: does it works better than "1 rwmutex for all types" or not

[AskAlexSharov]

you also can --http.compression=false

[AskAlexSharov]

FYI: also created #11157

[tholcman]

I would say it is not ready for PR. I would probably move the methods into RoSnapshots and walk through all the uses of View() and refactor them to these methods & immediate RUnlock (there is ~12? uses of View() in BlockReader).

OR change the View() to use RLock (all the segment & types) - it may have the significant impact (as original RW lock is exclusive) with minimal effort.

Which path would you suggest? (I don't have that much time during weekdays to properly test both).

& do I understand correctly that I should prepare PR into release/2.60? Will the change get also into E3 - I see the same code also in main so I guess it is affected as well?

[AskAlexSharov]

@tholcman "all the uses of View()" - did it in my PR. "OR change the View() to use RLock" - also done in my PR.

[AskAlexSharov]

i did
e2 PR: #11155
e3 PR: #11156

[tholcman]

Oh great! Thank you! When is the expected next minor release? I will use custom built image from release/2.60 for more of our benchmarks. BTW looks like optimal db.read.concurrency in our case will be around 120-150.

[AskAlexSharov]

@tholcman it's because you test on hot data. try test on cold data (various block nums across all history) and likely you will see that bigger read.concurrency helps - if disk can handle parallel reads.

[tholcman]

Actually my test simulates a traffic which we see from our clients:

• ~3 clients are following the tip "get last block" & several batch (30) calls to "get all it's receipts"
• ~2 clients doing "backfill" - "get random block from last 1/3 of the chain" & same batch calls to get all receipts
  I guess they want to be implementation independent so they don't use eth_getBlockReceipts, or they just have a old codebase

Also the list of transactions I used for the vegeta tests was from "random blocks from the last 1/3 of the chain" (as i found this the most problematic).

Can I port your changes to node-real/bsc-erigon? I guess they are no longer in sync with this repo and this fix would be beneficial there as well (and on our BSCnodes).

[AskAlexSharov]

yes. please.