Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
AskAlexSharov opened this issue Jul 23, 2024 · 0 comments
Open

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

AskAlexSharov opened this issue Jul 23, 2024 · 0 comments
Labels
erigon3 imp2 Medium importance

Comments

@AskAlexSharov
Copy link
Collaborator

AskAlexSharov commented Jul 23, 2024 •
edited
Loading

I did hack for performance on chain-tip: #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
@AskAlexSharov AskAlexSharov added this to the 3.0.0-alpha1 milestone Jul 23, 2024
@VBulikov VBulikov modified the milestones: 3.0.0-alpha1, 3.0.0-alpha2 Jul 24, 2024
@yperbasis yperbasis added the imp1 High importance label Jul 24, 2024
@AskAlexSharov AskAlexSharov added imp2 Medium importance complexity:low and removed imp1 High importance labels Jul 25, 2024
@VBulikov VBulikov modified the milestones: 3.0.0-alpha4, 3.0.0-alpha5 Sep 27, 2024
@AskAlexSharov AskAlexSharov removed this from the 3.0.0-beta2 milestone Jan 23, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
erigon3 imp2 Medium importance
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@VBulikov @yperbasis @AskAlexSharov