From eeb5dcc08214c2cd04f3dde9603c681491f18b0e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Tue, 24 Oct 2023 00:16:23 +0200 Subject: [PATCH 1/3] `CheckWeight`: Add more logging This adds more logging to `CheckWeight` to get a better understanding why a transaction exhausts resources. --- substrate/frame/support/src/dispatch.rs | 2 +- .../system/src/extensions/check_weight.rs | 66 ++++++++++++++++--- substrate/primitives/weights/src/weight_v2.rs | 2 +- 3 files changed, 58 insertions(+), 12 deletions(-) diff --git a/substrate/frame/support/src/dispatch.rs b/substrate/frame/support/src/dispatch.rs index 75e94827fea8..e6a090ebcae8 100644 --- a/substrate/frame/support/src/dispatch.rs +++ b/substrate/frame/support/src/dispatch.rs @@ -390,7 +390,7 @@ impl GetDispatchInfo } /// A struct holding value for each `DispatchClass`. -#[derive(Clone, Eq, PartialEq, Default, RuntimeDebug, Encode, Decode, TypeInfo, MaxEncodedLen)] +#[derive(Clone, Eq, PartialEq, Default, Debug, Encode, Decode, TypeInfo, MaxEncodedLen)] pub struct PerDispatchClass { /// Value for `Normal` extrinsics. normal: T, diff --git a/substrate/frame/system/src/extensions/check_weight.rs b/substrate/frame/system/src/extensions/check_weight.rs index 1030c8daf7b0..7d103a2c109d 100644 --- a/substrate/frame/system/src/extensions/check_weight.rs +++ b/substrate/frame/system/src/extensions/check_weight.rs @@ -15,7 +15,7 @@ // See the License for the specific language governing permissions and // limitations under the License. -use crate::{limits::BlockWeights, Config, Pallet}; +use crate::{limits::BlockWeights, Config, Pallet, LOG_TARGET}; use codec::{Decode, Encode}; use frame_support::{ dispatch::{DispatchInfo, PostDispatchInfo}, @@ -50,8 +50,18 @@ where ) -> Result<(), TransactionValidityError> { let max = T::BlockWeights::get().get(info.class).max_extrinsic; match max { - Some(max) if info.weight.any_gt(max) => - Err(InvalidTransaction::ExhaustsResources.into()), + Some(max) if info.weight.any_gt(max) => { + log::debug!( + target: LOG_TARGET, + "Extrinsic weight ({}, {}) is greater than the max extrinsic weight ({}, {})", + info.weight.ref_time(), + info.weight.proof_size(), + max.ref_time(), + max.proof_size(), + ); + + Err(InvalidTransaction::ExhaustsResources.into()) + }, _ => Ok(()), } } @@ -79,6 +89,13 @@ where let added_len = len as u32; let next_len = current_len.saturating_add(added_len); if next_len > *length_limit.max.get(info.class) { + log::debug!( + target: LOG_TARGET, + "Exceeded block length limit: {} > {}", + next_len, + length_limit.max.get(info.class), + ); + Err(InvalidTransaction::ExhaustsResources.into()) } else { Ok(next_len) @@ -137,17 +154,28 @@ where if limit_per_class.max_total.is_none() && limit_per_class.reserved.is_none() { all_weight.accrue(extrinsic_weight, info.class) } else { - all_weight - .checked_accrue(extrinsic_weight, info.class) - .map_err(|_| InvalidTransaction::ExhaustsResources)?; + all_weight.checked_accrue(extrinsic_weight, info.class).map_err(|_| { + log::debug!( + target: LOG_TARGET, + "All weight checked add overflow.", + ); + + InvalidTransaction::ExhaustsResources + })?; } let per_class = *all_weight.get(info.class); // Check if we don't exceed per-class allowance match limit_per_class.max_total { - Some(max) if per_class.any_gt(max) => - return Err(InvalidTransaction::ExhaustsResources.into()), + Some(max) if per_class.any_gt(max) => { + log::debug!( + target: LOG_TARGET, + "Exceeded the per-class allowance.", + ); + + return Err(InvalidTransaction::ExhaustsResources.into()) + }, // There is no `max_total` limit (`None`), // or we are below the limit. _ => {}, @@ -158,8 +186,14 @@ where if all_weight.total().any_gt(maximum_weight.max_block) { match limit_per_class.reserved { // We are over the limit in reserved pool. - Some(reserved) if per_class.any_gt(reserved) => - return Err(InvalidTransaction::ExhaustsResources.into()), + Some(reserved) if per_class.any_gt(reserved) => { + log::debug!( + target: LOG_TARGET, + "Total block weight is exceeded.", + ); + + return Err(InvalidTransaction::ExhaustsResources.into()) + }, // There is either no limit in reserved pool (`None`), // or we are below the limit. _ => {}, @@ -233,6 +267,18 @@ where }) } + log::debug!( + target: LOG_TARGET, + "Used block weight: {:?}", + crate::BlockWeight::::get(), + ); + + log::debug!( + target: LOG_TARGET, + "Used block length: {:?}", + Pallet::::all_extrinsics_len(), + ); + Ok(()) } } diff --git a/substrate/primitives/weights/src/weight_v2.rs b/substrate/primitives/weights/src/weight_v2.rs index 3946cfe42c8d..b8265d551d9c 100644 --- a/substrate/primitives/weights/src/weight_v2.rs +++ b/substrate/primitives/weights/src/weight_v2.rs @@ -23,7 +23,7 @@ use sp_debug_derive::RuntimeDebug; use super::*; #[derive( - Encode, Decode, MaxEncodedLen, TypeInfo, Eq, PartialEq, Copy, Clone, RuntimeDebug, Default, + Encode, Decode, MaxEncodedLen, TypeInfo, Eq, PartialEq, Copy, Clone, Debug, Default, )] #[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] pub struct Weight { From 0f2b0134cecb619213b4cda503787b3148c124d8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Tue, 24 Oct 2023 11:04:46 +0200 Subject: [PATCH 2/3] Fix warning and review comments --- .../frame/system/src/extensions/check_weight.rs | 12 +++++------- substrate/primitives/weights/src/weight_v2.rs | 1 - 2 files changed, 5 insertions(+), 8 deletions(-) diff --git a/substrate/frame/system/src/extensions/check_weight.rs b/substrate/frame/system/src/extensions/check_weight.rs index 7d103a2c109d..70d1e7563327 100644 --- a/substrate/frame/system/src/extensions/check_weight.rs +++ b/substrate/frame/system/src/extensions/check_weight.rs @@ -53,11 +53,9 @@ where Some(max) if info.weight.any_gt(max) => { log::debug!( target: LOG_TARGET, - "Extrinsic weight ({}, {}) is greater than the max extrinsic weight ({}, {})", - info.weight.ref_time(), - info.weight.proof_size(), - max.ref_time(), - max.proof_size(), + "Extrinsic {} is greater than the max extrinsic {}", + info.weight, + max, ); Err(InvalidTransaction::ExhaustsResources.into()) @@ -267,13 +265,13 @@ where }) } - log::debug!( + log::trace!( target: LOG_TARGET, "Used block weight: {:?}", crate::BlockWeight::::get(), ); - log::debug!( + log::trace!( target: LOG_TARGET, "Used block length: {:?}", Pallet::::all_extrinsics_len(), diff --git a/substrate/primitives/weights/src/weight_v2.rs b/substrate/primitives/weights/src/weight_v2.rs index b8265d551d9c..a2abf6efb7f3 100644 --- a/substrate/primitives/weights/src/weight_v2.rs +++ b/substrate/primitives/weights/src/weight_v2.rs @@ -18,7 +18,6 @@ use codec::{Decode, Encode, MaxEncodedLen}; use core::ops::{Add, AddAssign, Div, Mul, Sub, SubAssign}; use sp_arithmetic::traits::{Bounded, CheckedAdd, CheckedSub, Zero}; -use sp_debug_derive::RuntimeDebug; use super::*; From d286ff86208b9d8ea3332ab33f5904a98d3a5b62 Mon Sep 17 00:00:00 2001 From: command-bot <> Date: Tue, 24 Oct 2023 09:11:35 +0000 Subject: [PATCH 3/3] ".git/.scripts/commands/fmt/fmt.sh" --- substrate/primitives/weights/src/weight_v2.rs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/substrate/primitives/weights/src/weight_v2.rs b/substrate/primitives/weights/src/weight_v2.rs index a2abf6efb7f3..d692aaff8f5a 100644 --- a/substrate/primitives/weights/src/weight_v2.rs +++ b/substrate/primitives/weights/src/weight_v2.rs @@ -21,9 +21,7 @@ use sp_arithmetic::traits::{Bounded, CheckedAdd, CheckedSub, Zero}; use super::*; -#[derive( - Encode, Decode, MaxEncodedLen, TypeInfo, Eq, PartialEq, Copy, Clone, Debug, Default, -)] +#[derive(Encode, Decode, MaxEncodedLen, TypeInfo, Eq, PartialEq, Copy, Clone, Debug, Default)] #[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] pub struct Weight { #[codec(compact)]