investigation(lib/runtime): block execution slows down severally after 0.9.25

[EclesioMeloJunior]

Describe the bug

• Gossamer slow down its sync speed severally after reaching the 11m height, after looking through the logs I've noticed that after the 0.9.25 runtime upgrade the sync speed was around 0.10 bps and before was around ~10 bps

[EclesioMeloJunior]

This investigation led to the creating of a script to retrieve chains of blocks to measure and narrow down the block execution bottleneck: #3945

[EclesioMeloJunior]

Investigation

The previous runtime version (0.9.23) does not have the transactions feature enabled so the runtime could retrieve informations directly from the in-memory trie quickly, after the runtime upgrade to 0.9.25 the transactions feature was enabled and a particular host function (ext_storage_next_key_version_1) that was taking 0ms to execute to take up to 4000ms to execute and that leads Gossamer to slow down the execution time.

Runtime upgrade

The runtime upgrade to version 0.9.25 happens on block #11409279 (https://westend.subscan.io/block/11409279) and the previous runtime that was being used was 0.9.23 (Westend chain does not have the runtime version 0.9.24). At that previous version the start_transaction host function was not being called and after the upgrade to 0.9.25 the nested transactions feature was enabled.
ref: Runtime release notes: https://github.com/paritytech/polkadot/releases/tag/v0.9.25
ref: Specific PR: paritytech/substrate#11431

Comparision

Using the scripts to retrieve the state and blocks I was able to compare the time that Gossamer take to exec 480 blocks before and after the runtime upgrade, and here is the results (on a M1 Apple Silicon)

Before:
took 500.14 seconds
mean 1.04 seconds

After:
took 1162.43 seconds
mean 2.43 seconds

Also I was print to the stdout every host function that takes more than 1ms to complete. I notice that on version 0.9.23 the function ext_storage_next_key_version_1 was not even being printed while after the upgrade it was being printed and also was taking between 1000ms to 4004ms to complete.
on 0.9.23

on 0.9.25

Explanation

So basically this is because the host function ext_storage_next_key_version_1 when called inside an ongoing, the storage will retrieve all the keys present in the memory key plus the keys in the storage diff to perform find the next key