search

skalenetwork / skaled

Running more than 20 production blockchains, SKALED is Ethereum-compatible, high performance C++ Proof-of-Stake client, tools and libraries. Uses SKALE consensus as a blockchain consensus core. Includes dynamic Oracle. Implements file storage and retrieval as an EVM extension.
https://skale.network
GNU General Public License v3.0
88 stars 41 forks source link

"Performance warning: 4.3 s execution time for eth_getBlockByNumber" warning on indexer node after exhausting all RSS on instance. #1981

Open oleksandrSydorenkoJ opened 2 months ago

oleksandrSydorenkoJ commented 2 months ago

Describe the bug The indexer node continuously catches up with new blocks, and on slower instances, this prolonged process slows Skaled's JSON-RPC server.

Preconditions Whitelisted IP for Instance with 4GB RSS, 2 cores The long-turn load tests of token transfer with 100k gas usage

Versions: skalenetwork/schain:3.19.1

To Reproduce

  1. Run indexer node from 0 block
  2. Send eth_getBlockByNumber("latest") in a loop
  3. Run load tests on the core nodes (at least 300 transactions token transfers per block)
  4. Wait for 6 days
  5. Send eth_getBlockByNumber on the indexer endpoint

Expected behavior The "eth_getBlockByNumber" call should be processed in less than 1 second

Actual state After exhausting all RSS on the instance (4GB), Skaled's JSON-RPC server is slow down and throws the "Performance warning" logs. Indexer node is behind core node by 30k blocks

2024-09-09 11:15:59.099509   Performance warning: 1.545505 seconds execution time for eth_getBlockByNumber call with id=1 when called from origin http://127.0.0.1:39738 through server with index=0
2024-09-09 11:15:59.099912   SWT:4449:BFT:4513
2024-09-09 11:15:59.099934   TQBYTES:CTQ:0:FTQ:0:TQSIZE:CTQ:0:FTQ:0
[2024-09-09 11:15:59.102] [8:main] [info] 1496491:BLOCK_COMMITED: PRPSR:13:BID: 1496492:ROOT:12390051706433997174657264043132457667126472190155056832213590207262755263903:HASH:af0d112e:BLOCK_TXS:160:DMSG:0:TPRPS:413:MPRPS:0:RPRPS:0:TXS:157075:TXLS:413:MGS:0:INSTS:0:BPS:0:HDRS:2:SOCK:1:FDS:3955:PRT:0:BTA:110329256:BSA:0:TPS:0:LWT:0:LRT:0:LWC:46930:LRC:46536:STAMP:1725827128.756
2024-09-09 11:15:59.239174   Block sealed #1496492 (#2c3b1289…)
2024-09-09 11:15:59.239223   Block stats:BN:1496491:BTS:1725827127:TXS:480:HDRS:12:LOGS:8284:SENGS:1:TXRS:8244:BLCKS:3:ACCS:199:BQS:1:BDS:59:TSS:0:UTX:0:VTX:0:CMM:9100111:KDS:31
2024-09-09 11:15:59.239902   Block 1496492 DB usage is 222753. Piece DB usage is 226853169 bytes
2024-09-09 11:16:05.126912   Performance warning: 4.059041 seconds execution time for eth_getBlockByNumber call with id=741 when called from origin http://1.1.1.1:53160 through server with index=0
2024-09-09 11:16:05.657774   Performance warning: 6.267574 seconds execution time for eth_blockNumber call with id=1 when called from origin http://127.0.0.1:39758 through server with index=0
2024-09-09 11:16:05.659372   SWT:6491:BFT:6559
2024-09-09 11:16:05.659403   TQBYTES:CTQ:0:FTQ:0:TQSIZE:CTQ:0:FTQ:0
[2024-09-09 11:16:05.662] [8:main] [info] 1496492:BLOCK_COMMITED: PRPSR:14:BID: 1496493:ROOT:12390051706433997174657264043132457667126472190155056832213590207262755263903:HASH:38830abc:BLOCK_TXS:822:DMSG:0:TPRPS:413:MPRPS:0:RPRPS:0:TXS:157075:TXLS:413:MGS:0:INSTS:0:BPS:0:HDRS:2:SOCK:1:FDS:3955:PRT:0:BTA:110322204:BSA:0:TPS:0:LWT:0:LRT:0:LWC:46933:LRC:46541:STAMP:1725827129.931
2024-09-09 11:16:06.885109   Block sealed #1496493 (#6ef73046…)
2024-09-09 11:16:06.885167   Block stats:BN:1496492:BTS:1725827128:TXS:2466:HDRS:12:LOGS:9768:SENGS:1:TXRS:9728:BLCKS:3:ACCS:199:BQS:1:BDS:60:TSS:0:UTX:0:VTX:0:CMM:9302742:KDS:31
2024-09-09 11:16:06.888417   Block 1496493 DB usage is 1141508. Piece DB usage is 227994677 bytes
2024-09-09 11:16:11.314201   SWT:5582:BFT:5654
...
2024-09-09 11:16:21.307435   Block stats:BN:1496495:BTS:1725827134:TXS:1014:HDRS:12:LOGS:10257:SENGS:1:TXRS:10217:BLCKS:3:ACCS:199:BQS:1:BDS:62:TSS:0:UTX:0:VTX:0:CMM:10846313:KDS:31
2024-09-09 11:16:23.294857   Performance warning: 1.449030 seconds execution time for eth_getBlockByNumber call with id=747 when called from origin http://1.1.1.1:53160 through server with index=0
2024-09-09 11:16:23.294870   Block 1496496 DB usage is 469724. Piece DB usage is 229347372 bytes
2024-09-09 11:16:27.806283   Performance warning: 4.369296 seconds execution time for eth_getBlockByNumber call with id=748 when called from origin http://1.1.1.1:53160 through server with index=0
oleksandrSydorenkoJ commented 2 months ago 
> eth.syncing
{
  currentBlock: 1497073,
  healedBytecodeBytes: 0,
  healedBytecodes: 0,
  healedTrienodeBytes: 0,
  healedTrienodes: 0,
  healingBytecode: 0,
  healingTrienodes: 0,
  highestBlock: 1523128,
  startingBlock: 1497001,
  syncedAccountBytes: 0,
  syncedAccounts: 0,
  syncedBytecodeBytes: 0,
  syncedBytecodes: 0,
  syncedStorage: 0,
  syncedStorageBytes: 0,
  txIndexFinishedBlocks: 0,
  txIndexRemainingBlocks: 0
}
PolinaKiporenko commented 2 months ago

Could be fixed by https://github.com/skalenetwork/skaled/issues/1545