v2.61.0 slow to sync on sepolia

[keithchew]

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]

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]

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]

@keithchew can you provide all the flags you used?

[keithchew]

@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]

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]

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

[keithchew]

@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]

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

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