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

v2.61.0 slow to sync on sepolia #13457

Closed
keithchew opened this issue Jan 16, 2025 · 31 comments
Closed

v2.61.0 slow to sync on sepolia #13457

keithchew opened this issue Jan 16, 2025 · 31 comments
Assignees
@antonis19
Labels
performance
Milestone
2.61.1-fixes

Comments

@keithchew
Copy link

keithchew commented Jan 16, 2025 •
edited
Loading

Trying to upgrade from v2.60.10 to v2.61.0. It is trying to catch up with the latest block, but very very slow:

[INFO] [01-16|05:07:29.105] [p2p] GoodPeers                          eth67=2
[INFO] [01-16|05:07:29.212] [mem] memory stats                       Rss=4.2GB Size=0B Pss=4.2GB SharedClean=996.0KB SharedDirty=0B PrivateClean=2.1GB PrivateDirty=2.1GB Referenced=3.9GB Anonymous=2.1GB Swap=0B alloc=1.2GB sys=1.6GB
[INFO] [01-16|05:07:32.714] [txpool] stat                            pending=0 baseFee=0 queued=30000 alloc=1.3GB sys=1.6GB
[INFO] [01-16|05:07:38.604] [4/12 Execution] Executed blocks         number=7497169 blk/s=0.1 tx/s=16.6 Mgas/s=2.3 gasState=0.01 batch=360.1KB alloc=1.3GB sys=1.6GB
[INFO] [01-16|05:08:09.627] [4/12 Execution] Executed blocks         number=7497172 blk/s=0.1 tx/s=12.2 Mgas/s=1.8 gasState=0.02 batch=425.9KB alloc=1.4GB sys=1.6GB
[INFO] [01-16|05:08:34.071] [4/12 Execution] Executed blocks         number=7497174 blk/s=0.1 tx/s=9.0 Mgas/s=1.0 gasState=0.02 batch=457.2KB alloc=1004.0MB sys=1.6GB
[INFO] [01-16|05:09:07.728] [4/12 Execution] Executed blocks         number=7497178 blk/s=0.1 tx/s=15.7 Mgas/s=2.1 gasState=0.02 batch=547.7KB alloc=1.2GB sys=1.6GB
[INFO] [01-16|05:09:39.720] [4/12 Execution] Executed blocks         number=7497182 blk/s=0.1 tx/s=17.3 Mgas/s=2.3 gasState=0.03 batch=649.5KB alloc=1.3GB sys=1.6GB
[INFO] [01-16|05:10:14.534] [4/12 Execution] Executed blocks         number=7497185 blk/s=0.1 tx/s=10.5 Mgas/s=2.0 gasState=0.03 batch=727.7KB alloc=929.7MB sys=1.6GB
[INFO] [01-16|05:10:29.104] [p2p] GoodPeers                          eth67=2
[INFO] [01-16|05:10:29.208] [mem] memory stats                       Rss=4.2GB Size=0B Pss=4.2GB SharedClean=996.0KB SharedDirty=0B PrivateClean=2.1GB PrivateDirty=2.1GB Referenced=4.0GB Anonymous=2.1GB Swap=0B alloc=1007.3MB sys=1.6GB
[INFO] [01-16|05:10:32.587] [txpool] stat                            pending=0 baseFee=0 queued=30000 alloc=1020.0MB sys=1.6GB
[INFO] [01-16|05:10:35.920] [4/12 Execution] Executed blocks         number=7497188 blk/s=0.1 tx/s=16.7 Mgas/s=2.3 gasState=0.03 batch=795.6KB alloc=1.0GB sys=1.6GB
[INFO] [01-16|05:11:15.351] [4/12 Execution] Executed blocks         number=7497195 blk/s=0.2 tx/s=23.8 Mgas/s=3.0 gasState=0.04 batch=939.2KB alloc=1.2GB sys=1.6GB
[INFO] [01-16|05:11:41.644] [4/12 Execution] Executed blocks         number=7497197 blk/s=0.1 tx/s=10.9 Mgas/s=1.6 gasState=0.04 batch=990.2KB alloc=1.3GB sys=1.6GB
[INFO] [01-16|05:12:08.349] [4/12 Execution] Executed blocks         number=7497200 blk/s=0.1 tx/s=14.7 Mgas/s=2.0 gasState=0.05 batch=1.0MB alloc=1.4GB sys=1.6GB

Rolling back to v2.60.10, it catches up quickly. Is there a regression issue?
@keithchew
Copy link
Author

keithchew commented Jan 16, 2025 •
edited
Loading

8+ hours later, it seems to be stuck here:

[INFO] [01-16|15:39:47.339] [6/12 IntermediateHashes] Calculating Merkle root current key=4c1c73d8
[INFO] [01-16|15:40:17.667] [6/12 IntermediateHashes] Calculating Merkle root current key=4c678244
[INFO] [01-16|15:40:29.105] [p2p] GoodPeers                          eth68=1 eth67=2
[INFO] [01-16|15:40:29.251] [mem] memory stats                       Rss=4.3GB Size=0B Pss=4.3GB SharedClean=912.0KB SharedDirty=0B PrivateClean=2.0GB PrivateDirty=2.3GB Referenced=4.1GB Anonymous=2.3GB Swap=0B alloc=1.1GB sys=1.8GB
[INFO] [01-16|15:40:33.307] [txpool] stat                            pending=0 baseFee=0 queued=30000 alloc=1.1GB sys=1.8GB
[INFO] [01-16|15:40:47.660] [6/12 IntermediateHashes] Calculating Merkle root current key=4ca80123
[INFO] [01-16|15:41:18.340] [6/12 IntermediateHashes] Calculating Merkle root current key=4ce78978
[INFO] [01-16|15:41:47.479] [6/12 IntermediateHashes] Calculating Merkle root current key=4d28fb46
[INFO] [01-16|15:42:17.363] [6/12 IntermediateHashes] Calculating Merkle root current key=4d8472b8
[INFO] [01-16|15:42:48.449] [6/12 IntermediateHashes] Calculating Merkle root current key=4dd61fc0
[INFO] [01-16|15:43:23.991] [6/12 IntermediateHashes] Calculating Merkle root current key=4df87133
[INFO] [01-16|15:43:29.104] [p2p] GoodPeers                          eth68=1 eth67=2
[INFO] [01-16|15:43:29.287] [mem] memory stats                       Rss=4.3GB Size=0B Pss=4.3GB SharedClean=912.0KB SharedDirty=0B PrivateClean=2.0GB PrivateDirty=2.3GB Referenced=4.1GB Anonymous=2.3GB Swap=0B alloc=1.3GB sys=1.8GB
[INFO] [01-16|15:43:32.556] [txpool] stat                            pending=0 baseFee=0 queued=30000 alloc=1.4GB sys=1.8GB
[INFO] [01-16|15:43:47.892] [6/12 IntermediateHashes] Calculating Merkle root current key=4e3e7125
[INFO] [01-16|15:44:17.704] [6/12 IntermediateHashes] Calculating Merkle root current key=4e96f4e3
[INFO] [01-16|15:46:29.105] [p2p] GoodPeers                          eth68=1 eth67=2
[INFO] [01-16|15:46:29.253] [mem] memory stats                       Rss=4.3GB Size=0B Pss=4.3GB SharedClean=912.0KB SharedDirty=0B PrivateClean=2.0GB PrivateDirty=2.3GB Referenced=4.1GB Anonymous=2.3GB Swap=0B alloc=1.1GB sys=1.8GB
[INFO] [01-16|15:46:32.441] [txpool] stat                            pending=0 baseFee=0 queued=30000 alloc=1.1GB sys=1.8GB
[INFO] [01-16|15:49:29.105] [p2p] GoodPeers                          eth67=2 eth68=1
[INFO] [01-16|15:49:29.254] [mem] memory stats                       Rss=4.3GB Size=0B Pss=4.3GB SharedClean=912.0KB SharedDirty=0B PrivateClean=2.0GB PrivateDirty=2.3GB Referenced=4.1GB Anonymous=2.3GB Swap=0B alloc=1.4GB sys=1.8GB
[INFO] [01-16|15:49:32.442] [txpool] stat                            pending=0 baseFee=0 queued=30000 alloc=1.4GB sys=1.8GB
[INFO] [01-16|15:52:29.104] [p2p] GoodPeers                          eth68=1 eth67=2
[INFO] [01-16|15:52:29.251] [mem] memory stats                       Rss=4.3GB Size=0B Pss=4.3GB SharedClean=912.0KB SharedDirty=0B PrivateClean=2.0GB PrivateDirty=2.3GB Referenced=4.2GB Anonymous=2.3GB Swap=0B alloc=1.1GB sys=1.8GB
[INFO] [01-16|15:52:32.821] [txpool] stat                            pending=0 baseFee=0 queued=30000 alloc=1.1GB sys=1.8GB

Note that when it started, it only needed to catch up from block from 7496738 to 7497695 (957 blocks), ie a very small range:

{"log":"[INFO] [01-15|17:12:24.405] [3/12 Senders] Started                   from=7496738 to=7497695\n","stream":"stderr","time":"2025-01-15T17:12:24.405204644Z"}

@keithchew
Copy link
Author

Downgrading to v2.60.10, all the steps above completed in about 20mins (and the rest fairly quickly in 7mins):

