from-genesis replay slows down quadratically: 60% of CPU walking an unbounded candidateVotesWraper chain

[envestcc]

Summary

Replaying mainnet history from genesis, per-block cost grows linearly with the number of blocks processed, making a from-genesis sync effectively impossible. At height ~355k the node is down to 3.2 blocks/s from 185 blocks/s at the start, and the trend is still linear. Extrapolating the measured slope to height 8,000,000 gives ~325 days.

CPU profiling puts 60% of the time in stakingindex.(*candidateVotesWraper).IsDirty, walking a linked chain of vote-view wrappers that accumulates as the replay proceeds. A further ~22% goes to GC over the objects that chain retains.

This is not a regression: systemcontractindex/stakingindex/{candidate_votes,voteview}.go are byte-identical between master, rc_2.5.0 and v2.4.4. Filing it separately from the release.

Impact

• A node syncing mainnet from genesis does not finish in any practical time.
• Segmented historical replay/verification (the fullsync test) cannot cover the 0–8M range at all.

Evidence

Measured on iotex-core:rc_2.5.0, mainnet, replaying from genesis with no pre-existing trie.db. Blocks are served from local chain-*.db files (no P2P). Single container, 1 core saturated, host otherwise idle (iowait 0%).

Throughput decays linearly with blocks processed

Wall time per 5000-block milestone, from the node's own indexer is catching up. logs:

height	seconds per 5000 blocks	blocks/s
10,000	27	185.2
50,000	241	20.7
90,000	389	12.9
130,000	601	8.3
170,000	808	6.2
210,000	956	5.2
250,000	1170	4.3
290,000	1365	3.7
355,000	1577	3.2

Time per block is ~linear in blocks processed, so total cost is O(N²).

CPU profile (30s, at height ~372k)

      flat  flat%   cum   cum%
    19.50s 60.26% 19.75s 61.03%  stakingindex.(*candidateVotesWraper).IsDirty
     0.51s  1.58%  2.80s  8.65%  staking.(*viewData).Fork
         -      -  7.09s 21.91%  runtime.gcDrain
         -      -  5.37s 16.59%  runtime.scanSpan

IsDirty is reached from viewData.IsDirty → contractStakeView.IsDirty → voteView.IsDirty, and is essentially all self time — it is walking the chain, not doing work per candidate.

Heap profile (same moment, height ~372k)

allocation site	live objects
stakingindex.newCandidateVotes	436,913
stakingindex.newCandidateVotesWrapper	152,917
stakingindex.newBucketStore	141,997
staking.(*viewData).Fork	81,923
iotex-election/types.NewVote	313,657

~153k live wrappers at ~372k blocks processed. RSS ~3.7 GB and growing; a comparable worker replaying a mid-range segment holds 315–740 MB.

Hot path

IsDirty recurses into its base, so its cost is the chain length:

// systemcontractindex/stakingindex/candidate_votes.go
func (cv *candidateVotesWraper) IsDirty() bool {
	return len(cv.change.cands) > 0 || cv.base.IsDirty()
}

Fork() and Wrap() each push a new link onto that chain:

// systemcontractindex/stakingindex/voteview.go
func (s *voteView) Fork() staking.ContractStakeView {
	cur := newCandidateVotesWrapperCommitInClone(s.cur)   // wraps the current head
	...
}

The chain is only collapsed in Commit(), which folds change into base. So the question is which replay paths fork without ever committing.

Control experiment

To find what triggers the accumulation I ran a second worker under the same binary, host and configuration, differing only in where it starts: 8m -> 9m, restored from the 8m checkpoint. Both ranges are below OkhotskBlockHeight.

	0m -> 8m (from genesis)	8m -> 9m (from 8m checkpoint)
blocks processed at sample	372,000	145,000
live candidateVotesWrapper	152,917	not in top 8 (< 11k)
live candidateVotes	436,913	not in top 8
IsDirty share of CPU	60.3%	3.5%
RSS	3.7 GiB	165 MiB
throughput	3.2 blk/s, still decaying	160-290 blk/s, flat over 145k blocks

The control's heap is dominated by roaring bitmaps, prometheus label pairs and json decoding — i.e. startup-time allocations. The staking wrapper chain simply does not grow there. 8m -> 12m under the same setup previously completed all 4M blocks at a flat 208-357 blk/s.

So the trigger is not "replaying below the Okhotsk gate" — both cases are below it, only one accumulates.

Two differences remain between the two runs, and I could not separate them with the checkpoints available (there is no checkpoint below 8m to start a pre-Fairbank run from):

