Performance regression on the chain tip

[mriccobene]

Many tests (sync-from-scratch, tip-tracking) are failing on the main branch due to poor Erigon performance on the chain tip. Usually, Erigon stays in sync 99/100% of the time. But currently, on many tests, the percentage is below 75%. Also, there are performance warnings in the logs.

See for example the last sync from scratch run

[VBulikov]

mriccobene added Imp1 as Importance

[yperbasis]

Analysis (May 3 mainnet run, 67% in-sync)

Symptom pattern — 19 in-sync windows averaging ~4.5 min each, separated by ~1 min out-of-sync gaps. 48 treating forkChoiceUpdated as asynchronous events during the tip-tracking phase (446 FCUs total). Forkchoice timings sit at flush=150–300ms, commit=150–300ms in steady state but spike to flush=2s commit=2s (peaks flush=9s commit=4s) every 2–4 min.

Mechanism — FcuBackgroundCommit defaults to false (node/ethconfig/config.go:116), so the FCU's flush+commit runs in the foreground inside runForkchoiceFlushCommit. When a Retire Blocks → collate-build → state merge burst contends for disk IO, that fsync chain blows out to seconds; Caplin times out with ExecutionStatusBusy and that's the "out of sync" gap. Cross-referencing the log, the spike sequence is always Retire Blocks (5–7s) → collate-build → state merge done → slow FCU. holding state collation at block snapshot boundary printed 381 times. temp/ grew 3 GB, fd count climbed 16→3206.

Regression timeline — tip-tracking was last green on 2026-03-15 (b129b92a94) and has failed every weekly run since 2026-03-22 (ea6a21dc3a). So the root commit is in that 1-week window.

Top candidates:

• execmodule: extract PipelineExecutor, internalize ForkValidator #19961 / 3248639b5b (Mar 22) — execmodule: extract PipelineExecutor, internalize ForkValidator. Large FCU refactor; runForkchoiceFlushCommit now chains 3 separate MDBX transactions per FCU.
• commitment: enable warmup cache for all paths + add cache miss counters #19952 / 9a77d9e51b (Mar 20) — commitment: enable warmup cache for all paths. Flipped EnableWarmupCache(true) for the isApplyingBlocks path immediately before the first failure.

Later cherry-picks likely compound but aren't the root:

• warmuper: blocking and more  #20819 / bfc30afb89 (Apr 28) — warmuper: made WarmKey blocking instead of drop-on-full.
• enforce block-snapshots cap inside aggregator collation #20900 / 2e50c368f1 (Apr 29) — enforce block-snapshots cap inside aggregator collation.

Current status

Three bisection probes dispatched:

Probe	Commit	Workflow	Run
Suspect (Apr 28)	bfc30afb89	Tip tracking	https://github.com/erigontech/erigon/actions/runs/25674778861
Last-green (Mar 15)	b129b92a94	Tip tracking	https://github.com/erigontech/erigon/actions/runs/25674975157
Suspect cross-check	bfc30afb89	Sync from scratch	https://github.com/erigontech/erigon/actions/runs/25674976642

The two tip-tracking probes serialize on the tip-tracking self-hosted runner; expected wall-clock ~24h for both. Sync-from-scratch runs on a different pool. I'll bisect the Mar 15…Apr 28 window once these come back.

[mriccobene]

The "tip-tracking & migration" test is fragile. It is more convenient to use sync-from-scratch tests like:

• sync-from-scratch (it uses archive mode)
• sync-from-scratch minimal node

It could also be beneficial to compare the main branch with the release branch, where the problem either does not exist or is less impactful.

[yperbasis]

Important: tip-tracking on main is blocked by a testbed infra issue, not by tip performance

Update from running bisection probes — the QA - Tip tracking & migration workflow on main is not actually exercising tip behavior right now. Both my dispatched probes (commits bfc30afb89 and b129b92a94) failed in the stabilization phase in ~42 min, never reaching the part of the workflow that runs the candidate's binary.

The stabilization step runs the reference Erigon binary at /opt/erigon-versions/reference-version/erigon against /opt/erigon-versions/reference-version/datadir to bring the testbed up to head before testing the candidate. That reference binary deterministically fails at mainnet block 24785118:

[WARN] [4/6 Execution] Execution failed block=24785118 txNum=3414988061
  err="invalid block, txnIdx=114, gas used by execution: 20855803,
       in header: 21032903"

It then retries in a loop for ~30 min, balloons to ~120 GB RSS, and gets OOM-killed (exit code: -9). The candidate binary built on our branch is never invoked.

