From c3a6bd6c2ae3b9a9c34dbd155eb1d790053ff5d8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Tue, 24 Oct 2023 11:55:46 +0200 Subject: [PATCH] `CheckWeight`: Add more logging (#1996) 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 | 64 ++++++++++++++++--- substrate/primitives/weights/src/weight_v2.rs | 5 +- 3 files changed, 56 insertions(+), 15 deletions(-) diff --git a/substrate/frame/support/src/dispatch.rs b/substrate/frame/support/src/dispatch.rs index 75e94827fea8a..e6a090ebcae8a 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 1030c8daf7b04..70d1e75633278 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,16 @@ 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 {} is greater than the max extrinsic {}", + info.weight, + max, + ); + + Err(InvalidTransaction::ExhaustsResources.into()) + }, _ => Ok(()), } } @@ -79,6 +87,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 +152,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 +184,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 +265,18 @@ where }) } + log::trace!( + target: LOG_TARGET, + "Used block weight: {:?}", + crate::BlockWeight::::get(), + ); + + log::trace!( + 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 3946cfe42c8d0..d692aaff8f5ab 100644 --- a/substrate/primitives/weights/src/weight_v2.rs +++ b/substrate/primitives/weights/src/weight_v2.rs @@ -18,13 +18,10 @@ 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::*; -#[derive( - Encode, Decode, MaxEncodedLen, TypeInfo, Eq, PartialEq, Copy, Clone, RuntimeDebug, Default, -)] +#[derive(Encode, Decode, MaxEncodedLen, TypeInfo, Eq, PartialEq, Copy, Clone, Debug, Default)] #[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] pub struct Weight { #[codec(compact)]