From c6c26e6ec95083b47762e9516e1306453099f03a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jose=CC=81=20Molina?= Date: Wed, 4 Sep 2024 20:17:58 +0200 Subject: [PATCH 1/5] Add debugging info for StorageWeightReclaim --- .../storage-weight-reclaim/src/lib.rs | 38 +++++++++---------- 1 file changed, 19 insertions(+), 19 deletions(-) diff --git a/cumulus/primitives/storage-weight-reclaim/src/lib.rs b/cumulus/primitives/storage-weight-reclaim/src/lib.rs index a557e881e26b..c99fb9575ae1 100644 --- a/cumulus/primitives/storage-weight-reclaim/src/lib.rs +++ b/cumulus/primitives/storage-weight-reclaim/src/lib.rs @@ -128,7 +128,7 @@ where type AccountId = T::AccountId; type Call = T::RuntimeCall; type AdditionalSigned = (); - type Pre = Option; + type Pre = (Option, Self::Call); fn additional_signed( &self, @@ -140,11 +140,11 @@ where fn pre_dispatch( self, _who: &Self::AccountId, - _call: &Self::Call, + call: &Self::Call, _info: &sp_runtime::traits::DispatchInfoOf, _len: usize, ) -> Result { - Ok(get_proof_size()) + Ok((get_proof_size(), call.clone())) } fn post_dispatch( @@ -154,7 +154,7 @@ where _len: usize, _result: &DispatchResult, ) -> Result<(), TransactionValidityError> { - let Some(Some(pre_dispatch_proof_size)) = pre else { + let Some((Some(pre_dispatch_proof_size), call)) = pre else { return Ok(()); }; @@ -183,13 +183,13 @@ where if consumed_weight > benchmarked_weight { log::error!( target: LOG_TARGET, - "Benchmarked storage weight smaller than consumed storage weight. benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}" + "Benchmarked storage weight smaller than consumed storage weight. call: {call:?} benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}" ); current.accrue(Weight::from_parts(0, storage_size_diff), info.class) } else { log::trace!( target: LOG_TARGET, - "Reclaiming storage weight. benchmarked: {benchmarked_weight}, consumed: {consumed_weight} unspent: {unspent}" + "Reclaiming storage weight. call: {call:?} benchmarked: {benchmarked_weight}, consumed: {consumed_weight} unspent: {unspent}" ); current.reduce(Weight::from_parts(0, storage_size_diff), info.class) } @@ -293,7 +293,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(0)); + assert_eq!(pre, (Some(0), CALL.clone())); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); // We expect a refund of 400 @@ -332,7 +332,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(0)); + assert_eq!(pre, (Some(0), CALL.clone())); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); // We expect an accrue of 1 @@ -368,7 +368,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(1000)); + assert_eq!(pre, (Some(1000), CALL.clone())); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); assert_ok!(StorageWeightReclaim::::post_dispatch( @@ -404,7 +404,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(175)); + assert_eq!(pre, (Some(175), CALL.clone())); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); @@ -442,7 +442,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, None); + assert_eq!(pre, (None, CALL.clone())); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); assert_ok!(StorageWeightReclaim::::post_dispatch( @@ -473,7 +473,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(100)); + assert_eq!(pre, (Some(100), CALL.clone())); // We expect no refund assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); @@ -505,7 +505,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(0)); + assert_eq!(pre, (Some(0), CALL.clone())); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); assert_ok!(StorageWeightReclaim::::post_dispatch( @@ -537,7 +537,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(300)); + assert_eq!(pre, (Some(300), CALL.clone())); // Refund 500 unspent weight according to `post_info`, total weight is now 1650 assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); @@ -576,7 +576,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(100)); + assert_eq!(pre, (Some(100), CALL.clone())); // The `CheckWeight` extension will refund `actual_weight` from `PostDispatchInfo` // we always need to call `post_dispatch` to verify that they interoperate correctly. @@ -615,7 +615,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(100)); + assert_eq!(pre, (Some(100), CALL.clone())); // The `CheckWeight` extension will refund `actual_weight` from `PostDispatchInfo` // we always need to call `post_dispatch` to verify that they interoperate correctly. @@ -660,7 +660,7 @@ mod tests { .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); // Should return `setup_test_externalities` proof recorder value: 100. - assert_eq!(pre, Some(0)); + assert_eq!(pre, (Some(0), CALL.clone())); // The `CheckWeight` extension will refund `actual_weight` from `PostDispatchInfo` // we always need to call `post_dispatch` to verify that they interoperate correctly. @@ -705,7 +705,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(100)); + assert_eq!(pre, (Some(100), CALL.clone())); // This refunds 100 - 50(unspent), total weight is now 1400 assert_ok!(StorageWeightReclaim::::post_dispatch( @@ -746,7 +746,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, Some(100)); + assert_eq!(pre, (Some(100), CALL.clone())); // Adds additional 150 weight recorded assert_ok!(StorageWeightReclaim::::post_dispatch( From db6628eb02f5898a513bb75021772d9326d7164d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jose=CC=81=20Molina?= Date: Wed, 4 Sep 2024 20:26:02 +0200 Subject: [PATCH 2/5] Add prdoc --- prdoc/pr_5594.prdoc | 13 +++++++++++++ 1 file changed, 13 insertions(+) create mode 100644 prdoc/pr_5594.prdoc diff --git a/prdoc/pr_5594.prdoc b/prdoc/pr_5594.prdoc new file mode 100644 index 000000000000..8ffd8af1ea9b --- /dev/null +++ b/prdoc/pr_5594.prdoc @@ -0,0 +1,13 @@ +# Schema: Polkadot SDK PRDoc Schema (prdoc) v1.0.0 +# See doc at https://raw.githubusercontent.com/paritytech/polkadot-sdk/master/prdoc/schema_user.json + +title: "Add debugging info for `StorageWeightReclaim`" + +doc: + - audience: Runtime Dev + description: | + - Includes call information to be displayed in the logs when the consumed weight is higher than the measured one. + +crates: + - name: cumulus-primitives-storage-weight-reclaim + bump: patch From 41857405bcb18c33a770d67054f92298c3f9851a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jose=CC=81=20Molina?= Date: Thu, 5 Sep 2024 12:02:06 +0200 Subject: [PATCH 3/5] Only include extrinsic count in debug log --- .../storage-weight-reclaim/src/lib.rs | 39 ++++++++++--------- prdoc/pr_5594.prdoc | 2 +- 2 files changed, 21 insertions(+), 20 deletions(-) diff --git a/cumulus/primitives/storage-weight-reclaim/src/lib.rs b/cumulus/primitives/storage-weight-reclaim/src/lib.rs index c99fb9575ae1..9008602cfa17 100644 --- a/cumulus/primitives/storage-weight-reclaim/src/lib.rs +++ b/cumulus/primitives/storage-weight-reclaim/src/lib.rs @@ -128,7 +128,7 @@ where type AccountId = T::AccountId; type Call = T::RuntimeCall; type AdditionalSigned = (); - type Pre = (Option, Self::Call); + type Pre = Option; fn additional_signed( &self, @@ -140,11 +140,11 @@ where fn pre_dispatch( self, _who: &Self::AccountId, - call: &Self::Call, + _call: &Self::Call, _info: &sp_runtime::traits::DispatchInfoOf, _len: usize, ) -> Result { - Ok((get_proof_size(), call.clone())) + Ok(get_proof_size()) } fn post_dispatch( @@ -154,7 +154,7 @@ where _len: usize, _result: &DispatchResult, ) -> Result<(), TransactionValidityError> { - let Some((Some(pre_dispatch_proof_size), call)) = pre else { + let Some(Some(pre_dispatch_proof_size)) = pre else { return Ok(()); }; @@ -181,15 +181,16 @@ where // that in. frame_system::BlockWeight::::mutate(|current| { if consumed_weight > benchmarked_weight { + let extrinsic_count = frame_system::Pallet::::extrinsic_count(); log::error!( target: LOG_TARGET, - "Benchmarked storage weight smaller than consumed storage weight. call: {call:?} benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}" + "Benchmarked storage weight smaller than consumed storage weight. extrinsic: {extrinsic_count} benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}" ); current.accrue(Weight::from_parts(0, storage_size_diff), info.class) } else { log::trace!( target: LOG_TARGET, - "Reclaiming storage weight. call: {call:?} benchmarked: {benchmarked_weight}, consumed: {consumed_weight} unspent: {unspent}" + "Reclaiming storage weight. benchmarked: {benchmarked_weight}, consumed: {consumed_weight} unspent: {unspent}" ); current.reduce(Weight::from_parts(0, storage_size_diff), info.class) } @@ -293,7 +294,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(0), CALL.clone())); + assert_eq!(pre, Some(0)); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); // We expect a refund of 400 @@ -332,7 +333,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(0), CALL.clone())); + assert_eq!(pre, Some(0)); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); // We expect an accrue of 1 @@ -368,7 +369,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(1000), CALL.clone())); + assert_eq!(pre, Some(1000)); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); assert_ok!(StorageWeightReclaim::::post_dispatch( @@ -404,7 +405,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(175), CALL.clone())); + assert_eq!(pre, Some(175)); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); @@ -442,7 +443,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (None, CALL.clone())); + assert_eq!(pre, None); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); assert_ok!(StorageWeightReclaim::::post_dispatch( @@ -473,7 +474,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(100), CALL.clone())); + assert_eq!(pre, Some(100)); // We expect no refund assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); @@ -505,7 +506,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(0), CALL.clone())); + assert_eq!(pre, Some(0)); assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); assert_ok!(StorageWeightReclaim::::post_dispatch( @@ -537,7 +538,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(300), CALL.clone())); + assert_eq!(pre, Some(300)); // Refund 500 unspent weight according to `post_info`, total weight is now 1650 assert_ok!(CheckWeight::::post_dispatch(None, &info, &post_info, 0, &Ok(()))); @@ -576,7 +577,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(100), CALL.clone())); + assert_eq!(pre, Some(100)); // The `CheckWeight` extension will refund `actual_weight` from `PostDispatchInfo` // we always need to call `post_dispatch` to verify that they interoperate correctly. @@ -615,7 +616,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(100), CALL.clone())); + assert_eq!(pre, Some(100)); // The `CheckWeight` extension will refund `actual_weight` from `PostDispatchInfo` // we always need to call `post_dispatch` to verify that they interoperate correctly. @@ -660,7 +661,7 @@ mod tests { .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); // Should return `setup_test_externalities` proof recorder value: 100. - assert_eq!(pre, (Some(0), CALL.clone())); + assert_eq!(pre, Some(0)); // The `CheckWeight` extension will refund `actual_weight` from `PostDispatchInfo` // we always need to call `post_dispatch` to verify that they interoperate correctly. @@ -705,7 +706,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(100), CALL.clone())); + assert_eq!(pre, Some(100)); // This refunds 100 - 50(unspent), total weight is now 1400 assert_ok!(StorageWeightReclaim::::post_dispatch( @@ -746,7 +747,7 @@ mod tests { let pre = StorageWeightReclaim::(PhantomData) .pre_dispatch(&ALICE, CALL, &info, LEN) .unwrap(); - assert_eq!(pre, (Some(100), CALL.clone())); + assert_eq!(pre, Some(100)); // Adds additional 150 weight recorded assert_ok!(StorageWeightReclaim::::post_dispatch( diff --git a/prdoc/pr_5594.prdoc b/prdoc/pr_5594.prdoc index 8ffd8af1ea9b..dbdc7937b73d 100644 --- a/prdoc/pr_5594.prdoc +++ b/prdoc/pr_5594.prdoc @@ -6,7 +6,7 @@ title: "Add debugging info for `StorageWeightReclaim`" doc: - audience: Runtime Dev description: | - - Includes call information to be displayed in the logs when the consumed weight is higher than the measured one. + - Includes extrinsic index to be displayed in the logs when the consumed weight is higher than the measured one. crates: - name: cumulus-primitives-storage-weight-reclaim From 4d79ca51d857534fe25f52ecc9ab28b7169971f5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jose=CC=81=20Molina?= Date: Thu, 5 Sep 2024 12:06:02 +0200 Subject: [PATCH 4/5] Only query extrinsic count when log level is sufficient --- cumulus/primitives/storage-weight-reclaim/src/lib.rs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/cumulus/primitives/storage-weight-reclaim/src/lib.rs b/cumulus/primitives/storage-weight-reclaim/src/lib.rs index 9008602cfa17..64136fd6919b 100644 --- a/cumulus/primitives/storage-weight-reclaim/src/lib.rs +++ b/cumulus/primitives/storage-weight-reclaim/src/lib.rs @@ -181,16 +181,17 @@ where // that in. frame_system::BlockWeight::::mutate(|current| { if consumed_weight > benchmarked_weight { - let extrinsic_count = frame_system::Pallet::::extrinsic_count(); log::error!( target: LOG_TARGET, - "Benchmarked storage weight smaller than consumed storage weight. extrinsic: {extrinsic_count} benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}" + "Benchmarked storage weight smaller than consumed storage weight. extrinsic: {} benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}", + frame_system::Pallet::::extrinsic_count() ); current.accrue(Weight::from_parts(0, storage_size_diff), info.class) } else { log::trace!( target: LOG_TARGET, - "Reclaiming storage weight. benchmarked: {benchmarked_weight}, consumed: {consumed_weight} unspent: {unspent}" + "Reclaiming storage weight. extrinsic: {} benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}", + frame_system::Pallet::::extrinsic_count() ); current.reduce(Weight::from_parts(0, storage_size_diff), info.class) } From 0dbc046b628bfc0ede35c42361ba2f441b1bafd9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Fri, 6 Sep 2024 10:21:41 +0200 Subject: [PATCH 5/5] Apply suggestions from code review --- cumulus/primitives/storage-weight-reclaim/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cumulus/primitives/storage-weight-reclaim/src/lib.rs b/cumulus/primitives/storage-weight-reclaim/src/lib.rs index 64136fd6919b..2529297691e8 100644 --- a/cumulus/primitives/storage-weight-reclaim/src/lib.rs +++ b/cumulus/primitives/storage-weight-reclaim/src/lib.rs @@ -184,14 +184,14 @@ where log::error!( target: LOG_TARGET, "Benchmarked storage weight smaller than consumed storage weight. extrinsic: {} benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}", - frame_system::Pallet::::extrinsic_count() + frame_system::Pallet::::extrinsic_index().unwrap_or(0) ); current.accrue(Weight::from_parts(0, storage_size_diff), info.class) } else { log::trace!( target: LOG_TARGET, "Reclaiming storage weight. extrinsic: {} benchmarked: {benchmarked_weight} consumed: {consumed_weight} unspent: {unspent}", - frame_system::Pallet::::extrinsic_count() + frame_system::Pallet::::extrinsic_index().unwrap_or(0) ); current.reduce(Weight::from_parts(0, storage_size_diff), info.class) }