Performance regression on 3.6

[yperbasis]

looks like `release/3.6` has some big spikes compared to 3.5

[AskAlexSharov]

prune looks bad (5s instead 2s). but it happened in another time (doesn't correlate with newPayload). i will fix.
seems no file-merges that time
What correlates: accounts reads per sec. But there was couple similar reads/sec - without newPayload jump.
machines disk monitoring doesn't show anything: 02:01AM UTC
block num: 25642542

StateCache low hit rate:
[INFO] [07-30|02:01:00.770] [5/5 Execution] parallel done in=102.382557ms buf=75.5KB/512.0MB blk=25642541 blks=1 blk/s=9 txs=239 tx/s=2.33k gas/s=262.59M stepsInDB=0.55 step=9441.6 alloc=13.4GB sys=31.7GB isForkValidation=true isApplyingBlocks=false
[DBUG] [07-30|02:01:00.770] [5/5 Execution] storage stateCache="hit=1.13k miss=823 rate=58%" db=125 dbdur=3µs files=698 fdur=536ns

[INFO] [07-30|02:01:14.107] [5/5 Execution] parallel done in=1.632528511s buf=220.4KB/512.0MB blk=25642542 blks=1 blk/s=0.61 txs=1.22k tx/s=750 gas/s=36.72M stepsInDB=0.55 step=9441.6 alloc=10.4GB sys=31.7GB isForkValidation=true isApplyingBlocks=false
[DBUG] [07-30|02:01:14.107] [5/5 Execution] storage stateCache="hit=888 miss=2.43k rate=27%" db=39 dbdur=3µs files=2.39k fdur=42ns

Files read count (for Storage): 700 -> 2.390
Files read count (for Commitment): 1K -> 5.76k

So, seems in same time - and bigger block - and Gas/s: gas/s=263.37M -> gas/s=36.73M

Commitment: keys=1.39k keys/s=25.34k -> keys=2.98k keys/s=13.61k

(Numbers above are from logs, from blocks 25642541 and 25642542)
https://etherscan.io/block/25642541 - 238txs, Gas Used: 26,885,573
https://etherscan.io/block/25642542 - 1224txs, Gas Used: 59,950,601
So, it's in same time: bigger block - and block which has lower StateCache hit-rate:
Storage hit rate 58% -> 27%
Account Domain - also smaller hitrate 79% -> 26%

But i don't see disk IO spikes or PageFaults spikes that time in grafana

Logs:
message.txt

[AskAlexSharov]

Couple follow-ups to speedup ApplyLoop:
#22883
#22899

[AskAlexSharov]

about retry rate.

1. As i remember we do apply state changes after successful conflict-checks by

for keys { 
   mutex.Lock()
   put(key)
   mutex.Unlock()
} 

in my head - if we switch to:

mutex.Lock()
for keys { 
   put(key)
} 
mutex.Unlock()

it must reduce retry-rate, because "probability to see partial updates by other txs execution" reducing

2. in E2 we had ibs.balanceInc which are conflict-free state collisions.

3. if some work can move from applyLoop to workers - then better move. faster apply -> less retries.

block=25642541 keys=1.39k keys/s=25.34k spent=54.883512ms
block=25642542 keys=2.98k keys/s=13.61k spent=219.532085ms

commitment seems was not a bottleneck on this block. it was 2x slower than usually and worked over 2x more keys - but in total took 15% from 1.632667182s

4. If Apply loop see Tx=N got conflict on N-1 state. Then ApplyLoop can instantly re-exec Tx=N - without sending it to workers.

5. Theoretically - if producer see high repeat rate - it can slow-down sending new txs to workers. If Workers and ApplyLoop will see less "very future transactions" -> less will repeat rate. Because "Very Future transactions - have higher probability of conflicts and retry"

6. Perf of ApplyLoop can affect retry-rate greatly. (Perf of Workers too - but my head - less). Maybe we need simple bench - which will trigger our worst case scenario (Block full of 100% data dependent txs). It likely will highlight some our weakness.

7. "More workers" can cause more repeat rate. For example Sudeep did PR to increase result-queue size. Such PR can increase repeat-rate: workers don't wait when out-channel is full -> workers exec far-ahead transactions -> higher conflict probability -> higher conflict rate.

8. In AI-era: we can create set of unit-tests which catching retry-rate regression. "Block full of data-deps", "Block little dara-deps", "Block where end of block depends on begin of block", "Block where 10K txs with data-deps". Inject to that bench "throttled IO" (mock storage with various time.Sleep). Or even more crazy: write Fuzz test which trying to increase retry-rate (or AI can play as fuzzer: can ask research-loop to find block - which triggering high repeat-rate. Or configuration (workers/queue amount, disk latency) which does high repeat-ratio - and add panics on such configuration - so Alex cant set it in future). I know we have benches for repeat-rate - but it can be something more systematic - like "continuous fuzzing" (run something on server every night - to find new bad cases - based on known old bad cases)

9. The worst thing now is: improving execution speed can reduce overall system perf. Faster exec of 1 txn in worker -> more txs will fall to ApplyLoop -> more conflicts workers can produce -> more-far-ahead can run Workers ahead of ApplyLoop.

10. We have benches which show speed of parallel exec faster than sequential. But now we need somehow stop using "sequential exec" as a base.

11. Some optimizations for ApplyLoop:
    exec: merge writeSets without cloning in the apply loop #22883
    rawdb: receiptWriter - to hold long-living buffers. and avoid per-tx allocs  #22899

12. probably worth splitting "flush to db" to separated goroutine. So, "applyLoop" stay "more pure". (to avoid repeat-rate dependency on Chaindata size)

13. probably worth move writeSet.Normalize from ApplyLoop to Worker (maybe not possible). So, "applyLoop" stay "more pure". (Normalize - does read code from disk)

[AskAlexSharov]

Block characteristics:
number : 25642542 hash: 0x91f175cf...cc8bf7ad
txs : 1224
gasUsed : 59,950,601 / 60,000,000 (99.9% full)
distinct 'to' : 100 of 1224 txs
distinct senders : 1202
top target: 0xdac17f95...31ec7 ×1090 ← USDT

1090 of 1224 transactions — 89% — hit USDT. With 1202 distinct senders, so nonce chains don't serialize anything; the contention is
purely storage. That's the real-world version of exactly the pathology my synthetic benchmark fakes with one hot slot, except this is
genuine mainnet load at a full 60M gas.

---

txs: 1224 distinct parties: 1237
parties touched by >1 tx: 11 of 1237
hottest party (idx 25): 1071 txs = 87.5%
parties per tx: 2 → 1108 txs, 1 → 114 txs, 3 → 2 txs

1226 of 1237 balance slots are touched by exactly one transaction. The entire conflict structure is one hot party plus ten
weakly-shared ones plus a sea of private slots. That is precisely what realBlockPathGenerator encodes — and the 87.5% in my model
isn't a guess, I derived hotRecipientShare = 8 from this 1071/1224 directly, so it matches exactly.

---

1K txs: did transfer USDT from "different senders" to "1 hot recepitent" 0x28c6c062…bf21d60
(it's not usdt addr. usdt just did accounting)

block_25642542_2.json.gz

[taratorio]

update: I made an unintentional mistake and run bench-n1 (release/3.5 branch) with EXEC3_PARALLEL=false (serial exec) instead of with its default EXEC3_PARALLEL=true so we weren't comparing default 3.5 vs default 3.6. I've updated the process now, will send a screenshot of how the comparison looks on Monday.

however this did highlight we have some anomaly blocks with parallel exec where we take quite long to exec due to number of conflicts/re-executions. this goes away with BALs since there we have perfect 0 conflict parallelism. it does a raise the question if we should try to do something about those parallel exec bumps in the meantime (3 months until glamsterdam)

[taratorio]

if the new payload metrics over the weekend are looking good then this is probably not a blocker for 3.6

[taratorio]

Looks a bit more comparable with 3.5 now when I switched both to parallel exec. Although looks like 3.6 still had some larger spikes than 3.5 (check below). Up to Alex/Andrew if you want to drill more into it.

Looks like Alex may have found the reason in #22963. Let's see

[AskAlexSharov]

seems i found #22963

[taratorio]

updated bench-n2 with latest release/3.6 running #22963 just now.
let's check tomorrow/in 2 days