[INFO] [01-16|16:21:16.577] [3/12 Senders] Started                   from=7496738 to=7497697
[INFO] [01-16|16:21:46.578] [3/12 Senders] Recovery                  block_number=7496794 ch=0/10000
[INFO] [01-16|16:22:16.577] [3/12 Senders] Recovery                  block_number=7496865 ch=0/10000
[INFO] [01-16|16:22:46.578] [3/12 Senders] Recovery                  block_number=7497097 ch=0/10000
[INFO] [01-16|16:23:16.578] [3/12 Senders] Recovery                  block_number=7497269 ch=0/10000
[INFO] [01-16|16:23:36.210] [3/12 Senders] DONE                      in=2m19.632375019s
[INFO] [01-16|16:23:36.210] [4/12 Execution] Blocks execution        from=7496738 to=7497697
[INFO] [01-16|16:24:02.654] [p2p] GoodPeers                          eth67=1
[INFO] [01-16|16:24:02.709] [mem] memory stats                       Rss=2.3GB Size=0B Pss=2.3GB SharedClean=960.0KB SharedDirty=0B PrivateClean=1.1GB PrivateDirty=1.3GB Referenced=2.3GB Anonymous=1.3GB Swap=0B alloc=1.1GB sys=1.2GB
[INFO] [01-16|16:24:05.895] [txpool] stat                            pending=0 baseFee=0 queued=1490 alloc=1.2GB sys=1.2GB
[INFO] [01-16|16:24:06.423] [4/12 Execution] Executed blocks         number=7496920 blk/s=6.0 tx/s=785.2 Mgas/s=105.2 gasState=0.19 batch=3.7MB alloc=1.2GB sys=1.3GB
[INFO] [01-16|16:24:38.255] Committed State                          gas reached=7304242147 gasTarget=17179869184 block=7497156 time=2.459166067s committedToDb=false
[INFO] [01-16|16:24:38.255] [4/12 Execution] Executed blocks         number=7497156 blk/s=7.4 tx/s=991.8 Mgas/s=130.1 gasState=0.00 batch=0B alloc=1.3GB sys=1.5GB
[INFO] [01-16|16:25:06.521] [4/12 Execution] Executed blocks         number=7497316 blk/s=5.7 tx/s=753.2 Mgas/s=103.8 gasState=0.17 batch=3.6MB alloc=1.4GB sys=1.5GB
[INFO] [01-16|16:25:33.908] Committed State                          gas reached=7635664416 gasTarget=17179869184 block=7497555 time=1.802006751s committedToDb=false
[INFO] [01-16|16:25:36.217] [4/12 Execution] Executed blocks         number=7497574 blk/s=8.7 tx/s=1163.3 Mgas/s=169.2 gasState=0.02 batch=438.1KB alloc=1.3GB sys=1.7GB
[INFO] [01-16|16:26:08.582] [4/12 Execution] Executed blocks         number=7497606 blk/s=1.0 tx/s=130.7 Mgas/s=17.4 gasState=0.05 batch=1.0MB alloc=966.0MB sys=1.7GB
[INFO] [01-16|16:26:36.988] [4/12 Execution] Executed blocks         number=7497617 blk/s=0.4 tx/s=48.7 Mgas/s=6.7 gasState=0.06 batch=1.3MB alloc=1.2GB sys=1.7GB
[INFO] [01-16|16:27:02.654] [p2p] GoodPeers                          eth67=1
[INFO] [01-16|16:27:02.765] [mem] memory stats                       Rss=4.3GB Size=0B Pss=4.3GB SharedClean=960.0KB SharedDirty=0B PrivateClean=2.0GB PrivateDirty=2.3GB Referenced=4.2GB Anonymous=2.3GB Swap=0B alloc=1.5GB sys=1.8GB
[INFO] [01-16|16:27:07.117] [4/12 Execution] Executed blocks         number=7497630 blk/s=0.4 tx/s=57.8 Mgas/s=7.6 gasState=0.08 batch=1.5MB alloc=1.5GB sys=1.8GB
[INFO] [01-16|16:27:17.783] [txpool] stat                            pending=0 baseFee=0 queued=2833 alloc=1.6GB sys=1.9GB
[INFO] [01-16|16:27:44.762] [4/12 Execution] Executed blocks         number=7497644 blk/s=0.4 tx/s=43.1 Mgas/s=7.3 gasState=0.09 batch=1.8MB alloc=1.1GB sys=1.9GB
[INFO] [01-16|16:27:57.930] [4/12 Execution] Completed on            block=7497697
[INFO] [01-16|16:27:57.930] [4/12 Execution] DONE                    in=4m21.720250439s
[INFO] [01-16|16:27:57.930] [5/12 HashState] Promoting plain state   from=7496738 to=7497697
[INFO] [01-16|16:27:57.930] [5/12 HashState] Incremental promotion   from=7496738 to=7497697 codes=true csbucket=AccountChangeSet
[INFO] [01-16|16:28:05.908] [5/12 HashState] Incremental promotion   from=7496738 to=7497697 codes=false csbucket=AccountChangeSet
[INFO] [01-16|16:28:36.494] [5/12 HashState] ETL [2/2] Loading       into=HashedAccount current_prefix=e6a17a65
[INFO] [01-16|16:28:42.035] [5/12 HashState] Incremental promotion   from=7496738 to=7497697 codes=false csbucket=StorageChangeSet
[INFO] [01-16|16:29:12.055] [5/12 HashState] ETL [1/2] Extracting    from=StorageChangeSet current_prefix=00000000007265060d83dab629f0e0f9d36c0cbc89b69a489f0751bd0000000000000001
[INFO] [01-16|16:29:42.036] [5/12 HashState] ETL [1/2] Extracting    from=StorageChangeSet current_prefix=00000000007265248cd0bad60e5ad9be59e5ca75214c100a88d4d87d0000000000000001
[INFO] [01-16|16:30:02.654] [p2p] GoodPeers                          eth68=1 eth67=1
[INFO] [01-16|16:30:02.778] [mem] memory stats                       Rss=4.4GB Size=0B Pss=4.4GB SharedClean=808.0KB SharedDirty=0B PrivateClean=1.9GB PrivateDirty=2.4GB Referenced=4.1GB Anonymous=2.4GB Swap=0B alloc=1.5GB sys=1.9GB
[INFO] [01-16|16:30:05.894] [txpool] stat                            pending=0 baseFee=0 queued=6250 alloc=1.5GB sys=1.9GB
[INFO] [01-16|16:30:12.040] [5/12 HashState] ETL [1/2] Extracting    from=StorageChangeSet current_prefix=000000000072655730dbb98d2b09acad19fd362bd88aa304ab6c10cc0000000000000001
[INFO] [01-16|16:30:42.078] [5/12 HashState] ETL [1/2] Extracting    from=StorageChangeSet current_prefix=00000000007265740d83dab629f0e0f9d36c0cbc89b69a489f0751bd0000000000000001
[INFO] [01-16|16:31:12.063] [5/12 HashState] ETL [1/2] Extracting    from=StorageChangeSet current_prefix=00000000007265a467fa43ca2d689bea4d10b9f2c96828828a2ab2750000000000000001
[INFO] [01-16|16:32:07.472] [5/12 HashState] ETL [2/2] Loading       into=HashedStorage current_prefix=4ea6f0c2
[INFO] [01-16|16:32:35.596] [5/12 HashState] ETL [2/2] Loading       into=HashedStorage current_prefix=64caa5b4
[INFO] [01-16|16:33:02.654] [p2p] GoodPeers                          eth67=1 eth68=1
[INFO] [01-16|16:33:02.783] [mem] memory stats                       Rss=4.5GB Size=0B Pss=4.5GB SharedClean=808.0KB SharedDirty=0B PrivateClean=1.9GB PrivateDirty=2.6GB Referenced=4.3GB Anonymous=2.5GB Swap=0B alloc=1.0GB sys=2.0GB
[INFO] [01-16|16:33:05.403] [5/12 HashState] DONE                    in=5m7.473417231s
[INFO] [01-16|16:33:05.404] [6/12 IntermediateHashes] Generating intermediate hashes from=7496738 to=7497697
[INFO] [01-16|16:33:05.893] [txpool] stat                            pending=0 baseFee=0 queued=7746 alloc=1.1GB sys=2.0GB
[INFO] [01-16|16:33:41.263] [6/12 IntermediateHashes] Calculating Merkle root current key=20d3b4b5
[INFO] [01-16|16:34:08.963] [6/12 IntermediateHashes] Calculating Merkle root current key=3143232e
[INFO] [01-16|16:34:38.949] [6/12 IntermediateHashes] Calculating Merkle root current key=4e7ab35d
[INFO] [01-16|16:35:12.907] [6/12 IntermediateHashes] Calculating Merkle root current key=4ea6f0c2
[INFO] [01-16|16:35:39.409] [6/12 IntermediateHashes] Calculating Merkle root current key=6bd4c711
[INFO] [01-16|16:36:02.654] [p2p] GoodPeers                          eth68=2 eth67=1
[INFO] [01-16|16:36:02.806] [mem] memory stats                       Rss=4.4GB Size=0B Pss=4.4GB SharedClean=808.0KB SharedDirty=0B PrivateClean=1.8GB PrivateDirty=2.6GB Referenced=4.3GB Anonymous=2.6GB Swap=0B alloc=1.7GB sys=2.1GB
[INFO] [01-16|16:36:05.893] [txpool] stat                            pending=0 baseFee=0 queued=9253 alloc=1.7GB sys=2.1GB
[INFO] [01-16|16:36:09.222] [6/12 IntermediateHashes] Calculating Merkle root current key=95a2aca8
[INFO] [01-16|16:36:39.439] [6/12 IntermediateHashes] Calculating Merkle root current key=a9fdd4af
[INFO] [01-16|16:37:09.488] [6/12 IntermediateHashes] Calculating Merkle root current key=ac28d030
[INFO] [01-16|16:37:39.012] [6/12 IntermediateHashes] Calculating Merkle root current key=aeb8c955
[INFO] [01-16|16:38:10.259] [6/12 IntermediateHashes] Calculating Merkle root current key=aff74aa7
[INFO] [01-16|16:38:38.925] [6/12 IntermediateHashes] Calculating Merkle root current key=b4766032
[INFO] [01-16|16:39:02.654] [p2p] GoodPeers                          eth68=2 eth67=1
[INFO] [01-16|16:39:02.801] [mem] memory stats                       Rss=4.6GB Size=0B Pss=4.6GB SharedClean=808.0KB SharedDirty=0B PrivateClean=1.8GB PrivateDirty=2.8GB Referenced=4.3GB Anonymous=2.8GB Swap=0B alloc=1.4GB sys=2.2GB
[INFO] [01-16|16:39:05.969] [txpool] stat                            pending=0 baseFee=0 queued=11027 alloc=1.4GB sys=2.2GB
[INFO] [01-16|16:39:09.300] [6/12 IntermediateHashes] Calculating Merkle root current key=cade2309
[INFO] [01-16|16:39:39.043] [6/12 IntermediateHashes] Calculating Merkle root current key=d798a1d7
[INFO] [01-16|16:40:09.052] [6/12 IntermediateHashes] Calculating Merkle root current key=d978c15e
[INFO] [01-16|16:40:39.714] [6/12 IntermediateHashes] Calculating Merkle root current key=e8658a51
[INFO] [01-16|16:41:31.462] [6/12 IntermediateHashes] ETL [2/2] Loading into=TrieAccount current_prefix=090e0d09
[INFO] [01-16|16:42:02.654] [p2p] GoodPeers                          eth68=2 eth67=1
[INFO] [01-16|16:42:02.833] [mem] memory stats                       Rss=4.9GB Size=0B Pss=4.9GB SharedClean=808.0KB SharedDirty=0B PrivateClean=2.0GB PrivateDirty=2.9GB Referenced=4.7GB Anonymous=2.8GB Swap=0B alloc=1.7GB sys=2.2GB
[INFO] [01-16|16:42:05.893] [txpool] stat                            pending=0 baseFee=0 queued=12668 alloc=1.7GB sys=2.2GB
[INFO] [01-16|16:42:16.750] [6/12 IntermediateHashes] ETL [2/2] Loading into=TrieStorage current_prefix=4ea6f0c2
[INFO] [01-16|16:42:46.750] [6/12 IntermediateHashes] ETL [2/2] Loading into=TrieStorage current_prefix=bdcb1adb
[INFO] [01-16|16:43:03.417] [6/12 IntermediateHashes] DONE           in=9m58.013248346s
[INFO] [01-16|16:43:07.031] [7/12 CallTraces] Pruned call trace intermediate table from=7406738 to=7407696
[INFO] [01-16|16:43:37.070] [7/12 CallTraces] ETL [2/2] Loading      into=CallFromIndex current_prefix=f0344a17
[INFO] [01-16|16:44:10.608] [7/12 CallTraces] ETL [2/2] Loading      into=CallToIndex current_prefix=e2ca9c43
[INFO] [01-16|16:44:12.156] [7/12 CallTraces] DONE                   in=1m8.738828605s
[INFO] [01-16|16:44:43.012] [8/12 AccountHistoryIndex] ETL [2/2] Loading into=AccountHistory current_prefix=c68f1841
[INFO] [01-16|16:45:02.654] [p2p] GoodPeers                          eth68=2 eth67=1
[INFO] [01-16|16:45:02.822] [mem] memory stats                       Rss=4.5GB Size=0B Pss=4.5GB SharedClean=796.0KB SharedDirty=0B PrivateClean=1.8GB PrivateDirty=2.7GB Referenced=4.3GB Anonymous=2.6GB Swap=0B alloc=1.5GB sys=2.2GB
[INFO] [01-16|16:45:05.894] [txpool] stat                            pending=0 baseFee=0 queued=14259 alloc=1.6GB sys=2.2GB
[INFO] [01-16|16:45:24.715] [9/12 StorageHistoryIndex] ETL [2/2] Loading into=StorageHistory current_prefix=5500e5f8
[INFO] [01-16|16:45:54.639] [9/12 StorageHistoryIndex] ETL [2/2] Loading into=StorageHistory current_prefix=b74d5dba
[INFO] [01-16|16:46:05.561] [9/12 StorageHistoryIndex] DONE          in=1m12.891285228s
[INFO] [01-16|16:46:05.561] [10/12 LogIndex] processing              from=7496739 to=7497697 pruneTo=0
[INFO] [01-16|16:46:40.928] [10/12 LogIndex] ETL [2/2] Loading       into=LogTopicIndex current_prefix=0000000000000000000000004bf08113210dd5bb38950aa7936c990865ab7a9effffffff
[INFO] [01-16|16:47:11.040] [10/12 LogIndex] ETL [2/2] Loading       into=LogTopicIndex current_prefix=0be06592
[INFO] [01-16|16:47:41.432] [10/12 LogIndex] DONE                    in=1m35.870380161s
[INFO] [01-16|16:48:02.654] [p2p] GoodPeers                          eth67=1 eth68=2
[INFO] [01-16|16:48:02.828] [mem] memory stats                       Rss=4.8GB Size=0B Pss=4.8GB SharedClean=792.0KB SharedDirty=0B PrivateClean=2.2GB PrivateDirty=2.6GB Referenced=4.5GB Anonymous=2.6GB Swap=0B alloc=1.6GB sys=2.3GB
[INFO] [01-16|16:48:05.893] [txpool] stat                            pending=0 baseFee=0 queued=15879 alloc=1.6GB sys=2.3GB
[INFO] [01-16|16:48:21.925] [11/12 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=432f1ed8
[INFO] [01-16|16:48:51.916] [11/12 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=4a00751a
[INFO] [01-16|16:49:21.926] [11/12 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=519fed57
[INFO] [01-16|16:49:52.022] [11/12 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=5411cc54
[INFO] [01-16|16:50:21.919] [11/12 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=7378cf9f
[INFO] [01-16|16:50:51.934] [11/12 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=fe9b982f
[INFO] [01-16|16:50:55.666] [11/12 TxLookup] DONE                    in=3m14.233826003s
[INFO] [01-16|16:50:56.571] RPC Daemon notified of new headers       from=7496738 to=7497697 amount=959 hash=0xaa0108e6c3358eb48392cdb5bc06602b3ca87663115e7ae715304fdb943c829a header sending=77.745197ms log sending=418ns

@antonis19
Copy link
Member

@keithchew can you provide all the flags you used?

@keithchew
Copy link
Author

@antonis19 here are the flags I am using:

--rpc.returndata.limit=2000000 --db.size.limit=8TB --authrpc.addr 0.0.0.0 --authrpc.port=8553 --datadir /root/.ethereum --chain=sepolia --http.port=8545 --batchSize=8mb --torrent.conns.perfile=4 --torrent.upload.rate=1mb --torrent.download.rate=1mb --private.api.addr=127.0.0.1:9090 --http --http.addr 0.0.0.0 --ws --http.api=eth,debug,net,trace,web3,erigon

@keithchew
Copy link
Author

Hmm, I have 2 other nodes on mainnet, which the upgrade went fine last week. But today, one of them is lagging behind, and very slow to catch up:

INFO[01-18|06:26:58.408] [NewPayload] Handling new payload        height=21648879 hash=0x6f15aefe4ea1e533f7cdb373c2601b26e7584f61b10447b83f1619cae882c3e1
INFO[01-18|06:27:21.091] [p2p] GoodPeers                          eth68=11 eth67=11
INFO[01-18|06:27:21.814] [mem] memory stats                       Rss=10.3GB Size=0B Pss=10.3GB SharedClean=4.0MB SharedDirty=0B PrivateClean=6.0GB PrivateDirty=4.3GB Referenced=10.2GB Anonymous=4.3GB Swap=0B alloc=3.3GB sys=4.7GB
INFO[01-18|06:27:37.798] [7/7 IntermediateHashes] Calculating Merkle root current key=d20e9c31
INFO[01-18|06:28:01.265] [txpool] stat                            pending=5326 baseFee=2283 queued=8513 alloc=3.6GB sys=4.7GB
INFO[01-18|06:28:33.808] [NewPayload] Handling new payload        height=21648879 hash=0x6f15aefe4ea1e533f7cdb373c2601b26e7584f61b10447b83f1619cae882c3e1
INFO[01-18|06:28:35.402] [4/12 Execution] Completed on            block=21648879
INFO[01-18|06:29:15.480] RPC Daemon notified of new headers       from=21648878 to=21648879 amount=1 hash=0x6f15aefe4ea1e533f7cdb373c2601b26e7584f61b10447b83f1619cae882c3e1
 header sending=8.676µs log sending=221ns
INFO[01-18|06:29:15.480] head updated                             hash=0x6f15aefe4ea1e533f7cdb373c2601b26e7584f61b10447b83f1619cae882c3e1 number=21648879
INFO[01-18|06:30:21.091] [p2p] GoodPeers                          eth68=11 eth67=12
INFO[01-18|06:30:21.810] [mem] memory stats                       Rss=10.3GB Size=0B Pss=10.3GB SharedClean=4.0MB SharedDirty=0B PrivateClean=6.1GB PrivateDirty=4.3GB Referenced=10.2GB Anonymous=4.3GB Swap=0B alloc=3.6GB sys=4.7GB
INFO[01-18|06:30:41.009] [NewPayload] Handling new payload        height=21648880 hash=0x6bd882da65a8e03e70ddb06734f7661888852e88f259d08a3a4b2dafffd73cdd
INFO[01-18|06:31:02.572] [txpool] stat                            pending=5573 baseFee=2376 queued=8738 alloc=3.2GB sys=4.7GB
INFO[01-18|06:31:33.208] [NewPayload] Handling new payload        height=21648880 hash=0x6bd882da65a8e03e70ddb06734f7661888852e88f259d08a3a4b2dafffd73cdd
INFO[01-18|06:31:35.207] [4/12 Execution] Completed on            block=21648880
INFO[01-18|06:31:53.353] RPC Daemon notified of new headers       from=21648879 to=21648880 amount=1 hash=0x6bd882da65a8e03e70ddb06734f7661888852e88f259d08a3a4b2dafffd73cdd
 header sending=12.173µs log sending=621ns
INFO[01-18|06:31:53.353] head updated                             hash=0x6bd882da65a8e03e70ddb06734f7661888852e88f259d08a3a4b2dafffd73cdd number=21648880
INFO[01-18|06:33:05.409] [NewPayload] Handling new payload        height=21648881 hash=0x4428dbfea831160bad3de71d6ddc7159da51f7465667b034031c1273300720b8
INFO[01-18|06:33:21.092] [p2p] GoodPeers                          eth68=12 eth67=12
INFO[01-18|06:33:21.824] [mem] memory stats                       Rss=10.4GB Size=0B Pss=10.4GB SharedClean=4.4MB SharedDirty=0B PrivateClean=6.1GB PrivateDirty=4.3GB Referenced=10.3GB Anonymous=4.3GB Swap=0B alloc=3.3GB sys=4.7GB
INFO[01-18|06:33:46.845] [7/7 IntermediateHashes] Calculating Merkle root current key=89187d0f
INFO[01-18|06:34:02.262] [txpool] stat                            pending=6085 baseFee=2177 queued=9109 alloc=3.5GB sys=4.7GB
INFO[01-18|06:34:09.255] [NewPayload] Handling new payload        height=21648881 hash=0x4428dbfea831160bad3de71d6ddc7159da51f7465667b034031c1273300720b8
INFO[01-18|06:34:10.879] [4/12 Execution] Completed on            block=21648881
INFO[01-18|06:34:52.060] RPC Daemon notified of new headers       from=21648880 to=21648881 amount=1 hash=0x4428dbfea831160bad3de71d6ddc7159da51f7465667b034031c1273300720b8
 header sending=11.051µs log sending=551ns
INFO[01-18|06:34:52.060] head updated                             hash=0x4428dbfea831160bad3de71d6ddc7159da51f7465667b034031c1273300720b8 number=21648881
INFO[01-18|06:36:21.091] [p2p] GoodPeers                          eth67=13 eth68=13
INFO[01-18|06:36:22.046] [mem] memory stats                       Rss=10.5GB Size=0B Pss=10.5GB SharedClean=4.9MB SharedDirty=0B PrivateClean=6.1GB PrivateDirty=4.4GB Referenced=10.4GB Anonymous=4.4GB Swap=0B alloc=3.6GB sys=4.7GB
INFO[01-18|06:36:39.009] [NewPayload] Handling new payload        height=21648882 hash=0x8b230560126ccc0e2d9714135281e077f2728d2a9dd5d8d13eb11ee0ee52253e
INFO[01-18|06:37:01.362] [txpool] stat                            pending=6291 baseFee=2331 queued=9387 alloc=3.2GB sys=4.7GB
INFO[01-18|06:37:26.919] [7/7 IntermediateHashes] Calculating Merkle root current key=672d71b3
INFO[01-18|06:37:56.806] [7/7 IntermediateHashes] Calculating Merkle root current key=f9eabf1e

It is interesting that it looks like each block is being handled twice? A restart did not help, and the same logs as above appears. Reverting back to v2.60.10 works, it catches up fast and without issues.

It might not be related to this sepolia bug, but will keep monitoring...

@antonis19
Copy link
Member

Can you try setting --batchSize 5G and see if the issue persists?

@keithchew
Copy link
Author

@antonis19 I have updated to 5G, and it is still painfully slow. It is similar to the mainnet logs above, ie each block is processed twice. And there are these strange [7/7 IntermediateHashes] Calculating Merkle logs coming up during the steps.

[INFO] [01-18|17:55:58.323] [txpool] Started
[INFO] [01-18|17:55:58.935] [1/12 Snapshots] Requesting downloads
[INFO] [01-18|17:55:59.344] Started P2P networking                   version=67 self=enode://cd92c2bead2ebc2a6f43a7f2a732c0153ba3da404b03a768c75c358e933babb5fe9f8d156584541df10a49fce4d5c0d9506dd1feae61a7baf214bf7eb2b1a0cf@210.185.60.47:31304 name=erigon/v2.61.0-3ea0dd41/linux-amd64/go1.22.2
[INFO] [01-18|17:55:59.348] Started P2P networking                   version=68 self=enode://cd92c2bead2ebc2a6f43a7f2a732c0153ba3da404b03a768c75c358e933babb5fe9f8d156584541df10a49fce4d5c0d9506dd1feae61a7baf214bf7eb2b1a0cf@210.185.60.47:31303 name=erigon/v2.61.0-3ea0dd41/linux-amd64/go1.22.2
[INFO] [01-18|17:55:59.409] [snapshots:download] Stat                blocks=7429k indices=7429k alloc=852.3MB sys=902.6MB
[INFO] [01-18|17:55:59.992] [NewPayload] Handling new payload        height=7519969 hash=0xa14a0b8db7861cb93f9b0c2eb5b176f86e03a16c6f732859838be25501f60a05
[INFO] [01-18|17:56:33.426] [7/7 IntermediateHashes] Calculating Merkle root current key=6f68313a
[INFO] [01-18|17:57:03.243] [7/7 IntermediateHashes] Calculating Merkle root current key=9ae103c0
[INFO] [01-18|17:57:33.628] [7/7 IntermediateHashes] Calculating Merkle root current key=da17d0e6

[INFO] [01-18|17:57:59.624] [NewPayload] Handling new payload        height=7519969 hash=0xa14a0b8db7861cb93f9b0c2eb5b176f86e03a16c6f732859838be25501f60a05
[INFO] [01-18|17:58:01.365] [4/12 Execution] Completed on            block=7519969
[INFO] [01-18|17:58:31.719] [5/12 HashState] ETL [2/2] Loading       into=HashedCodeHash current_prefix=e0bababf
[INFO] [01-18|17:58:54.867] [p2p] GoodPeers                          eth68=1 eth67=2
[INFO] [01-18|17:58:55.955] [mem] memory stats                       Rss=1.5GB Size=0B Pss=1.5GB SharedClean=1008.0KB SharedDirty=0B PrivateClean=358.9MB PrivateDirty=1.1GB Referenced=1.4GB Anonymous=1.1GB Swap=0B alloc=1018.6MB sys=1.1GB
[INFO] [01-18|17:59:32.179] [7/12 CallTraces] ETL [2/2] Loading      into=CallFromIndex current_prefix=7079c07c
[INFO] [01-18|18:00:01.962] [7/12 CallTraces] ETL [2/2] Loading      into=CallFromIndex current_prefix=cea3e624
[INFO] [01-18|18:00:38.459] [7/12 CallTraces] ETL [2/2] Loading      into=CallToIndex current_prefix=6ea58b0c
[INFO] [01-18|18:01:08.356] [7/12 CallTraces] ETL [2/2] Loading      into=CallToIndex current_prefix=ff000000
[INFO] [01-18|18:01:08.357] [7/12 CallTraces] DONE                   in=2m6.580072174s
[INFO] [01-18|18:01:38.478] [8/12 AccountHistoryIndex] ETL [2/2] Loading into=AccountHistory current_prefix=4257db82
[INFO] [01-18|18:01:54.868] [p2p] GoodPeers                          eth68=2 eth67=2
[INFO] [01-18|18:01:54.894] [mem] memory stats                       Rss=1.7GB Size=0B Pss=1.7GB SharedClean=1008.0KB SharedDirty=0B PrivateClean=437.2MB PrivateDirty=1.2GB Referenced=1.5GB Anonymous=1.2GB Swap=0B alloc=817.4MB sys=1.2GB
[INFO] [01-18|18:02:08.362] [8/12 AccountHistoryIndex] ETL [2/2] Loading into=AccountHistory current_prefix=a85ee64b
[INFO] [01-18|18:02:32.383] [8/12 AccountHistoryIndex] DONE          in=1m24.026059703s
[INFO] [01-18|18:03:02.962] [9/12 StorageHistoryIndex] ETL [2/2] Loading into=StorageHistory current_prefix=4e26e873
[INFO] [01-18|18:03:32.493] [9/12 StorageHistoryIndex] ETL [2/2] Loading into=StorageHistory current_prefix=6866b492
[INFO] [01-18|18:04:02.547] [9/12 StorageHistoryIndex] ETL [2/2] Loading into=StorageHistory current_prefix=b74d5dba
[INFO] [01-18|18:04:32.203] [9/12 StorageHistoryIndex] DONE          in=1m59.820028738s
[INFO] [01-18|18:04:54.867] [p2p] GoodPeers                          eth68=2 eth67=3
[INFO] [01-18|18:04:54.896] [mem] memory stats                       Rss=1.8GB Size=0B Pss=1.8GB SharedClean=1008.0KB SharedDirty=0B PrivateClean=493.2MB PrivateDirty=1.3GB Referenced=1.6GB Anonymous=1.3GB Swap=0B alloc=1.0GB sys=1.2GB
[INFO] [01-18|18:05:02.504] [10/12 LogIndex] ETL [2/2] Loading       into=LogTopicIndex current_prefix=000000000000000000000000d94be4db5bbc413988190072bd0f4deddfaeccacffffffff
[INFO] [01-18|18:05:32.260] [10/12 LogIndex] ETL [2/2] Loading       into=LogTopicIndex current_prefix=f73cdb28
[INFO] [01-18|18:05:52.041] [10/12 LogIndex] DONE                    in=1m19.838372905s
[INFO] [01-18|18:06:22.169] [11/12 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=712ef6c2
[INFO] [01-18|18:06:52.403] [11/12 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=f18e5b05
[INFO] [01-18|18:06:56.976] [11/12 TxLookup] DONE                    in=1m4.9348169s
[INFO] [01-18|18:06:58.580] RPC Daemon notified of new headers       from=7519966 to=7519969 amount=3 hash=0xa14a0b8db7861cb93f9b0c2eb5b176f86e03a16c6f732859838be25501f60a05 header sending=19.734µs log sending=181ns
[INFO] [01-18|18:06:58.580] head updated                             hash=0xa14a0b8db7861cb93f9b0c2eb5b176f86e03a16c6f732859838be25501f60a05 number=7519969
[INFO] [01-18|18:07:08.833] [NewPayload] Handling new payload        height=7519970 hash=0xec531dd050e250f24723b305a187c72497c16bf937d3fcef3ee67ac022701402
[INFO] [01-18|18:07:54.867] [p2p] GoodPeers                          eth68=2 eth67=3
[INFO] [01-18|18:07:54.911] [mem] memory stats                       Rss=2.0GB Size=0B Pss=2.0GB SharedClean=1008.0KB SharedDirty=0B PrivateClean=681.2MB PrivateDirty=1.3GB Referenced=1.8GB Anonymous=1.3GB Swap=0B alloc=835.2MB sys=1.2GB
[INFO] [01-18|18:09:14.535] [7/7 IntermediateHashes] Calculating Merkle root current key=2198fa93
[INFO] [01-18|18:10:00.679] [7/7 IntermediateHashes] Calculating Merkle root current key=35a0fddd
[INFO] [01-18|18:10:12.362] [7/7 IntermediateHashes] Calculating Merkle root current key=4631fe63
[INFO] [01-18|18:10:41.189] [7/7 IntermediateHashes] Calculating Merkle root current key=4ea6f0c2
[INFO] [01-18|18:10:54.867] [p2p] GoodPeers                          eth68=2 eth67=3
[INFO] [01-18|18:10:54.911] [mem] memory stats                       Rss=2.0GB Size=0B Pss=2.0GB SharedClean=1008.0KB SharedDirty=0B PrivateClean=734.7MB PrivateDirty=1.3GB Referenced=1.8GB Anonymous=1.3GB Swap=0B alloc=1.1GB sys=1.2GB
[INFO] [01-18|18:11:11.887] [7/7 IntermediateHashes] Calculating Merkle root current key=67d91fc8
[INFO] [01-18|18:11:20.482] [txpool] stat                            pending=0 baseFee=0 queued=0 alloc=685.7MB sys=1.2GB
[INFO] [01-18|18:11:40.860] [7/7 IntermediateHashes] Calculating Merkle root current key=8e998158
[INFO] [01-18|18:12:18.903] [7/7 IntermediateHashes] Calculating Merkle root current key=af19b430
[INFO] [01-18|18:12:41.871] [7/7 IntermediateHashes] Calculating Merkle root current key=c3e6c03b
[INFO] [01-18|18:13:10.997] [7/7 IntermediateHashes] Calculating Merkle root current key=e105edc6
[INFO] [01-18|18:13:41.675] [7/7 IntermediateHashes] Calculating Merkle root current key=feed655e
[INFO] [01-18|18:13:52.377] [NewPayload] Handling new payload        height=7519970 hash=0xec531dd050e250f24723b305a187c72497c16bf937d3fcef3ee67ac022701402
[INFO] [01-18|18:13:53.523] [4/12 Execution] Completed on            block=7519970
[INFO] [01-18|18:13:54.868] [p2p] GoodPeers                          eth67=3 eth68=2
[INFO] [01-18|18:13:54.922] [mem] memory stats                       Rss=2.0GB Size=0B Pss=2.0GB SharedClean=1008.0KB SharedDirty=0B PrivateClean=761.0MB PrivateDirty=1.3GB Referenced=1.9GB Anonymous=1.3GB Swap=0B alloc=818.8MB sys=1.2GB

I have seen some recent issues regarding erigon3 that is broken with externalcl, I wonder if v2.61.0 pulled some work from e3 which is now causing issues with e2?

@antonis19
Copy link
Member

Are you running with external CL? If so which one is it?

I am getting around 400 mgas/s running with internal CL btw.

@keithchew
Copy link
Author

yes, running prysm v5.2.0.

@AskAlexSharov
Copy link
Collaborator

see https://github.com/erigontech/erigon?tab=readme-ov-file#cloud-network-drives

@keithchew
Copy link
Author

I am sunning on SSD, and v2.60.10 working fine. v2.61.0 is consistently slow/broken.

@AskAlexSharov
Copy link
Collaborator

  • It is interesting that it looks like each block is being handled twice? - seems this is root of problem.
  • I wonder if v2.61.0 pulled some work from e3 which is now causing issues with e2? - no.

@keithchew
Copy link
Author

@antonis19 do you have what you need to investigate this issue? Let me know if you need me to try anything else from my end.

@antonis19
Copy link
Member

@keithchew yes, we are investigating this currently. I will reach out with more updates or if we need more info.

@antonis19
Copy link
Member

@keithchew I wasn't able to replicate the issue, I managed to catch up with latest block just fine using Prysm v5.1.2 following the guide here: https://docs.prylabs.network/docs/install/install-with-script.

I will also try with v5.2.0 to see if the version is the cause of the problem.

In the meantime, could you provide me with the command you used to run prysm?

@antonis19
Copy link
Member

@keithchew actually the prysm.sh automatically fetches the latest version which is v5.2.0 , so I was running the latest version of prysm and erigon 2.61.0 on sepolia tip with no issues.

@keithchew
Copy link
Author

@antonis19 do you mind doing a restart on erigon, and post the logs here, so that I can compare with mine above?

@antonis19
Copy link
Member

@keithchew Sure. I'll stop erigon for 1hour and let it catch up to the tip, and will paste the logs here.

@antonis19
Copy link
Member

antonis19 commented Jan 21, 2025 •
edited
Loading

@keithchew See logs below:

[INFO] [01-21|19:29:07.136] logging to file system                   log dir=/home/erigon/sepolia-e2/logs file prefix=erigon log level=info json=false
[INFO] [01-21|19:29:07.136] Enabling metrics export to prometheus    path=http://0.0.0.0:6061/debug/metrics/prometheus
[INFO] [01-21|19:29:07.136] Build info                               git_branch=release/2.61 git_tag=v2.61.0-12-ge6b7ad8 git_commit=e6b7ad827b465d524c7878bf6ea51f4b24b54ef0
[INFO] [01-21|19:29:07.136] Starting Erigon on Sepolia testnet... 
[INFO] [01-21|19:29:07.137] Maximum peer count                       ETH=100 total=100
[INFO] [01-21|19:29:07.137] starting HTTP APIs                       port=8545 APIs=eth,debug,net,trace,web3,erigon
[INFO] [01-21|19:29:07.137] torrent verbosity                        level=WRN
[INFO] [01-21|19:29:09.140] Set global gas cap                       cap=50000000
[INFO] [01-21|19:29:09.140] [Downloader] Running with                ipv6-enabled=true ipv4-enabled=true download.rate=1G upload.rate=1G
[INFO] [01-21|19:29:09.143] Opening Database                         label=chaindata path=/home/erigon/sepolia-e2/chaindata
[INFO] [01-21|19:29:09.144] [db] open                                label=chaindata sizeLimit=8TB pageSize=8192
[INFO] [01-21|19:29:09.144] Initialised chain configuration          config="{ChainID: 11155111, Homestead: 0, DAO: <nil>, Tangerine Whistle: 0, Spurious Dragon: 0, Byzantium: 0, Constantinople: 0, Petersburg: 0, Istanbul: 0, Muir Glacier: 0, Berlin: 0, London: 0, Arrow Glacier: <nil>, Gray Glacier: <nil>, Terminal Total Difficulty: 17000000000000000, Merge Netsplit: 1735371, Shanghai: 1677557088, Cancun: 1706655072, Prague: <nil>, Osaka: <nil>, Engine: ethash}" genesis=0x25a5cc106eea7138acab33231d7160d69cb777ee0c2c553fcddf5138993e6dd9
[INFO] [01-21|19:29:49.816] Initialising Ethereum protocol           network=11155111
[INFO] [01-21|19:29:49.816] Disk storage enabled for ethash DAGs     dir=/home/erigon/sepolia-e2/ethash-dags count=2
[INFO] [01-21|19:29:50.012] Starting private RPC server              on=127.0.0.1:9090
[INFO] [01-21|19:29:50.012] new subscription to logs established 
[INFO] [01-21|19:29:50.012] rpc filters: subscribing to Erigon events 
[INFO] [01-21|19:29:50.012] new subscription to newHeaders established 
[INFO] [01-21|19:29:50.012] New txs subscriber joined 
[INFO] [01-21|19:29:50.012] [txpool] Started 
[INFO] [01-21|19:29:50.012] Reading JWT secret                       path=/home/erigon/sepolia-e2/jwt.hex
[INFO] [01-21|19:29:50.012] HTTP endpoint opened for Engine API      url=[::]:8553 ws=true ws.compression=true
[INFO] [01-21|19:29:50.012] JsonRpc endpoint opened                  ws=true ws.compression=true grpc=false websocket.url=[::]:8546 http.url=[::]:8545
[INFO] [01-21|19:29:50.025] [1/12 Snapshots] Requesting downloads 
[WARN] [01-21|19:29:50.026] NAT ExternalIP resolution has failed, try to pass a different --nat option err="no UPnP or NAT-PMP router discovered"
[WARN] [01-21|19:29:50.028] NAT ExternalIP resolution has failed, try to pass a different --nat option err="no UPnP or NAT-PMP router discovered"
[INFO] [01-21|19:29:50.047] Started P2P networking                   version=67 self=enode://72fe439530f69bea02d13bd7342e1171de26eb72f4f468e0bc376cdb6a291b6785fc4f8735fb8f53e5b274ce5afbf2e7338a11599903b3736b9260624794f3f7@127.0.0.1:30304 name=erigon/v2.61.0-e6b7ad82/linux-amd64/go1.23.3
[INFO] [01-21|19:29:50.049] Started P2P networking                   version=68 self=enode://72fe439530f69bea02d13bd7342e1171de26eb72f4f468e0bc376cdb6a291b6785fc4f8735fb8f53e5b274ce5afbf2e7338a11599903b3736b9260624794f3f7@127.0.0.1:30303 name=erigon/v2.61.0-e6b7ad82/linux-amd64/go1.23.3
[WARN] [01-21|19:29:53.083] [rpc] served                             conn=194.67.206.45:35784 method=eth_coinbase reqid=2 t=70.161µs err="etherbase must be explicitly specified"
[WARN] [01-21|19:29:53.244] [rpc] served                             conn=194.67.206.44:51074 method=eth_accounts reqid=2 t=49.813µs err="the method has been deprecated: eth_accounts"
[INFO] [01-21|19:30:10.027] [1/12 Snapshots] download finished       time=20.000990499s
[INFO] [01-21|19:30:10.044] [snapshots:download] Stat                blocks=7451k indices=7451k alloc=822.1MB sys=1.1GB
[INFO] [01-21|19:30:31.199] [11/12 TxLookup Prune] Flushed buffer file name=erigon-sortable-buf-1131307324
[INFO] [01-21|19:30:40.045] [11/12 TxLookup Prune] ETL [1/2] Extracting from=CanonicalHeader block=7364896
[INFO] [01-21|19:30:51.942] [11/12 TxLookup Prune] Flushed buffer file name=erigon-sortable-buf-3896147876
[INFO] [01-21|19:31:12.411] [11/12 TxLookup Prune] Flushed buffer file name=erigon-sortable-buf-4131290344
[INFO] [01-21|19:31:12.411] [11/12 TxLookup Prune] ETL [1/2] Extracting from=CanonicalHeader block=7422861
[INFO] [01-21|19:31:29.391] [11/12 TxLookup Prune] Flushed buffer file name=erigon-sortable-buf-235373302
[INFO] [01-21|19:31:39.295] [11/12 TxLookup] Prune done              in=1m29.250630144s
[INFO] [01-21|19:32:00.489] [NewPayload] Handling new payload        height=7541416 hash=0xe0141566f0ebb00f190b4d48d96915068b6618037446f47856d00fc3bc8270ee
[INFO] [01-21|19:32:00.663] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:00.835] RPC Daemon notified of new headers       from=7541415 to=7541416 amount=1 hash=0xe0141566f0ebb00f190b4d48d96915068b6618037446f47856d00fc3bc8270ee header sending=10.189µs log sending=151ns
[INFO] [01-21|19:32:00.835] head updated                             hash=0xe0141566f0ebb00f190b4d48d96915068b6618037446f47856d00fc3bc8270ee number=7541416
[INFO] [01-21|19:32:00.903] [NewPayload] Handling new payload        height=7541417 hash=0x8ad11afc387188bba8fac3c82ff3d66daa46ad34a00dc95d6372f84978067b13
[INFO] [01-21|19:32:01.141] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:01.336] RPC Daemon notified of new headers       from=7541416 to=7541417 amount=1 hash=0x8ad11afc387188bba8fac3c82ff3d66daa46ad34a00dc95d6372f84978067b13 header sending=10.209µs log sending=291ns
[INFO] [01-21|19:32:01.336] head updated                             hash=0x8ad11afc387188bba8fac3c82ff3d66daa46ad34a00dc95d6372f84978067b13 number=7541417
[INFO] [01-21|19:32:01.393] [NewPayload] Handling new payload        height=7541418 hash=0x0cb1f8926b634edb985cd6afc3ecad54f7500edf5e6d55596f910a978ebb7681
[INFO] [01-21|19:32:01.707] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:01.919] RPC Daemon notified of new headers       from=7541417 to=7541418 amount=1 hash=0x0cb1f8926b634edb985cd6afc3ecad54f7500edf5e6d55596f910a978ebb7681 header sending=9.898µs log sending=421ns
[INFO] [01-21|19:32:01.919] head updated                             hash=0x0cb1f8926b634edb985cd6afc3ecad54f7500edf5e6d55596f910a978ebb7681 number=7541418
[INFO] [01-21|19:32:01.975] [NewPayload] Handling new payload        height=7541419 hash=0x383939e3d496657ff0a03245d306c094e005d3da70ca3d56bd9a41663c20fac0
[INFO] [01-21|19:32:02.178] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:02.325] RPC Daemon notified of new headers       from=7541418 to=7541419 amount=1 hash=0x383939e3d496657ff0a03245d306c094e005d3da70ca3d56bd9a41663c20fac0 header sending=9.799µs log sending=160ns
[INFO] [01-21|19:32:02.325] head updated                             hash=0x383939e3d496657ff0a03245d306c094e005d3da70ca3d56bd9a41663c20fac0 number=7541419
[INFO] [01-21|19:32:02.370] [NewPayload] Handling new payload        height=7541420 hash=0x5db003d85618f7788ff5471cac6401d8b12f6d48ad0d3345db9913d05066ce2b
[INFO] [01-21|19:32:02.491] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:02.608] RPC Daemon notified of new headers       from=7541419 to=7541420 amount=1 hash=0x5db003d85618f7788ff5471cac6401d8b12f6d48ad0d3345db9913d05066ce2b header sending=10.87µs log sending=250ns
[INFO] [01-21|19:32:02.608] head updated                             hash=0x5db003d85618f7788ff5471cac6401d8b12f6d48ad0d3345db9913d05066ce2b number=7541420
[INFO] [01-21|19:32:02.665] [NewPayload] Handling new payload        height=7541421 hash=0x214680b1bf1ba6f3b35128f0131f9a4e1d15f3f9739578a7cec31fc23b92f622
[INFO] [01-21|19:32:02.818] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:02.958] RPC Daemon notified of new headers       from=7541420 to=7541421 amount=1 hash=0x214680b1bf1ba6f3b35128f0131f9a4e1d15f3f9739578a7cec31fc23b92f622 header sending=9.768µs log sending=251ns
[INFO] [01-21|19:32:02.958] head updated                             hash=0x214680b1bf1ba6f3b35128f0131f9a4e1d15f3f9739578a7cec31fc23b92f622 number=7541421
[INFO] [01-21|19:32:03.019] [NewPayload] Handling new payload        height=7541422 hash=0xfbc5f45f4cadb13fcdf12abb581c2687775681f001cdebca818657a65dfdfa04
[INFO] [01-21|19:32:03.138] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:03.255] RPC Daemon notified of new headers       from=7541421 to=7541422 amount=1 hash=0xfbc5f45f4cadb13fcdf12abb581c2687775681f001cdebca818657a65dfdfa04 header sending=10.82µs log sending=151ns
[INFO] [01-21|19:32:03.255] head updated                             hash=0xfbc5f45f4cadb13fcdf12abb581c2687775681f001cdebca818657a65dfdfa04 number=7541422
[INFO] [01-21|19:32:03.302] [NewPayload] Handling new payload        height=7541423 hash=0xd312ec3cc72b1ae699d30b19f33886d8df82d4fa89f3d582b25b0614c136a2ef
[INFO] [01-21|19:32:03.407] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:03.515] RPC Daemon notified of new headers       from=7541422 to=7541423 amount=1 hash=0xd312ec3cc72b1ae699d30b19f33886d8df82d4fa89f3d582b25b0614c136a2ef header sending=9.537µs log sending=170ns
[INFO] [01-21|19:32:03.515] head updated                             hash=0xd312ec3cc72b1ae699d30b19f33886d8df82d4fa89f3d582b25b0614c136a2ef number=7541423
[INFO] [01-21|19:32:03.563] [NewPayload] Handling new payload        height=7541424 hash=0x3f66da8d21bc107d440375ce457abc1e55a4c36486a210189ed2d05c0e146a60
[INFO] [01-21|19:32:04.069] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:04.443] RPC Daemon notified of new headers       from=7541423 to=7541424 amount=1 hash=0x3f66da8d21bc107d440375ce457abc1e55a4c36486a210189ed2d05c0e146a60 header sending=11.11µs log sending=240ns
[INFO] [01-21|19:32:04.443] head updated                             hash=0x3f66da8d21bc107d440375ce457abc1e55a4c36486a210189ed2d05c0e146a60 number=7541424
[INFO] [01-21|19:32:04.511] [NewPayload] Handling new payload        height=7541425 hash=0x7ca1c1de6cca2bd9e336c5ee8b643584c4be6d3d310c97f8a4019090ea56a87a
[INFO] [01-21|19:32:04.637] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:04.752] RPC Daemon notified of new headers       from=7541424 to=7541425 amount=1 hash=0x7ca1c1de6cca2bd9e336c5ee8b643584c4be6d3d310c97f8a4019090ea56a87a header sending=11.031µs log sending=240ns
[INFO] [01-21|19:32:04.752] head updated                             hash=0x7ca1c1de6cca2bd9e336c5ee8b643584c4be6d3d310c97f8a4019090ea56a87a number=7541425
[INFO] [01-21|19:32:04.799] [NewPayload] Handling new payload        height=7541426 hash=0xd4282911aad00c0236e8d724d1bc3ea5bdcdfde61beda05079d3057736c6fd7a
[INFO] [01-21|19:32:04.915] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:05.032] RPC Daemon notified of new headers       from=7541425 to=7541426 amount=1 hash=0xd4282911aad00c0236e8d724d1bc3ea5bdcdfde61beda05079d3057736c6fd7a header sending=9.698µs log sending=231ns
[INFO] [01-21|19:32:05.032] head updated                             hash=0xd4282911aad00c0236e8d724d1bc3ea5bdcdfde61beda05079d3057736c6fd7a number=7541426
[INFO] [01-21|19:32:05.091] [NewPayload] Handling new payload        height=7541427 hash=0x20e433648a56a41768ef3670a2c38730a6ca687a05746d680ba50b734a1e5943
[INFO] [01-21|19:32:05.207] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:05.314] RPC Daemon notified of new headers       from=7541426 to=7541427 amount=1 hash=0x20e433648a56a41768ef3670a2c38730a6ca687a05746d680ba50b734a1e5943 header sending=12.023µs log sending=150ns
[INFO] [01-21|19:32:05.314] head updated                             hash=0x20e433648a56a41768ef3670a2c38730a6ca687a05746d680ba50b734a1e5943 number=7541427
[INFO] [01-21|19:32:05.357] [NewPayload] Handling new payload        height=7541428 hash=0xf0a0c0e61628b27659f3d406212b4c60b935fb29db4097fea386c9be7622fcfb
[INFO] [01-21|19:32:05.440] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:05.533] RPC Daemon notified of new headers       from=7541427 to=7541428 amount=1 hash=0xf0a0c0e61628b27659f3d406212b4c60b935fb29db4097fea386c9be7622fcfb header sending=10.219µs log sending=161ns
[INFO] [01-21|19:32:05.534] head updated                             hash=0xf0a0c0e61628b27659f3d406212b4c60b935fb29db4097fea386c9be7622fcfb number=7541428
[INFO] [01-21|19:32:05.583] [NewPayload] Handling new payload        height=7541429 hash=0xe192ad804d3ef505ee00efc631e21d72cacab9f5534358cca515fd716916d9f9
[INFO] [01-21|19:32:05.704] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:05.818] RPC Daemon notified of new headers       from=7541428 to=7541429 amount=1 hash=0xe192ad804d3ef505ee00efc631e21d72cacab9f5534358cca515fd716916d9f9 header sending=14.377µs log sending=160ns
[INFO] [01-21|19:32:05.818] head updated                             hash=0xe192ad804d3ef505ee00efc631e21d72cacab9f5534358cca515fd716916d9f9 number=7541429
[INFO] [01-21|19:32:05.852] [NewPayload] Handling new payload        height=7541430 hash=0x8f3b11941106b303b14cbe52a65a37f852233fcdcacf5817817dad56775f7c71
[INFO] [01-21|19:32:05.866] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:05.877] RPC Daemon notified of new headers       from=7541429 to=7541430 amount=1 hash=0x8f3b11941106b303b14cbe52a65a37f852233fcdcacf5817817dad56775f7c71 header sending=7.174µs log sending=591ns
[INFO] [01-21|19:32:05.877] head updated                             hash=0x8f3b11941106b303b14cbe52a65a37f852233fcdcacf5817817dad56775f7c71 number=7541430
[INFO] [01-21|19:32:05.901] [NewPayload] Handling new payload        height=7541431 hash=0xdfd292c241c4189026a9f315912768866ca0ae5beabede8e3a94ad4b7a8070fe
[INFO] [01-21|19:32:06.087] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:06.279] RPC Daemon notified of new headers       from=7541430 to=7541431 amount=1 hash=0xdfd292c241c4189026a9f315912768866ca0ae5beabede8e3a94ad4b7a8070fe header sending=8.807µs log sending=431ns
[INFO] [01-21|19:32:06.279] head updated                             hash=0xdfd292c241c4189026a9f315912768866ca0ae5beabede8e3a94ad4b7a8070fe number=7541431
[INFO] [01-21|19:32:06.368] [NewPayload] Handling new payload        height=7541432 hash=0xc25521a8cea0e71c0dca77d18ec49a4606ed0d31c019cb0a19285b41109e8843
[INFO] [01-21|19:32:06.546] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:06.703] RPC Daemon notified of new headers       from=7541431 to=7541432 amount=1 hash=0xc25521a8cea0e71c0dca77d18ec49a4606ed0d31c019cb0a19285b41109e8843 header sending=8.946µs log sending=241ns
[INFO] [01-21|19:32:06.703] head updated                             hash=0xc25521a8cea0e71c0dca77d18ec49a4606ed0d31c019cb0a19285b41109e8843 number=7541432
[INFO] [01-21|19:32:06.774] [NewPayload] Handling new payload        height=7541433 hash=0x168b3774eb81d068c729ac1ad2d14a357ac53c7df5cef9fa3574b6d57439bd6b
[INFO] [01-21|19:32:06.910] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:07.040] RPC Daemon notified of new headers       from=7541432 to=7541433 amount=1 hash=0x168b3774eb81d068c729ac1ad2d14a357ac53c7df5cef9fa3574b6d57439bd6b header sending=14.106µs log sending=561ns
[INFO] [01-21|19:32:07.040] head updated                             hash=0x168b3774eb81d068c729ac1ad2d14a357ac53c7df5cef9fa3574b6d57439bd6b number=7541433
[INFO] [01-21|19:32:07.094] [NewPayload] Handling new payload        height=7541434 hash=0x738beaf6ca784872cf358ff9cdaad2c432df87f1ad50c8726a2527757d05236a
[INFO] [01-21|19:32:07.184] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:07.263] RPC Daemon notified of new headers       from=7541433 to=7541434 amount=1 hash=0x738beaf6ca784872cf358ff9cdaad2c432df87f1ad50c8726a2527757d05236a header sending=9.298µs log sending=230ns
[INFO] [01-21|19:32:07.263] head updated                             hash=0x738beaf6ca784872cf358ff9cdaad2c432df87f1ad50c8726a2527757d05236a number=7541434
[INFO] [01-21|19:32:07.300] [NewPayload] Handling new payload        height=7541435 hash=0x284d8eac70e29d2ca5c84476107f77f09b919409f083e9c041587d08dca9d50a
[INFO] [01-21|19:32:07.393] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:07.497] RPC Daemon notified of new headers       from=7541434 to=7541435 amount=1 hash=0x284d8eac70e29d2ca5c84476107f77f09b919409f083e9c041587d08dca9d50a header sending=10.149µs log sending=541ns
[INFO] [01-21|19:32:07.497] head updated                             hash=0x284d8eac70e29d2ca5c84476107f77f09b919409f083e9c041587d08dca9d50a number=7541435
[INFO] [01-21|19:32:07.556] [NewPayload] Handling new payload        height=7541436 hash=0xe1931be301f73a2425375c3a3983011070963b7480cb44fb416351016da79d7a
[INFO] [01-21|19:32:07.655] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:07.753] RPC Daemon notified of new headers       from=7541435 to=7541436 amount=1 hash=0xe1931be301f73a2425375c3a3983011070963b7480cb44fb416351016da79d7a header sending=13.495µs log sending=631ns
[INFO] [01-21|19:32:07.754] head updated                             hash=0xe1931be301f73a2425375c3a3983011070963b7480cb44fb416351016da79d7a number=7541436
[INFO] [01-21|19:32:07.828] [NewPayload] Handling new payload        height=7541437 hash=0x9d1c7c5f64e94e4e4d7f092acf420430695c749eef8ad86b25fbaeae2b03b25c
[INFO] [01-21|19:32:07.930] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:08.036] RPC Daemon notified of new headers       from=7541436 to=7541437 amount=1 hash=0x9d1c7c5f64e94e4e4d7f092acf420430695c749eef8ad86b25fbaeae2b03b25c header sending=9.999µs log sending=240ns
[INFO] [01-21|19:32:08.036] head updated                             hash=0x9d1c7c5f64e94e4e4d7f092acf420430695c749eef8ad86b25fbaeae2b03b25c number=7541437
[INFO] [01-21|19:32:08.094] [NewPayload] Handling new payload        height=7541438 hash=0x0f5528840a11dba4a739393607a59efa0c23899c435d4016a421fc0f1a99c961
[INFO] [01-21|19:32:08.184] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:08.282] RPC Daemon notified of new headers       from=7541437 to=7541438 amount=1 hash=0x0f5528840a11dba4a739393607a59efa0c23899c435d4016a421fc0f1a99c961 header sending=15.199µs log sending=310ns
[INFO] [01-21|19:32:08.282] head updated                             hash=0x0f5528840a11dba4a739393607a59efa0c23899c435d4016a421fc0f1a99c961 number=7541438
[INFO] [01-21|19:32:08.325] [NewPayload] Handling new payload        height=7541439 hash=0x67fd3e684e61a54fbb133aace6b063ad735e3cddb7c7ea5b0907fbfa966760f9
[INFO] [01-21|19:32:08.442] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:08.550] RPC Daemon notified of new headers       from=7541438 to=7541439 amount=1 hash=0x67fd3e684e61a54fbb133aace6b063ad735e3cddb7c7ea5b0907fbfa966760f9 header sending=10.43µs log sending=330ns
[INFO] [01-21|19:32:08.550] head updated                             hash=0x67fd3e684e61a54fbb133aace6b063ad735e3cddb7c7ea5b0907fbfa966760f9 number=7541439
[INFO] [01-21|19:32:08.593] [NewPayload] Handling new payload        height=7541440 hash=0x0b70d439c8458c20d5ba5edc6dd6abc7bc1d01c9d2c869590f673fc428a03461
[INFO] [01-21|19:32:08.674] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:08.782] RPC Daemon notified of new headers       from=7541439 to=7541440 amount=1 hash=0x0b70d439c8458c20d5ba5edc6dd6abc7bc1d01c9d2c869590f673fc428a03461 header sending=13.475µs log sending=521ns
[INFO] [01-21|19:32:08.782] head updated                             hash=0x0b70d439c8458c20d5ba5edc6dd6abc7bc1d01c9d2c869590f673fc428a03461 number=7541440
[INFO] [01-21|19:32:08.836] [NewPayload] Handling new payload        height=7541441 hash=0xe58757751457bd6682ffab8c2c86d1dae4a74bf92f62df18d01b12bc84b27f16
[INFO] [01-21|19:32:08.940] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:09.051] RPC Daemon notified of new headers       from=7541440 to=7541441 amount=1 hash=0xe58757751457bd6682ffab8c2c86d1dae4a74bf92f62df18d01b12bc84b27f16 header sending=21.791µs log sending=160ns
[INFO] [01-21|19:32:09.051] head updated                             hash=0xe58757751457bd6682ffab8c2c86d1dae4a74bf92f62df18d01b12bc84b27f16 number=7541441
[INFO] [01-21|19:32:09.108] [NewPayload] Handling new payload        height=7541442 hash=0xd0754c9774aa23a528ad1fb51f625dd166496b06984f641eb261e37187233f40
[INFO] [01-21|19:32:09.184] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:09.254] RPC Daemon notified of new headers       from=7541441 to=7541442 amount=1 hash=0xd0754c9774aa23a528ad1fb51f625dd166496b06984f641eb261e37187233f40 header sending=11.371µs log sending=300ns
[INFO] [01-21|19:32:09.254] head updated                             hash=0xd0754c9774aa23a528ad1fb51f625dd166496b06984f641eb261e37187233f40 number=7541442
[INFO] [01-21|19:32:09.295] [NewPayload] Handling new payload        height=7541443 hash=0x9e21edc243ad875d87853b7c8327562df99aeff774ee50a3db59a74fd6c54874
[INFO] [01-21|19:32:09.374] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:09.468] RPC Daemon notified of new headers       from=7541442 to=7541443 amount=1 hash=0x9e21edc243ad875d87853b7c8327562df99aeff774ee50a3db59a74fd6c54874 header sending=10.039µs log sending=260ns
[INFO] [01-21|19:32:09.468] head updated                             hash=0x9e21edc243ad875d87853b7c8327562df99aeff774ee50a3db59a74fd6c54874 number=7541443
[INFO] [01-21|19:32:09.507] [NewPayload] Handling new payload        height=7541444 hash=0x3cb728e3953a3d34b6f95690ec1fee6a25ac0016e2c5213a084a5cf1727c94d5
[INFO] [01-21|19:32:09.634] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:09.767] RPC Daemon notified of new headers       from=7541443 to=7541444 amount=1 hash=0x3cb728e3953a3d34b6f95690ec1fee6a25ac0016e2c5213a084a5cf1727c94d5 header sending=10.991µs log sending=260ns
[INFO] [01-21|19:32:09.767] head updated                             hash=0x3cb728e3953a3d34b6f95690ec1fee6a25ac0016e2c5213a084a5cf1727c94d5 number=7541444
[INFO] [01-21|19:32:09.812] [NewPayload] Handling new payload        height=7541445 hash=0x5c7a69284a0b17eee8e82d7889989e8f9ec688923e3ebb7325cb822e391f1911
[INFO] [01-21|19:32:09.886] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:09.970] RPC Daemon notified of new headers       from=7541444 to=7541445 amount=1 hash=0x5c7a69284a0b17eee8e82d7889989e8f9ec688923e3ebb7325cb822e391f1911 header sending=10.781µs log sending=250ns
[INFO] [01-21|19:32:09.970] head updated                             hash=0x5c7a69284a0b17eee8e82d7889989e8f9ec688923e3ebb7325cb822e391f1911 number=7541445
[INFO] [01-21|19:32:10.022] [NewPayload] Handling new payload        height=7541446 hash=0x38ab65537bc7430b16b8da568c73afff0e9f74ebcdff6e98b3af4444cfa3c421
[INFO] [01-21|19:32:10.104] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:10.179] RPC Daemon notified of new headers       from=7541445 to=7541446 amount=1 hash=0x38ab65537bc7430b16b8da568c73afff0e9f74ebcdff6e98b3af4444cfa3c421 header sending=10.119µs log sending=240ns
[INFO] [01-21|19:32:10.179] head updated                             hash=0x38ab65537bc7430b16b8da568c73afff0e9f74ebcdff6e98b3af4444cfa3c421 number=7541446
[INFO] [01-21|19:32:10.228] [NewPayload] Handling new payload        height=7541447 hash=0xd38b4b9b9d0b111bc7c5e3d43079f01f49d6fc35e5446ece1861583622a74ec8
[INFO] [01-21|19:32:10.351] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:10.484] RPC Daemon notified of new headers       from=7541446 to=7541447 amount=1 hash=0xd38b4b9b9d0b111bc7c5e3d43079f01f49d6fc35e5446ece1861583622a74ec8 header sending=12.523µs log sending=241ns
[INFO] [01-21|19:32:10.484] head updated                             hash=0xd38b4b9b9d0b111bc7c5e3d43079f01f49d6fc35e5446ece1861583622a74ec8 number=7541447
[INFO] [01-21|19:32:10.518] [NewPayload] Handling new payload        height=7541448 hash=0xb493791bf0a12171f80a848d324f285a791ecd45547b98191f469f59b62d0bcd
[INFO] [01-21|19:32:10.561] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:10.611] RPC Daemon notified of new headers       from=7541447 to=7541448 amount=1 hash=0xb493791bf0a12171f80a848d324f285a791ecd45547b98191f469f59b62d0bcd header sending=10.71µs log sending=261ns
[INFO] [01-21|19:32:10.611] head updated                             hash=0xb493791bf0a12171f80a848d324f285a791ecd45547b98191f469f59b62d0bcd number=7541448
[INFO] [01-21|19:32:10.640] [NewPayload] Handling new payload        height=7541449 hash=0x96c967211860a8f7928f34d4946984041fbc4f106c15f5a7bff3c486b3e404b9
[INFO] [01-21|19:32:10.727] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:10.816] RPC Daemon notified of new headers       from=7541448 to=7541449 amount=1 hash=0x96c967211860a8f7928f34d4946984041fbc4f106c15f5a7bff3c486b3e404b9 header sending=9.719µs log sending=160ns
[INFO] [01-21|19:32:10.816] head updated                             hash=0x96c967211860a8f7928f34d4946984041fbc4f106c15f5a7bff3c486b3e404b9 number=7541449
[INFO] [01-21|19:32:10.852] [NewPayload] Handling new payload        height=7541450 hash=0x7558d2b81cf6016499b0707953f6ca2454fbaf94602dbc54bdc4411065df6ef3
[INFO] [01-21|19:32:10.974] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:11.091] RPC Daemon notified of new headers       from=7541449 to=7541450 amount=1 hash=0x7558d2b81cf6016499b0707953f6ca2454fbaf94602dbc54bdc4411065df6ef3 header sending=12.734µs log sending=251ns
[INFO] [01-21|19:32:11.091] head updated                             hash=0x7558d2b81cf6016499b0707953f6ca2454fbaf94602dbc54bdc4411065df6ef3 number=7541450
[INFO] [01-21|19:32:11.147] [NewPayload] Handling new payload        height=7541451 hash=0x6d902d31e11473d071dcd83c5e5eb39b9e4f0f353984c68953f50126c309d438
[INFO] [01-21|19:32:11.225] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:11.306] RPC Daemon notified of new headers       from=7541450 to=7541451 amount=1 hash=0x6d902d31e11473d071dcd83c5e5eb39b9e4f0f353984c68953f50126c309d438 header sending=9.638µs log sending=230ns
[INFO] [01-21|19:32:11.306] head updated                             hash=0x6d902d31e11473d071dcd83c5e5eb39b9e4f0f353984c68953f50126c309d438 number=7541451
[INFO] [01-21|19:32:11.355] [NewPayload] Handling new payload        height=7541452 hash=0xa5f5f5b36a0fe88f3999123d4940c25743d3e1aade781d14f77da0c0378e9258
[INFO] [01-21|19:32:11.465] [updateForkchoice] Fork choice update: flushing in-memory state (built by previous newPayload) 
[INFO] [01-21|19:32:11.582] RPC Daemon notified of new headers       from=7541451 to=7541452 amount=1 hash=0xa5f5f5b36a0fe88f3999123d4940c25743d3e1aade781d14f77da0c0378e9258 header sending=11.602µs log sending=240ns
...

