From c3a6bd6c2ae3b9a9c34dbd155eb1d790053ff5d8 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Bastian=20K=C3=B6cher?= <git@kchr.de>
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<Call: Encode + GetDispatchInfo, Extra: Encode> 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<T> {
 	/// 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::<T>::get(),
+		);
+
+		log::trace!(
+			target: LOG_TARGET,
+			"Used block length: {:?}",
+			Pallet::<T>::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)]