Slowness of block generation after long run

[shuse2]

Expected behavior

Without load, block generation and execution should not change drastically

Actual behavior

Measuring time of req/res of ABI client

console.time(`${method}-${reqID}`);
await this._dealer.send([encodedRequest]);
const response = defer();
this._globalID += BigInt(1);
if (this._globalID >= MAX_UINT64) {
   this._globalID = BigInt(0);
}
const resp = await Promise.race([
    response.promise,
    timeout(DEFAULT_TIMEOUT, `Response not received in ${DEFAULT_TIMEOUT}ms`),
]);
console.timeEnd(`${method}-${reqID}`);

and on the ABI handler, measure actual execution of each method, there are quite difference after executing longer. (it disappears with restart)

clear-24113: 0.238ms
2023-02-22T17:27:16.674Z INFO  engine 43919 [id=214a9ba7b83974a1492e57b4cd426619702ddd63360af009815f3d4fde6c518d height=10067 generatorAddress=lsk2jjg9ob4qh7jokpdbf7hjgqftkaq4b2925f422] Generated new block
initStateMachine-24114: 0.53ms
verifyAssets: 0.032ms
verifyAssets-24115: 0.444ms
beforeExecuteBlock: 0.401ms
beforeTransactionsExecute-24116: 0.784ms
afterTransactionsExecute: 1.376ms
afterTransactionsExecute-24117: 1.666ms
commit: 0.901ms
commit-24118: 1.123ms
clear-24119: 617.428ms
finalize-24120: 2.429ms
2023-02-22T17:27:18.249Z INFO  engine 43919 [id=214a9ba7b83974a1492e57b4cd426619702ddd63360af009815f3d4fde6c518d height=10067 generator=lsk2jjg9ob4qh7jokpdbf7hjgqftkaq4b2925f422 numberOfTransactions=0 numberOfAssets=1 numberOfEvents=2] Block executed
2023-02-22T17:27:18.249Z INFO  engine 43919 [status=success event=chain_newBlock] IPCServer published event
2023-02-22T17:27:18.249Z INFO  engine 43919 [status=success event=network_newBlock] IPCServer published event
2023-02-22T17:27:18.249Z INFO  engine 43919 [status=success event=chain_newBlock] WSServer published event
2023-02-22T17:27:18.249Z INFO  engine 43919 [status=success event=network_newBlock] WSServer published event
2023-02-22T17:27:19.863Z INFO  engine 43919 starting to generate a block
initStateMachine-24121: 0.837ms
2023-02-22T17:27:26.237Z INFO  engine 43919 inserting asset
insertAssets: 0.253ms
insertAssets-24122: 0.621ms
2023-02-22T17:27:26.238Z INFO  engine 43919 bft execute
2023-02-22T17:27:26.240Z INFO  engine 43919 beforeTransactionsExecute
beforeExecuteBlock: 0.423ms
beforeTransactionsExecute-24123: 3.309ms
2023-02-22T17:27:26.243Z INFO  engine 43919 tx execute
2023-02-22T17:27:26.243Z INFO  engine 43919 afterTransactionsExecute
afterTransactionsExecute: 1.543ms
afterTransactionsExecute-24124: 2.561ms
2023-02-22T17:27:26.246Z INFO  engine 43919 state store finalize
2023-02-22T17:27:26.246Z INFO  engine 43919 event root update
2023-02-22T17:27:26.247Z INFO  engine 43919 state root commit
commit: 0.43ms
commit-24125: 5.06ms
2023-02-22T17:27:26.253Z INFO  engine 43919 sign block
2023-02-22T17:27:26.253Z INFO  engine 43919 generatorstore finalize
2023-02-22T17:27:26.253Z INFO  engine 43919 generatorstore write
clear-24126: 0.32ms
2023-02-22T17:27:26.254Z INFO  engine 43919 [id=4de83319b4e1134df4489182c068b1eaa68b60ca9ab88adf519a4b34044e5bd4 height=10068 generatorAddress=lskfok9nevnkj8pzh8nr6rtmrtn4zmrp9g66ygbqg] Generated new block
initStateMachine-24127: 0.285ms
verifyAssets: 0.032ms
verifyAssets-24128: 0.237ms
beforeExecuteBlock: 0.338ms
beforeTransactionsExecute-24129: 3.204s
afterTransactionsExecute: 1.406ms
afterTransactionsExecute-24130: 3.172s
commit: 0.571ms
commit-24131: 3.189s
clear-24132: 3.192s
2023-02-22T17:27:39.989Z INFO  engine 43919 [id=4de83319b4e1134df4489182c068b1eaa68b60ca9ab88adf519a4b34044e5bd4 height=10068 generator=lskfok9nevnkj8pzh8nr6rtmrtn4zmrp9g66ygbqg numberOfTransactions=0 numberOfAssets=1 numberOfEvents=1] Block executed
2023-02-22T17:27:39.990Z INFO  engine 43919 [status=success event=chain_newBlock] IPCServer published event
2023-02-22T17:27:39.990Z INFO  engine 43919 [status=success event=network_newBlock] IPCServer published event
2023-02-22T17:27:39.990Z INFO  engine 43919 [status=success event=chain_newBlock] WSServer published event
2023-02-22T17:27:39.990Z INFO  engine 43919 [status=success event=network_newBlock] WSServer published event
2023-02-22T17:27:42.205Z INFO  engine 43919 Skipping forging to wait for last block
2023-02-22T17:27:43.793Z INFO  engine 43919 starting to generate a block
initStateMachine-24133: 1.596s
2023-02-22T17:27:51.858Z INFO  engine 43919 inserting asset
insertAssets: 0.278ms
insertAssets-24134: 3.222s
2023-02-22T17:27:55.081Z INFO  engine 43919 bft execute
2023-02-22T17:27:56.048Z INFO  engine 43919 beforeTransactionsExecute
beforeExecuteBlock: 0.464ms
beforeTransactionsExecute-24135: 2.294s
2023-02-22T17:27:58.341Z INFO  engine 43919 tx execute
2023-02-22T17:27:58.341Z INFO  engine 43919 afterTransactionsExecute
afterTransactionsExecute: 1.666ms
afterTransactionsExecute-24136: 3.235s
2023-02-22T17:28:01.577Z INFO  engine 43919 state store finalize
2023-02-22T17:28:01.577Z INFO  engine 43919 event root update
2023-02-22T17:28:01.578Z INFO  engine 43919 state root commit
commit: 0.602ms
commit-24137: 3.262s
2023-02-22T17:28:04.841Z INFO  engine 43919 sign block
2023-02-22T17:28:04.841Z INFO  engine 43919 generatorstore finalize
2023-02-22T17:28:04.841Z INFO  engine 43919 generatorstore write

Steps to reproduce

• Run a node with 2s block time (just to see fast)
• Wait for around 15k req ID for ABI communication

Which version(s) does this affect? (Environment, OS, etc...)

Development

[shuse2]

this issue might be resolved by https://github.com/LiskHQ/lisk-sdk/pull/8269