@keithchew
Copy link
Author

keithchew commented Jan 22, 2025 •
edited
Loading

hmm, for some reason, I don't see this in my logs:

[INFO] [01-21|19:30:10.027] [1/12 Snapshots] download finished       time=20.000990499s

before Handling new payload starts, this could be why v2.61.0 is behaving strangely (but OK in v2.60.10).

Let me investigate further...

@luarx
Copy link

luarx commented Jan 22, 2025

This could be related with this issue #12722

@keithchew
Copy link
Author

Thanks @luarx the logs in #12722 look OK (for now), the dowloader has quite a large gap to go before reaching chain tip. Over here, even after reaching chain tip in v2.60.10, things start to turn bad when restarting with v2.61.0. perhaps they might see this issue after they have reached chain tip.

@keithchew
Copy link
Author

@antonis19 I think I found something. In my instance, I have this log:

[WARN] [01-23|01:10:22.510] [1/12 Snapshots] Some blocks are not in snapshots and not in db max_in_snapshots=7419999 min_in_db=7441000

I have tried:

integration stage_headers --reset --datadir /root/.ethereum --chain sepolia

and then started erigon (v2.60.10) and waited for it to rebuild. Once at chain tip, I restarted, but still seeing the Some blocks are not logs. However, it is happy to process new payloads fast. Then I restarted with v2.61.0, same logs above, but it processes new payloads slow.