1. Era. 0-372k is before FairbankBlockHeight (5,165,641), where delegates come from the gravity-chain election rather than native staking. Consistent with the affected heap also holding 313,657 live iotex-election/types.NewVote objects and 40 MB under ResultCalculator.AddBuckets, neither of which appears in the control.
2. Starting state. From genesis there is no pre-existing trie.db, so db.CreateKVStore with DBAuto creates a pebble store (path does not exist -> directory), while every checkpoint-restored run gets a bolt store (path is a file).

Worth noting the wrapper count is ~0.41 per block rather than 1:1, so whatever pushes onto the chain is per-something-else (actions? snapshots?) rather than strictly per block. viewData.Snapshot() calls contractsStake.Wrap(), and the snapshot list is only cleared in Commit() — which is the same Commit() that collapses the chain.

Reproduction

1. Take the mainnet genesis and chain.db + chain-00000001..07.db (blocks 0–8M) plus poll.db. Do not supply a trie.db.
2. Run iotex-server with system.active: false, no gateway plugin, and empty bootstrapNodes (all blocks come from the local files).
3. Watch indexer is catching up. milestone spacing — the interval grows steadily from the first milestone onward.

Side note

Profiling this required a code change: StartServer brings the admin mux (which hosts pprof) up after svr.Start(), and svr.Start() runs the entire startup indexer catch-up inline. On a node replaying a large height range — hours to days — the whole catch-up is therefore unobservable: no pprof, no log-level control. Moving the admin mux ahead of svr.Start() (still loopback-only) is what made this profile possible; happy to open that as a separate PR if useful.

Profiles available on request.

[envestcc]

Root-caused and fixed — two separate accumulations, both measured

There turned out to be two independent per-block accumulations. Fixing the first one (the IsDirty chain this issue opened on) removed 60% of CPU but left the replay quadratic; the second one was hiding behind it.

Fix 1 — vote-view layering before the staking contract exists

Branch fix-staking-voteview-preactivation, commit 556b442c2 (+38 lines, no type restructuring).

voteView.Wrap() / Fork() return a shallow copy instead of pushing a new candidateVotesWraper when s.height+1 < s.indexer.StartHeight(). Below the contract's deploy height (SystemStakingContractHeight = 24,486,464) the only mutator of cur is voteViewEventHandler, reached solely from eventProcessor.ProcessReceipts, which drops every log whose address is not the contract's — so no such layer can ever hold a change, and there is nothing to isolate. The +1 means the block before the contract can emit anything is already layering normally.

Digest-safe: the vote view's only state write is voteView.Commit → cvm.Store, which short-circuits on !isDirty; reads are unaffected because every skipped layer had an empty change, so base + change is unchanged.

Fix 2 — the snapshot undo log copied on every fork

Branch fix-viewdata-snapshots, commit 18d618320 (−10/+7 lines).

viewData.Fork() deep-copied the entire snapshots slice, allocating a Snapshot struct and a new(big.Int).Set(...) per retained entry, on every fork. v.snapshots grows one entry per action-snapshot and is cleared only in viewData.Commit, which below Okhotsk runs only when the staking view is dirty — almost never on early mainnet. The fix leaves fork.snapshots nil.

Digest safety rests on two independent legs:

1. snapshots cannot reach the write queue. The field appears only in viewdata.go; Snapshot() and Revert() take neither a StateManager nor a context and cannot write state. Commit reads candCenter/bucketPool/contractsStake and clears snapshots without reading it. The only channel is what Revert restores.
2. No snapshot index survives a fork, so no Revert can behave differently. views.Fork() returns NewViews() — snapshotID: 0, empty snapshot map — and it is the long-lived holder. The two call sites that hold an index directly (staking.Protocol.Handle, rewarding.slashDelegates) snapshot and revert within a single call frame, with no fork possible in between (forking happens only at working-set construction). Post-fork indices shift by a uniform constant, and Revert truncates with v.snapshots[:snapshot], so the retained set is identical.

Incidentally the old copy was latently unsafe: fork.snapshots[i].contractsStake was a bare pointer into the parent's unforked wrapper chain, so a revert to a pre-fork index would have installed parent-owned mutable state into the child — and it pinned the parent's whole chain alive.

Measured

Same segment (mainnet from genesis), same host, same data, only the binary differs.

build	throughput	trend	RSS	extrapolated 0→8M
rc_2.5.0	185 → 3.2 blk/s by height 355k	linear decay	3.7 GiB	~325 days
+ fix 1	250 → 71 blk/s over 85k blocks	still decaying	894 MiB	~60 days
+ fix 2	500–1000 blk/s, still 746 blk/s at height 2.67M	flat	stable	~2.7 hours

The flat row is measured over 1.6M+ blocks with no decay, and it is measured with SetBlockProfileRate(1) active (the profiling build), so the production figure should be better rather than worse.