This is not new — the same failure killed last week's scheduled main tip-tracking run on May 10 in 45m23s, exact same step. So the tip-tracking failures on main referenced in this issue are not measuring tip performance — they're being blocked before the test starts.

release/3.4 tip-tracking is healthy: the workflow's reference-dir logic resolves release/X.Y branches to /opt/erigon-versions/reference-version-X.(Y-1)/datadir (so release/3.4 uses reference-version-3.3), and that path works correctly — recent runs pass consistently.

Implication for this issue

The QA report conflates two distinct failures:

1. Sync-from-scratch — genuine performance regression in our code (the 67% in-sync metric in the May 3 run is real and is what the analysis above addresses).
2. Tip-tracking on main — blocked by a broken reference binary on the QA runner, not by tip performance.

I'll continue bisection using sync-from-scratch (chiado already passed at bfc30afb89; mainnet probes are in flight). Tip-tracking on main will need the reference binary at /opt/erigon-versions/reference-version/ rebuilt against the current mainnet state before it can produce a useful signal. /cc QA team.

[yperbasis]

Local profiling on mainnet + head-to-head with release/3.4

Ran the patched yperbasis/issue21008 build on a mainnet minimal node and compared steady-state tip behaviour against release/3.4 on the same chaindata, same NVMe, same hardware. (To get r34 to boot against a main-touched datadir, opened #21282 to restore JSON wire-format compatibility for chain.Config.ChainID / TerminalTotalDifficulty.)

Steady-state FCU latency at live mainnet tip

Both runs at live tip, neither overlapping a snapshot retire/collate/merge burst. Disk idle in both windows.

stat	main (53 samples)	release/3.4 (39 samples)	Δ
min	144 ms	53 ms	−63 %
p50	229 ms	149 ms	−35 %
p90	319 ms	210 ms	−34 %
p99	384 ms	225 ms	−41 %
mean	239 ms	150 ms	−37 %

main's median FCU is ~80 ms slower than 3.4's, with a noticeably wider tail. Even without observing a multi-second burst spike (the dramatic events described in the original report), the baseline per-FCU latency moved up by ~35–40 %.

Mechanism — confirmed by the FCU goroutine stack

Compared runForkchoiceCommit on r34 vs runForkchoiceFlushCommit on main, and traced what each enters from updateForkChoice. Two structurally different shapes:

release/3.4 — FCU body does one flush+commit only

updateForkChoice(...)
└── writeForkChoiceHashes / TruncateCanonicalChain
└── runForkchoiceCommit
    ├── sd.Flush(tx)
    └── tx.Commit()            // single MDBX commit = single fsync

TxLookup / Senders / BlockHashes / Finish run in a separate background StageLoop (execution/stagedsync/stageloop/stageloop.go:62) on its own cadence — decoupled from the FCU response.

main — FCU body routes through the full stagedsync pipeline

updateForkChoice(...)
└── pipelineExecutor.RunLoop                       // forkchoice.go:505
    ├── sync.Run(sd, tx, ...)                       // executor.go RunLoop body
    │   ├── BlockHashes
    │   ├── Senders
    │   ├── Execution
    │   ├── TxLookup            ← writes txhash→block index per FCU
    │   └── Finish
    └── sync.RunPrune(...)
└── runForkchoiceFlushCommit
    ├── sd.Flush(rwTx)
    └── rwTx.Commit()                                // MDBX commit = fsync

Caught the FCU goroutine inside SpawnTxLookup → ETL.Transform → tx.Hash() during a profile snapshot — confirming the lookup-index write pass really does run per-FCU on main.

Why it costs more

5-min fgprof at tip showed 88 % of the FCU commit wall-time is parked inside mdbx_txn_commit_ex (4.42 s wall vs 0.33 s CPU over 25 FCUs). The commit isn't CPU-bound, it's fsync-bound. main's commit has more dirty pages to durably write because TxLookup / Senders ran into the same tx before the commit. r34's commit has only SharedDomains.Flush output.

Burst amplification

Under quiet disk this just costs +80 ms median. When a retire/collate/merge burst hits the same NVMe (#20900 enforcing the block-snapshots cap, plus the normal background merge writes), per-FCU fsync stretches into seconds. Pre-#19961 the StageLoop ran independently of FCU and a burst stretched the StageLoop's cadence without blocking the FCU response. Post-#19961, every per-slot FCU response is downstream of TxLookup's MDBX writes, so a burst-stalled MDBX directly stalls the FCU and Caplin times out → treating forkChoiceUpdated as asynchronous / ExecutionStatusBusy → the out-of-sync windows you originally documented.

Likely root cause

#19961 (3248639b5b, Mar 21) — "execmodule: extract PipelineExecutor, internalize ForkValidator". The PR description says "no functional changes". Structurally true — the call graph was just reorganised. But moving TxLookup / Senders / Finish from the background StageLoop into the synchronous FCU path via PipelineExecutor.RunLoop is a behaviour change: the work happens at the same total rate, but now on the critical path of every FCU response.

Matches the original timeline: tip-tracking last green b129b92a94 (Mar 15), failed every run since ea6a21dc3a (Mar 22) — #19961 lands inside that window.

Raw data + profiles

Captured locally during the session (CPU/fgprof/heap/goroutine/block/mutex for both main and r34, plus FCU-timing logs). Happy to attach the pprof files if useful for further inspection.

Suggested next steps

1. Move TxLookup / Senders / Finish out of the FCU critical path back to a background loop equivalent to release/3.4's StageLoop. Keeps PR execmodule: extract PipelineExecutor, internalize ForkValidator #19961's nice consolidation of the executor type but undoes the synchronous-per-FCU staging that the rename quietly introduced.

2. Alternatively, try --fcu.background.commit=true (the flag already exists at node/ethconfig/config.go:116; gated off because rawdb + Coherent cache need wiring). That decouples the FCU response from the MDBX fsync, masking both the +80 ms steady-state cost and the burst spikes.

3. The background-merge contention story is real but secondary — even with the disk idle, the per-FCU baseline regressed. Throttling merges (db/state: add optional throttle to MergeLoop to reduce disk I/O pressure #20486) helps the spike side but won't recover the +80 ms baseline.

4. The bisection probes you have running on sync-from-scratch will independently confirm or rule out execmodule: extract PipelineExecutor, internalize ForkValidator #19961 — looking forward to those results.

[yperbasis]

Tip-spike captures from the last 9 hours — refined picture

Caught 4 spike events at live mainnet tip (one prune, three aggregations) while leaving the trigger script running. None reproduced the multi-second `flush=Xs commit=Ys` pattern from the original QA report, but they all hit the same code path and the data lets us bound the magnitude on a fast NVMe.

Burst events and their FCU impact

time	event	duration	concurrent FCU commits
23:55:39	`Background Prune`	1.0 s	next FCU commit=304ms (baseline ~220ms)
02:47:49	`[snapshots] aggregated step=9027`	11.32 s	291ms, 321ms, 158ms
03:16:16	`Background Prune`	1.0 s	not captured in detail
06:17:12	`[snapshots] aggregated step=9028`	10.61 s	peaks 479ms, 569ms, 467ms; sustained 300-500ms for ~2 min

So on this hardware (NVMe with plenty of bandwidth) the FCU commit only elevates ~2-3× over baseline during a single-step aggregation, not the multi-second `flush=9s commit=4s` the May 3 QA report described. Peak observed: 569ms.

Where the merge work goes — confirmed CPU-bound, not disk-bound

CPU profile during the 11.32-s aggregation (06:17, similar profile to the others):

cum %	function
82 %	`AggregatorRoTx.mergeFiles → DomainRoTx.mergeFiles`
62 %	`DomainRoTx.commitmentValTransformDomain → BranchData.ReplacePlainKeys`
52 %	`findShortenedKey → BtIndex.Get → BpsTree.Get`

iostat during the burst: 145 MB/s wMB/s, 4.5 % disk util. The disk is not saturated. The merge is CPU-bound in `commitmentValTransformDomain` — re-pointing every plain-key reference in the new merged commitment branch to the offsets in the merged storage/account files via per-key B-tree searches.

So the dominant per-burst cost on our hardware is CPU spent in `findShortenedKey → BtIndex.Get`, not disk fsync amplification. fsync amplification is real but modest at ~+100 ms because the disk has headroom; on the QA testbed (slower disk), the same merge produces fewer MB/s of headroom and fsync stretches harder, which matches the multi-second peaks they reported.

Practical implication

The "FCU foreground commit" framing (from the earlier analysis on this issue) is correct as a mechanism — the FCU commit fsyncs while merge writes are in flight — but its magnitude on any specific hardware is determined by how saturated that hardware's write queue gets. On a hardware-rich workstation, it's ~+100ms. On the QA testbed, it's multi-second.

The CPU side of `commitmentValTransformDomain` is the more universal lever: every box runs the same code on the same merge ranges, so a CPU optimization there cuts the burst duration everywhere. If the burst is shorter, the FCU has a smaller window in which to overlap.

Two complementary fix surfaces:

• CPU: cache the merged-file `BtIndex.Get` calls in `findShortenedKey` — same merged file is searched for every branch's plain-key references, so identical full keys recur (hot contracts: USDC, Uniswap routers, etc.) and would hit the cache. Trying this now.
• Latency-isolation: `FcuBackgroundCommit=true` (already exists, gated on `node/ethconfig/config.go:116` work). Removes FCU's exposure to fsync queue entirely on any hardware.

All raw profile data (CPU/fgprof/goroutine/iostat/heap snapshots per spike) saved locally under `tmp/profiles/spike-*`.

[AskAlexSharov]

commitmentValTransformDomain - this func used only for Commitment.Domain references (Artem working on releasing files to disable it)

[yperbasis]

Bisection complete: regression introduced by #20035

The mainnet tip performance regression was introduced by 082697d2a0 "caplin: unified Engine API client for standalone mode" (#20035), merged 2026-03-25.

Evidence

Bisection narrowed to adjacent commits on the same day:

Commit	Date (UTC)	Mainnet in-sync %	Source
19f44b15cd (parent)	2026-03-25 21:28	100% ✓	run 26167188026
082697d2a0 (#20035)	2026-03-25 22:38	3% ✗	run 26167198192

Parent is a 45-line addition to cmd/integration (zero runtime impact); child is a 3698-LOC, 35-file change. The regression appears at exactly this commit.

Bisection path with all data points (QA - Sync from scratch (minimal node), mainnet):

Commit	Date	in-sync%	Run time
b129b92a94	Mar 15	100% ✓	3h08m
9dd5317623	Mar 18	100% ✓	4h01m
9a77d9e51b	Mar 20 23:26	100% ✓	4h47m
b772ea8f6a	Mar 21	100% ✓	—
3248639b5b	Mar 21 17:40	100% ✓	—
26e6f5bdb4	Mar 24	100% ✓	6h54m
6b7412525e	Mar 26 00:55	100% ✓	7h08m
19f44b15cd	Mar 25 21:28	100% ✓	7h26m
082697d2a0	Mar 25 22:38	3% ✗	6h44m
7a25711a03	Mar 26 13:40	2% ✗	6h35m
ec45be4827	Apr 1	3% ✗	5h35m
9f5504aabb	Apr 11	2% ✗	5h02m
bfc30afb89	Apr 28	66% ✗	3h07m

(The Apr 11 peak severity gradually mitigates by Apr 28 — some commit in 9f5504aabb..bfc30afb89 partially fixes the regression. Worth identifying but not the root cause.)

Why this commit is suspect

#20035's stated goal is to add a standalone-mode HTTP/JWT Engine API client for Caplin. It should not have affected embedded mode. But the diff also touches the embedded-mode fork choice path:

• cl/phase1/forkchoice/forkchoice.go (+25)
• cl/phase1/forkchoice/get_head.go (22 changed)
• cl/phase1/forkchoice/on_block.go (10 changed)
• cl/phase1/forkchoice/utils.go (31 changed)
• cl/phase1/stages/clstages.go (+70)
• cl/phase1/stages/forkchoice.go (8 changed)
• execution/engineapi/engine_server.go (16 changed)

The PR description even calls out: "Fork choice fixes: Caplin's GetHead() now returns the justified/finalized checkpoints needed by forkchoiceUpdated, fixing standalone mode FCU calls" — exactly the path that's slow in our day-1 analysis.

The symptom (slow flush=2s commit=2s Forkchoice timings every few minutes) is consistent with extra work or contention introduced into the embedded-mode FCU path by changes that were intended only for standalone mode.

Next

Investigating the diff for the specific embedded-mode side effect. Once root cause is identified, will propose a targeted fix or revert of the embedded-mode portion.

cc @mh0lt (PR #20035 author for context on the embedded-mode changes)

[yperbasis]

Root cause: FCU fast-path removed in execution/engineapi/engine_server.go

Bisecting localized the regression to #20035 / 082697d2a0. Reading the diff, the load-bearing change is in getQuickPayloadStatusIfPossible:

- // We add the extra restriction blockHash != headHash for the FCU case of canonicalHash == blockHash
- // because otherwise (when FCU points to the head) we want go to stage headers
- // so that it calls writeForkChoiceHashes.
- if currentHeader != nil && blockHash != currentHeader.Hash() && header != nil && isCanonical {
+ // For NewPayload: if the block is already canonical and known, return VALID immediately.
+ // For FCU: we must always go through HandleForkChoice so the EL head actually moves,
+ // even if the requested head is a canonical ancestor (e.g. fork choice head regression).
+ if newPayload && currentHeader != nil && header != nil && isCanonical {
      return &engine_types.PayloadStatus{Status: engine_types.ValidStatus, LatestValidHash: &blockHash}, nil
  }

What this changes

Scenario	Pre-#20035	Post-#20035
NewPayload(canonical, known block)	fast-path VALID (with blockHash != head restriction)	fast-path VALID (always)
FCU(canonical ancestor of head)	fast-path VALID — silent no-op (PR-stated bug)	go through HandleForkChoice
FCU(canonical descendant of head) — forward tip-tracking	fast-path VALID	go through HandleForkChoice

The third row is the regression. In normal forward tip-tracking, after each NewPayload(N) the block is canonical and currentHeader is still N−1, so blockHash != currentHeader.Hash() && isCanonical was true → fast-path. Now every per-slot forward FCU goes through HandleForkChoice → chainRW.UpdateForkChoice → runForkchoiceFlushCommit (an MDBX RwTx with SD.Flush + commit + fsync).

In steady state that's ~200ms of overhead per FCU. Under contention from background work (block-retire → state-collate → state-merge), it spikes to flush=2s commit=2s (the original day-1 symptom). With one FCU per slot (12s), even moderate contention pushes the node out of sync.

The PR's stated goal of fixing the ancestor case is legitimate, but it removed the descendant fast-path along with it.

Proposed fix

Restore the fast-path only when the FCU's head is a descendant of the current head — i.e., the head needs to move forward, which is already implicitly handled because the block is canonical. Something like:

} else {
    // ... (downloader-wait branch unchanged) ...

    // Forward FCU to an already-canonical descendant: head must move via
    // FCU, but the block has been validated; we can return VALID quickly
    // and let the head update through the normal canonical-chain wiring.
    // Ancestor case (head regression) still flows through HandleForkChoice.
    if currentHeader != nil && header != nil && isCanonical &&
        header.Number.Uint64() > currentHeader.Number.Uint64() {
        return &engine_types.PayloadStatus{Status: engine_types.ValidStatus, LatestValidHash: &blockHash}, nil
    }
}

(needs verification: where does the head pointer actually advance under the OLD pre-#20035 code if FCU short-circuited — that path needs to still be active for the fast-path to be correct, not just fast)

Will validate this against a probe and post the PR. /cc @mh0lt

[yperbasis]

Correction: engine_server.go hypothesis was wrong

My earlier comment pointed at the engine_server.go FCU fast-path change as the mechanism. That's incorrect — in embedded mode (which is what main uses), Caplin's FCU does NOT go through engine_server.go:

cl/phase1/stages/forkchoice.go
  → cfg.forkChoice.Engine().ForkChoiceUpdate(...)
    → ExecutionClientDirect.ForkChoiceUpdate (cl/phase1/execution_client/execution_client_direct.go:124)
      → cc.chainRW.UpdateForkChoice(ctx, head, safe, finalized)
        → ExecModule.UpdateForkChoice
          → runForkchoiceFlushCommit  ← the slow flush+commit

engine_server.go is only on the standalone path (external CL via HTTP/JWT). The getQuickPayloadStatusIfPossible change is essentially dead code for our regression.

So the bisection result still stands — 082697d2a0 (#20035) IS the introducer — but the specific mechanism is still unknown to me. Re-examining the diff for embedded-mode side effects, the candidates are:

• cl/phase1/forkchoice/on_block.go — adds 2x sync.Map.Store per block import (per-block unrealized justifications/finalizations).
• cl/phase1/forkchoice/get_head.go — getFilterBlockTree now does a fallback lookup (unrealized map first, then fork graph) per filtered block.
• cl/phase1/forkchoice/utils.go — onNewFinalized now iterates the new sync.Maps on every finalization.
• cl/phase1/forkchoice/forkchoice.go — adds two new sync.Map fields (unrealizedJustifications, unrealizedFinalizations).
• Various changes to cl/cltypes/eth1_block.go (JSON marshalling refactor).

None of these obviously cost seconds, but sync.Map is known to be slower than a plain map under certain access patterns, and the maps are touched on every block import. With ~5 attestations × 12s slots, plus head-block import per slot, lock contention or GC pressure could compound.

Empirical next step

Going to revert 082697d2a0 on a branch from main (modulo conflicts) and dispatch a probe — if mainnet sync recovers, that confirms the regression is somewhere in #20035 (already strongly indicated by bisection) and gives us a baseline to iteratively narrow with file-level reverts. Will report findings.