iotexproject / iotexproject/iotex-core

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

Open
#4,964 2 comments 0 reactions 0 assignees View on GitHub
Dominant language
Go
Stars
1.6k
Forks
382
Avg merge
4d 22h
Merged PRs (30d)
17

Description

## 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:

```go
// 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:

```go
// 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.

Contributor guide

Open the contributing guide

Research direction

Reproduce the replay slowdown with the supplied genesis and checkpoint scenarios, then inspect systemcontractindex/stakingindex/candidate_votes.go and voteview.go, focusing on candidateVotesWraper.IsDirty, voteView.Fork, Wrap, and Commit. Trace which replay paths grow the wrapper chain without committing and compare profiles and heap growth. Done means the unbounded accumulation is removed and replay throughput and memory remain stable across the affected range.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
backend, blockchain, performance
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Active
Clarity
Needs clarification
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.