CPU dropped from 296% to 92% — the GC storm is gone.

Profile shift confirms the sequencing

After fix 1 (profile at height ~750k), candidateVotesWraper.IsDirty is absent from the top 60 (was 60.3%), and the new top consumer is exactly what fix 2 addresses:

      flat  flat%   cum   cum%
    12.84s 19.00%  21.64s 32.02%  runtime.tryDeferToSpanScan
    11.81s 17.47%  31.40s 46.46%  runtime.scanObjectsSmall
     3.62s  5.36%  17.28s 25.57%  action/protocol/staking.(*viewData).Fork
     2.12s  3.14%   2.55s  3.77%  math/big.(*Int).Set

viewData.Fork breakdown: runtime.newobject 55%, math/big.(*Int).Set 14.8%, runtime.makeslice 5.2% — i.e. the snapshot copy loop, with the rest of the profile being GC driven by it.

Correctness

go test ./action/protocol/... ./state/factory/... ./systemcontractindex/... ./e2etest/... — 1549 passed, 0 failed, 38 packages. (e2etest builds and validates real blocks, which exercises VerifyDeltaStateDigest.) Two pre-existing failures were confirmed pre-existing by stashing: an e2etest.TestLocalCommit p2p timing flake, and blockdao.TestBlockIndexerChecker_CheckIndexer asserting "failed to get producer address" where the code returns "failed to get pubkey".

Beyond unit tests, both fixes are currently under a replay soak with digest verification:

• from genesis (0 → 8M), 2.67M blocks in, 0 digest mismatches;
• a post-activation range (32M → 34M, i.e. past Okhotsk and past the V1/V2 contract heights, in the heaviest million-block file on the chain) replaying with both fixes and digest-verified.

Note the two fixes carry different risk. Fix 1 is height-gated and cannot affect any activated height. Fix 2 changes behaviour at every height, which is why it is being soaked against activated ranges rather than argued from tests alone. I would not merge fix 2 on the strength of the unit tests by themselves.

Profiles (cpu.pprof / heap.pprof, before and after each fix) available if wanted.

[envestcc]

From-genesis replay now finishes — 0 → 8M in 1 h 54 m

Confirming this issue's premise is resolved, from an independent run done as part of v2.5.0-rc2 whole-chain fullsync verification.

The issue opened on an extrapolation of ~325 days to reach height 8,000,000. With both fixes in (#4966 + #4967), the same range takes 1 hour 54 minutes, exit code 0, final height exactly 8,000,000, zero error-level delta state digest mismatches, zero fatals.

The second accumulation is the one that dominates at low heights

Your comment above identified two accumulations. My measurements say the split between them is very lopsided below the contract deploy height, and it is worth recording which is which:

CPU profile at 255k blocks, on a binary carrying #4966 (and #4967's protocol.go commit) but not #4967's viewdata.go commit:

      flat  flat%   cum   cum%
     6.63s 15.03% 22.65s 51.36%  staking.(*viewData).Fork

Fork's callees:

  runtime.newobject        11.89s  52.49%
  runtime.makeslice         2.03s   8.96%   <- make([]Snapshot, len(v.snapshots))
  math/big.(*Int).Set       1.97s   8.70%
  contractStakeView.Fork    0.01s   0.04%   <- #4966's path, nil below 24,486,464

So with #4966 applied alone, the replay is still quadratic and #4967's snapshot undo log is essentially the entire remaining cost. contractStakeView.Fork costing 0.01s is expected rather than surprising — the three contract-staking views are all nil until 24,486,464, so #4966 has nothing to skip down here. #4966 alone does not make a from-genesis sync feasible; #4967 is the one that does (at these heights).

Measured rate curves, same box, same checkpoint, 100k windows:

window	#4966 only	#4966 + #4967
0 – 100k	120.7 blk/s	1578.6 blk/s
200k – 300k	24.0	1811.4
400k – 500k	16.4	1729.8
700k – 800k	9.3	1338.8

Left column decays monotonically and fits a power law (exponent ≈ 0.76) that extrapolates to ~35 days for 800k → 8M. Right column is flat.

Caveat: the measured binary also carried an unrelated local change of mine (copy-on-write for candBase), so the attribution to #4967 rests on the profile — CandidateCenter.Clone accounts for zero time at these heights — rather than on an isolating A/B run.

Scope note

stateDB.Validate → getFromWorkingSets → newWorkingSet → views.Fork is the normal per-block path, not replay-specific, and len(v.snapshots) grows with chain age. So this was never only a "replay tooling is slow" problem: it is a per-block cost that grows over time, currently masked by the 5 s block interval. Replay just removes the masking.

Suggest this stays open until #4967 merges, since #4966 alone does not close it.