Do you know how I can get the node to sync up snapshots and db to remove the Some blocks are not log message?

@keithchew
Copy link
Author

keithchew commented Jan 23, 2025 •
edited
Loading

Another hint I noticed when I shutdown v2.61.0:

[INFO] [01-23|01:23:16.411] Got interrupt, shutting down...
[INFO] [01-23|01:23:16.411] Got interrupt, shutting down...          sig=terminated
[INFO] [01-23|01:23:16.411] Exiting...
[INFO] [01-23|01:23:16.411] HTTP endpoint closed                     url=[::]:8545
[INFO] [01-23|01:23:16.411] HTTP endpoint closed                     url=[::]:8546
[INFO] [01-23|01:23:16.411] RPC server shutting down
[INFO] [01-23|01:23:16.411] Exiting Engine...
[INFO] [01-23|01:23:16.411] RPC server shutting down
[INFO] [01-23|01:23:16.411] RPC server shutting down
[WARN] [01-23|01:23:17.648] Could not validate block                 err="[3/7 BlockHashes] stopped"
[WARN] [01-23|01:23:18.521] [rpc] served                             conn=172.17.0.1:51506 method=engine_newPayloadV3 reqid=120 t=3.840450788s err="validateAndStorePayload: [3/7 BlockHashes] stopped"
[INFO] [01-23|01:23:19.019] Engine HTTP endpoint close               url=[::]:8553

