erigontech / erigontech/erigon

StageFinish is ahead of StageExec. Replace performance hack by better solution.

Open
#11,293 0 comments 0 reactions 0 assignees View on GitHub
performance
Dominant language
Go
Stars
3.6k
Forks
1.5k
Avg merge
1d 16h
Merged PRs (30d)
455

Description

I did hack for performance on chain-tip: https://github.com/erigontech/erigon/pull/11287
Need replace it by something better - to make all stages have same progress - like dynamically adjust `--block.sync.limit` on chain tip - to something small - like 32.

```
[INFO] [07-23|13:24:49.851] [2/9 Headers] Waiting for headers... from=59712225
[INFO] [07-23|13:24:49.854] [2/9 Headers] Processed highest=59712275 age=0 headers=50 in=0.003 blk/sec=17042
[INFO] [07-23|13:24:49.854] [3/9 BorHeimdall] Processing spans... from=9331 to=9331
[INFO] [07-23|13:24:49.936] [3/9 BorHeimdall] Processing sync events... from=59712226 to=59712275
[INFO] [07-23|13:24:51.236] [3/9 BorHeimdall] Sync events progress=59712275 lastSpanID=9331 lastSpanID=9331 lastCheckpointId=0 lastMilestoneId=0 lastStateSyncEventID=2937316 total records=0 sync event time=1.230512054s fetch time=49.988317ms snap time=136.666038ms waypoint time=0s process time=1.382049534s
[INFO] [07-23|13:24:51.248] [5/9 Bodies] Processing bodies... from=59712225 to=59712275
[INFO] [07-23|13:24:51.446] [5/9 Bodies] Processed highest=59712275 blocks=50 in=0.198 blk/sec=252
[INFO] [07-23|13:24:51.446] [6/9 Senders] Started from=59712225 to=59712275
[INFO] [07-23|13:24:51.499] [7/9 Execution] starting from=59712083 to=59712275 fromTxNum=4384393432 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=false
[INFO] [07-23|13:25:15.505] [7/9 Execution] Transaction replay blk=59712092 tx/s=33.6 buffer=43.4MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=22.3GB sys=49.2GB
[INFO] [07-23|13:25:22.470] [bor.heimdall] Got new checkpoint start=59709350 end=59710629 rootHash=0x4f7a867ab44bcfb28ebef1be27e5c952095cf7994898428afd58eca052c6de03
[INFO] [07-23|13:25:34.086] [7/9 Execution] Transaction replay blk=59712097 tx/s=40.6 buffer=66.3MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=26.7GB sys=49.2GB
[INFO] [07-23|13:25:35.851] [snapshots:blocks:retire] Stat blocks=59711k indices=59711k alloc=27.8GB sys=49.2GB
[INFO] [07-23|13:25:36.395] [snapshots:bor:retire] Stat blocks=59711k indices=59711k alloc=28.0GB sys=49.2GB
[INFO] [07-23|13:25:52.753] [7/9 Execution] Transaction replay blk=59712100 tx/s=18.7 buffer=86.2MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=28.6GB sys=49.2GB
[INFO] [07-23|13:26:14.374] [7/9 Execution] Transaction replay blk=59712104 tx/s=25.2 buffer=108.2MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=29.0GB sys=49.2GB
[INFO] [07-23|13:26:36.768] [7/9 Execution] Transaction replay blk=59712111 tx/s=24.2 buffer=133.4MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=29.5GB sys=49.2GB
[INFO] [07-23|13:26:55.568] [7/9 Execution] Transaction replay blk=59712116 tx/s=16.4 buffer=154.3MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=16.9GB sys=49.2GB
[INFO] [07-23|13:27:02.032] [p2p] GoodPeers eth68=32 eth67=6
[INFO] [07-23|13:27:02.041] [txpool] stat pending=10000 baseFee=116 queued=14526 alloc=17.0GB sys=49.2GB
[INFO] [07-23|13:27:02.478] [bor.heimdall] Got new checkpoint start=59709350 end=59710629 rootHash=0x4f7a867ab44bcfb28ebef1be27e5c952095cf7994898428afd58eca052c6de03
[INFO] [07-23|13:27:05.504] [mem] memory stats Rss=82.6GB Size=0B Pss=82.6GB SharedClean=2.5MB SharedDirty=0B PrivateClean=48.0GB PrivateDirty=34.6GB Referenced=55.5GB Anonymous=34.6GB Swap=0B alloc=17.1GB sys=49.2GB
[INFO] [07-23|13:27:12.479] [7/9 Execution] Transaction replay blk=59712121 tx/s=23.1 buffer=173.1MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=17.2GB sys=49.2GB
[INFO] [07-23|13:27:32.284] [7/9 Execution] Transaction replay blk=59712127 tx/s=21.4 buffer=192.9MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=17.7GB sys=49.2GB
[INFO] [07-23|13:27:54.323] [7/9 Execution] Transaction replay blk=59712133 tx/s=22.9 buffer=216.9MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=18.1GB sys=49.2GB
[INFO] [07-23|13:28:11.684] [7/9 Execution] Transaction replay blk=59712138 tx/s=19.1 buffer=236.3MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=18.5GB sys=49.2GB
[INFO] [07-23|13:28:34.779] [7/9 Execution] Transaction replay blk=59712146 tx/s=23.9 buffer=266.9MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=19.2GB sys=49.2GB
[INFO] [07-23|13:28:44.414] [bor.heimdall] Got new checkpoint start=59709350 end=59710629 rootHash=0x4f7a867ab44bcfb28ebef1be27e5c952095cf7994898428afd58eca052c6de03
[INFO] [07-23|13:28:53.087] [7/9 Execution] Transaction replay blk=59712150 tx/s=29.1 buffer=286.0MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=17.1GB sys=49.2GB
[INFO] [07-23|13:29:12.611] [7/9 Execution] Transaction replay blk=59712158 tx/s=37.1 buffer=310.3MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=17.7GB sys=49.2GB
[INFO] [07-23|13:29:33.693] [7/9 Execution] Transaction replay blk=59712164 tx/s=23.2 buffer=334.6MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=18.2GB sys=49.2GB
[INFO] [07-23|13:29:53.899] [7/9 Execution] Transaction replay blk=59712170 tx/s=31.7 buffer=356.3MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=18.7GB sys=49.2GB
[INFO] [07-23|13:30:02.030] [p2p] GoodPeers eth68=32 eth67=6
[INFO] [07-23|13:30:02.042] [txpool] stat pending=10000 baseFee=115 queued=17089 alloc=18.8GB sys=49.2GB
[INFO] [07-23|13:30:05.600] [mem] memory stats Rss=80.4GB Size=0B Pss=80.4GB SharedClean=2.8MB SharedDirty=0B PrivateClean=56.8GB PrivateDirty=23.6GB Referenced=50.3GB Anonymous=23.6GB Swap=0B alloc=18.9GB sys=49.2GB
[INFO] [07-23|13:30:14.367] [7/9 Execution] Transaction replay blk=59712176 tx/s=22.6 buffer=379.7MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=19.1GB sys=49.2GB
[INFO] [07-23|13:30:22.487] [bor.heimdall] Got new checkpoint start=59709350 end=59710629 rootHash=0x4f7a867ab44bcfb28ebef1be27e5c952095cf7994898428afd58eca052c6de03
[INFO] [07-23|13:30:34.175] [7/9 Execution] Transaction replay blk=59712182 tx/s=25.9 buffer=399.0MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=19.6GB sys=49.2GB
[INFO] [07-23|13:30:52.500] [7/9 Execution] Transaction replay blk=59712189 tx/s=32.4 buffer=417.3MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=17.3GB sys=49.2GB
[INFO] [07-23|13:31:13.815] [7/9 Execution] Transaction replay blk=59712202 tx/s=53.6 buffer=445.8MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=18.1GB sys=49.2GB
[INFO] [07-23|13:31:35.522] [7/9 Execution] Transaction replay blk=59712210 tx/s=44.9 buffer=468.7MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=18.7GB sys=49.2GB
[INFO] [07-23|13:31:52.269] [7/9 Execution] Transaction replay blk=59712221 tx/s=54.8 buffer=488.7MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=19.3GB sys=49.2GB

[INFO] [07-23|13:32:02.549] [bor.heimdall] Got new checkpoint start=59710630 end=59711141 rootHash=0xcbb5c16d527b0897a540a58dca778857fb1463535fe333c12e671ca6a283fe4f

^[

[INFO] [07-23|13:32:12.360] [7/9 Execution] Transaction replay blk=59712227 tx/s=28.7 buffer=513.5MB/512.0MB stepsInDB=0.01 step=2806.0 alloc=19.9GB sys=49.2GB
[INFO] [07-23|13:32:20.979] [7/9 Execution] DONE in=7m29.480049676s block=59712082
[INFO] [07-23|13:32:21.169] RPC Daemon notified of new headers from=59712225 to=59712227 amount=2 hash=0xa806943f1911a74d83a666a67d14e21d4737acaa987cc386752ae7566d53d7b1 header sending=38.092µs log sending=250ns
[INFO] [07-23|13:32:21.172] Timings (slower than 50ms) BorHeimdall=1.382s Bodies=198ms Senders=52ms Execution=7m29.48s TxLookup=190ms alloc=21.2GB sys=49.2GB
[INFO] [07-23|13:32:21.309] [2/9 Headers] Waiting for headers... from=59712275
[INFO] [07-23|13:32:21.324] [2/9 Headers] Processed highest=59712488 age=0 headers=213 in=0.015 blk/sec=13901
[INFO] [07-23|13:32:21.324] [3/9 BorHeimdall] Processing sync events... from=59712276 to=59712488
[INFO] [07-23|13:32:27.470] [3/9 BorHeimdall] Sync events progress=59712488 lastSpanID=9331 lastSpanID=9331 lastCheckpointId=0 lastMilestoneId=0 lastStateSyncEventID=2937317 total records=1 sync event time=6.000938552s fetch time=5.91014765s snap time=277.858631ms waypoint time=0s process time=6.146104419s
[INFO] [07-23|13:32:27.585] [5/9 Bodies] Processing bodies... from=59712275 to=59712488
[WARN] [07-23|13:32:27.701] [bor] unable to handle whitelist milestone err="[bor] block not found: 59712451"
[INFO] [07-23|13:32:30.058] [5/9 Bodies] Processed highest=59712488 blocks=213 in=2.473 blk/sec=86
[INFO] [07-23|13:32:30.058] [6/9 Senders] Started from=59712275 to=59712488
[INFO] [07-23|13:32:30.190] [7/9 Execution] starting from=59712228 to=59712488 fromTxNum=4384406506 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=false
[INFO] [07-23|13:32:52.206] [7/9 Execution] Transaction replay blk=59712239 tx/s=48.1 buffer=53.2MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=16.7GB sys=49.2GB
[INFO] [07-23|13:33:02.031] [p2p] GoodPeers eth68=31 eth67=6
[INFO] [07-23|13:33:02.041] [txpool] stat pending=10000 baseFee=116 queued=19533 alloc=16.9GB sys=49.2GB
[INFO] [07-23|13:33:05.715] [mem] memory stats Rss=87.6GB Size=0B Pss=87.6GB SharedClean=2.6MB SharedDirty=0B PrivateClean=63.3GB PrivateDirty=24.3GB Referenced=51.6GB Anonymous=24.3GB Swap=0B alloc=17.1GB sys=49.2GB
[INFO] [07-23|13:33:10.813] [7/9 Execution] Transaction replay blk=59712246 tx/s=34.3 buffer=83.7MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=17.2GB sys=49.2GB
[INFO] [07-23|13:33:31.750] [7/9 Execution] Transaction replay blk=59712255 tx/s=34.7 buffer=117.3MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=17.8GB sys=49.2GB
[INFO] [07-23|13:33:42.481] [bor.heimdall] Got new checkpoint start=59710630 end=59711141 rootHash=0xcbb5c16d527b0897a540a58dca778857fb1463535fe333c12e671ca6a283fe4f
^[^[[INFO] [07-23|13:33:50.272] [7/9 Execution] Transaction replay blk=59712260 tx/s=78.0 buffer=144.9MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=18.3GB sys=49.2GB
[INFO] [07-23|13:34:11.076] [7/9 Execution] Transaction replay blk=59712271 tx/s=90.7 buffer=181.9MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=19.0GB sys=49.2GB
[INFO] [07-23|13:34:30.710] [7/9 Execution] Transaction replay blk=59712279 tx/s=31.3 buffer=204.5MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=19.6GB sys=49.2GB
[INFO] [07-23|13:34:52.827] [7/9 Execution] Transaction replay blk=59712287 tx/s=31.3 buffer=229.3MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=17.0GB sys=49.2GB
[INFO] [07-23|13:35:10.508] [7/9 Execution] Transaction replay blk=59712298 tx/s=70.9 buffer=254.1MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=17.7GB sys=49.2GB
[INFO] [07-23|13:35:22.478] [bor.heimdall] Got new checkpoint start=59710630 end=59711141 rootHash=0xcbb5c16d527b0897a540a58dca778857fb1463535fe333c12e671ca6a283fe4f
[INFO] [07-23|13:35:33.846] [7/9 Execution] Transaction replay blk=59712308 tx/s=38.5 buffer=281.3MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=18.4GB sys=49.2GB
[INFO] [07-23|13:35:51.300] [7/9 Execution] Transaction replay blk=59712314 tx/s=29.6 buffer=299.7MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=18.9GB sys=49.2GB
[INFO] [07-23|13:36:02.031] [p2p] GoodPeers eth68=32 eth67=6
[INFO] [07-23|13:36:02.042] [txpool] stat pending=10000 baseFee=120 queued=23574 alloc=19.1GB sys=49.2GB
[INFO] [07-23|13:36:05.525] [mem] memory stats Rss=79.0GB Size=0B Pss=79.0GB SharedClean=2.8MB SharedDirty=0B PrivateClean=54.7GB PrivateDirty=24.3GB Referenced=46.6GB Anonymous=24.3GB Swap=0B alloc=19.2GB sys=49.2GB
[INFO] [07-23|13:36:11.524] [7/9 Execution] Transaction replay blk=59712319 tx/s=18.5 buffer=321.0MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=19.4GB sys=49.2GB
[INFO] [07-23|13:36:30.769] [7/9 Execution] Transaction replay blk=59712324 tx/s=43.0 buffer=341.0MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=19.9GB sys=49.2GB
[INFO] [07-23|13:36:51.368] [7/9 Execution] Transaction replay blk=59712331 tx/s=29.7 buffer=362.1MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=17.2GB sys=49.2GB
[INFO] [07-23|13:37:02.480] [bor.heimdall] Got new checkpoint start=59710630 end=59711141 rootHash=0xcbb5c16d527b0897a540a58dca778857fb1463535fe333c12e671ca6a283fe4f
[INFO] [07-23|13:37:11.437] [7/9 Execution] Transaction replay blk=59712339 tx/s=32.0 buffer=386.0MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=17.8GB sys=49.2GB
[INFO] [07-23|13:37:36.353] [7/9 Execution] Transaction replay blk=59712352 tx/s=44.1 buffer=412.9MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=18.6GB sys=49.2GB
[INFO] [07-23|13:37:50.848] [7/9 Execution] Transaction replay blk=59712358 tx/s=36.6 buffer=429.9MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=18.9GB sys=49.2GB
[INFO] [07-23|13:38:13.840] [7/9 Execution] Transaction replay blk=59712364 tx/s=23.7 buffer=454.4MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=19.5GB sys=49.2GB
[INFO] [07-23|13:38:31.027] [7/9 Execution] Transaction replay blk=59712371 tx/s=51.1 buffer=471.7MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=20.0GB sys=49.2GB
[INFO] [07-23|13:38:42.483] [bor.heimdall] Got new checkpoint start=59710630 end=59711141 rootHash=0xcbb5c16d527b0897a540a58dca778857fb1463535fe333c12e671ca6a283fe4f
[INFO] [07-23|13:38:52.539] [7/9 Execution] Transaction replay blk=59712378 tx/s=40.0 buffer=494.1MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=17.4GB sys=49.2GB
[INFO] [07-23|13:39:02.030] [p2p] GoodPeers eth68=32 eth67=6
[INFO] [07-23|13:39:02.041] [txpool] stat pending=10000 baseFee=143 queued=26536 alloc=17.6GB sys=49.2GB
[INFO] [07-23|13:39:05.650] [mem] memory stats Rss=82.7GB Size=0B Pss=82.6GB SharedClean=2.7MB SharedDirty=0B PrivateClean=58.2GB PrivateDirty=24.5GB Referenced=50.0GB Anonymous=24.5GB Swap=0B alloc=17.8GB sys=49.2GB
[INFO] [07-23|13:39:10.541] [7/9 Execution] Transaction replay blk=59712387 tx/s=64.6 buffer=513.4MB/512.0MB stepsInDB=0.02 step=2806.0 alloc=18.0GB sys=49.2GB
[INFO] [07-23|13:39:17.576] [7/9 Execution] DONE in=6m47.402641862s block=59712227
[INFO] [07-23|13:39:17.773] RPC Daemon notified of new headers from=59712275 to=59712387 amount=112 hash=0x3cfdd9a59daaa9e7a85d5430c509e9d8c0adfbccc97bdb6d8f1e2d78f5ce2bf4 header sending=150.758µs log sending=260ns
[INFO] [07-23|13:39:17.775] Timings (slower than 50ms) BorHeimdall=6.146s BlockHashes=113ms Bodies=2.473s Senders=115ms Execution=6m47.402s TxLookup=195ms alloc=19.4GB sys=49.2GB
[INFO] [07-23|13:39:17.871] [2/9 Headers] Waiting for headers... from=59712488
[INFO] [07-23|13:39:17.885] [2/9 Headers] Processed highest=59712684 age=0 headers=196 in=0.014 blk/sec=14087
[INFO] [07-23|13:39:17.885] [3/9 BorHeimdall] Processing sync events... from=59712489 to=59712684
[INFO] [07-23|13:39:20.644] [3/9 BorHeimdall] Sync events progress=59712684 lastSpanID=9331 lastSpanID=9331 lastCheckpointId=0 lastMilestoneId=0 lastStateSyncEventID=2937319 total records=2 sync event time=2.580146254s fetch time=308.827057ms snap time=347.691727ms waypoint time=0s process time=2.758956568s
[INFO] [07-23|13:39:20.832] [5/9 Bodies] Processing bodies... from=59712488 to=59712684
[INFO] [07-23|13:39:22.991] [5/9 Bodies] Processed highest=59712684 blocks=196 in=2.158 blk/sec=90
[INFO] [07-23|13:39:22.991] [6/9 Senders] Started from=59712488 to=59712684
[INFO] [07-23|13:39:23.136] [7/9 Execution] starting from=59712388 to=59712684 fromTxNum=4384423769 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=false
[INFO] [07-23|13:39:46.409] [7/9 Execution] Transaction replay blk=59712394 tx/s=53.8 buffer=49.2MB/512.0MB stepsInDB=0.03 step=2806.0 alloc=20.5GB sys=49.2GB
[INFO] [07-23|13:40:06.707] [7/9 Execution] Transaction replay blk=59712401 tx/s=36.8 buffer=82.4MB/512.0MB stepsInDB=0.03 step=2806.0 alloc=21.1GB sys=49.2GB
[INFO] [07-23|13:40:23.872] [bor.heimdall] Got new checkpoint start=59710630 end=59711141 rootHash=0xcbb5c16d527b0897a540a58dca778857fb1463535fe333c12e671ca6a283fe4f
[INFO] [07-23|13:40:26.955] [7/9 Execution] Transaction replay blk=59712408 tx/s=26.7 buffer=112.4MB/512.0MB stepsInDB=0.03 step=2806.0 alloc=21.6GB sys=49.2GB
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.