Add debugging info for StorageWeightReclaim

[Moliholy]

When inspecting the logs we often encounter the following message:

Benchmarked storage weight smaller than consumed storage weight. benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}

However, it is very hard to guess which call is causing the issue.

With the changes proposed in this PR, information about the call is provided so that we can easily identify the source of the problem without further delay, and this way work more efficiently in solving the issue.

[bkchr]

Cloning the entire call is a little bit too expensive.

[Moliholy]

What about adding the GetCallMetadata to T::RuntimeCall and debugging the corresponding CallMetadata? We'd miss the call arguments, but at least it already points in the right direction. In that case we could also add the extrinsic number, as you suggested.

[bkchr]

You can just see the transaction with all its arguments in the block explorer. I don't see any need to log them.

[Moliholy]

Alright, I just pushed the changes as per your suggestion.

[bkchr]

Instead of the call we could print the frame_system::Pallet::extrinsic_count(). Then you have the index of the transaction.

[Moliholy]

I find that less straightforward. You might check the logs at a later point in time, when the state could, for instance, have been pruned. In that scenario you wouldn't be able to retrieve the block (after taking the time to inspect the block in PolkadotJS).

Also, it'd take more time to figure out which extrinsic is. My purpose is to increase as much as possible developer productivity, and the most go-to way I found is this one.

That being said, I understand passing the call and printing its debug information has a performance penalty. Still, I think it'd be better off with the proposed changes, as a small performance penalty could potentially save hours of debugging and improve overall productivity.

Still... if you think otherwise, I'll change it as per your suggestion. But I'd prefer to softly push for the proposed solution, as in my opinion it represents the best trade-off.

EDIT: besides, looking at the implementation of extrinsic_count():

/// Gets extrinsics count.
pub fn extrinsic_count() -> u32 {
    ExtrinsicCount::<T>::get().unwrap_or_default()
}

It does access an storage item. Wouldn't that introduce a higher performance penalty than the proposed solution?

[bkchr]

You might check the logs at a later point in time, when the state could, for instance, have been pruned. In that scenario you wouldn't be able to retrieve the block (after taking the time to inspect the block in PolkadotJS).

State pruning is different to blocks pruning. Block pruning needs to be enabled directly.

We don't have that much memory and wasting the memory just for some debugging which is only required in 0.01% of the cases is not a good idea.

It does access an storage item. Wouldn't that introduce a higher performance penalty than the proposed solution?

The storage item will only be accessed when the log level is enabled . For the release build on chain logging should be disabled any way. Thus, this should not lead to any performance impacts on production networks.

[Moliholy]

some debugging which is only required in 0.01% of the cases is not a good idea.

I'd say an incorrectly benchmarked custom pallet in a parachain is much more common than that. Still, I implemented it as per your suggestion.

[bkchr]

Just take all the nodes into account that need to execute the block and that are not used for debugging. Debugging is a small fraction and you get the index of the transaction and that gives you all the information for free.

[skunert]

@bkchr please double check, but to me it looks like ExtrinsicCount is not updated on the fly, but only at the end of the block here (also in line with the docs):

polkadot-sdk/substrate/frame/system/src/lib.rs

Lines 2048 to 2054 in fcea4ff

	pub fn note_finished_extrinsics() {
	let extrinsic_index: u32 =
	storage::unhashed::take(well_known_keys::EXTRINSIC_INDEX).unwrap_or_default();
	ExtrinsicCount::<T>::put(extrinsic_index);
	ExecutionPhase::<T>::put(Phase::Finalization);
	}

I think we should use extrinsic_index() instead which seems to be updated after every xt.

polkadot-sdk/substrate/frame/system/src/lib.rs

Line 2042 in fcea4ff

storage::unhashed::put(well_known_keys::EXTRINSIC_INDEX, &next_extrinsic_index);

[bkchr]

🙈

[paritytech-cmd-bot-polkadot-sdk]

Successfully created backport PR for stable2407:

• [stable2407] Backport #5594 #5766

[paritytech-cmd-bot-polkadot-sdk]

Successfully created backport PR for stable2409:

• [stable2409] Backport #5594 #5767