the rpc time for validateAndStorePayload above it 3.8s! I wonder if the slowness in v2.61.0 is due to the communication between EL and CL? I will compare codebases between v2.60.10 and 2.61.0 and see if I can see anything...

@keithchew
Copy link
Author

keithchew commented Jan 23, 2025 •
edited
Loading

@antonis19

I have finally tracked it down!

Using strace/gdb, I can see a lot of DB locks, so I had a look at the diff between v2.60.10 and v2.61.0 (because of the rename from ledgerwatch to erigontech, it had 1825 file changes!!).

I tracked it down to this PR:
841733c

Reverting this made it go fast again. So it looks like p2p batch updates could be choking the DB, causing congestion and slowdown.

@AskAlexSharov coincidently, that is the PR that you included to fix the other issue I found, ie:
#12826

@keithchew keithchew mentioned this issue Jan 23, 2025
Merged
@keithchew
Copy link
Author

keithchew commented Jan 23, 2025 •
edited
Loading

@antonis19 @AskAlexSharov

Instead of reverting the whole PR 841733c, I am testing bringing back SafeNoSync from v2.60.10 on my local instances. The PR for this is here:

#13541

It is looking good. Testing on 1 x sepolia and 2 x mainnet nodes, I am not experiencing any slowness. Let me know if you want me to alter the PR to target the next release branch when that becomes ready.

@antonis19
Copy link
Member

@keithchew thanks for sharing the results of your investigation.

Just to be sure, the slowness issue occurs only on Sepolia and not on mainnet?

On my side, I've stopped my Sepolia node for a day and upon restarting it I notice it is stuck on this log:

INFO[01-23|14:17:36.297] Initialised chain configuration          config="{ChainID: 11155111, Homestead: 0, DAO: <nil>, Tangerine Whistle: 0, Spurious Dragon: 0, Byzantium: 0, Constantinople: 0, Petersburg: 0, Istanbul: 0, Muir Glacier: 0, Berlin: 0, London: 0, Arrow Glacier: <nil>, Gray Glacier: <nil>, Terminal Total Difficulty: 17000000000000000, Merge Netsplit: 1735371, Shanghai: 1677557088, Cancun: 1706655072, Prague: <nil>, Osaka: <nil>, Engine: ethash}" genesis=0x25a5cc106eea7138acab33231d7160d69cb777ee0c2c553fcddf5138993e6dd9

Did you also observe the same behavior?

Thanks for raising the PR, I will check if that indeed improves the speed.

@antonis19
Copy link
Member

@keithchew Nevermind the comment I made about the log, it was a false alarm. The node managed to catch up to the tip in a matter of a few minutes, as you can see in the logs:

erigon.log

@keithchew
Copy link
Author

keithchew commented Jan 23, 2025 •
edited
Loading

@antonis19

I am seeing this in both sepolia and mainnet (logs above).

I have my public IP published for NAT, which will increase the p2p activity on my nodes. Even to a stage of crashing erigon by exceeding the 10000 threads limit:
#12826

The PR retains the previous flags from v2.60.10, ie the DB flags for no sync, so the 2s sync will allow for write backpressure. You should not see any speed improvements, but instead, when there is a spike of write activity, this will allow the writes to be flattened/smoothed out.

For reference, here are the flags from v2.60.10:
https://github.com/erigontech/erigon/blob/3afee08bfff043a731485e0a92dd8650823d8884/p2p/enode/nodedb.go#L127C1-L128C31

@yperbasis yperbasis added this to the 2.61.1-fixes milestone Jan 23, 2025
AskAlexSharov pushed a commit that referenced this issue Jan 24, 2025
@keithchew
revert SafeNoSync (#13541)
1de3742 
Discussion in:
#13457

This PR brings back SafeNoSync from v2.60.10 to prevent DB from being
congested and slowdown.
@AskAlexSharov
Copy link
Collaborator

AskAlexSharov commented Jan 24, 2025 •
edited
Loading

when there is a spike of write activity, this will allow the writes to be flattened/smoothed out. - i'm not agree with this explanation - because nodedb doesn't use .BeginRw/.Update - it using .Batch which making unlimited amount of parallel updates in 1 rwtx commit.

But anyway: if it helps in your case - maybe there is another explanation - let's accept your PR (because it was introduced only in recent release) and we will investigate why it impacting performance. Thank you for finding. I also port it to E3: #13545

@AskAlexSharov AskAlexSharov mentioned this issue Jan 24, 2025
Merged
@keithchew
Copy link
Author

Thanks @AskAlexSharov for the approval and merge.

Here is a page with the flags explanation:
https://docs.rs/libmdbx/latest/libmdbx/enum.SyncMode.html

In particular:

Depending on the platform and hardware, with SyncMode::SafeNoSync you may get a multiple increase of write performance, even 10 times or more.

The default is to flush to disk immediately, which can be costly on high write activity, SafeNoSync instead will let the OS perform the write in an async flush fashion.

@AskAlexSharov AskAlexSharov mentioned this issue Jan 24, 2025
Closed
AskAlexSharov added a commit that referenced this issue Jan 24, 2025
@AskAlexSharov
nodedb: use SafeNoSync (#13545)
381c069 
port of #13457
@keithchew keithchew mentioned this issue Jan 27, 2025
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@antonis19 antonis19

Labels
performance
Projects
None yet
Milestone
2.61.1-fixes
Development

No branches or pull requests
5 participants
@keithchew @antonis19 @luarx @yperbasis @AskAlexSharov