From 02892ae003f6e6aca2ea0f2eb9121b8c2a79a86d Mon Sep 17 00:00:00 2001 From: Oliver Tale-Yazdi Date: Fri, 3 Mar 2023 13:51:08 +0100 Subject: [PATCH 1/5] Unknit permanently overweight books A book with only permanently overweight messages should be unkit from the ready ring. This does currently not happen since perm. overweight messages are not counted as "processed" and therefore not increase the "total_processed" counter. This is only a problem when the next and only message that is processed is overweight. Eventually this should resolve itself when another non-overweight message is enqueued and processed. But for correctness it should be unknitted. Signed-off-by: Oliver Tale-Yazdi --- frame/message-queue/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/frame/message-queue/src/lib.rs b/frame/message-queue/src/lib.rs index 6c264be3c834e..821225a803d4f 100644 --- a/frame/message-queue/src/lib.rs +++ b/frame/message-queue/src/lib.rs @@ -961,11 +961,11 @@ impl Pallet { book_state.begin.saturating_inc(); } let next_ready = book_state.ready_neighbours.as_ref().map(|x| x.next.clone()); - if book_state.begin >= book_state.end && total_processed > 0 { + if book_state.begin >= book_state.end { // No longer ready - unknit. if let Some(neighbours) = book_state.ready_neighbours.take() { Self::ready_ring_unknit(&origin, neighbours); - } else { + } else if total_processed > 0 { defensive!("Freshly processed queue must have been ready"); } } From 02fcf1d9e7ffd195313725fb14953066ebc5fcff Mon Sep 17 00:00:00 2001 From: Oliver Tale-Yazdi Date: Fri, 3 Mar 2023 14:37:56 +0100 Subject: [PATCH 2/5] Add tests Signed-off-by: Oliver Tale-Yazdi --- frame/message-queue/src/mock.rs | 9 +++ frame/message-queue/src/mock_helpers.rs | 4 +- frame/message-queue/src/tests.rs | 93 +++++++++++++++++++++++++ 3 files changed, 104 insertions(+), 2 deletions(-) diff --git a/frame/message-queue/src/mock.rs b/frame/message-queue/src/mock.rs index 28a599bcf83c6..a0fe0105671e0 100644 --- a/frame/message-queue/src/mock.rs +++ b/frame/message-queue/src/mock.rs @@ -320,3 +320,12 @@ pub fn knit(queue: &MessageOrigin) { pub fn unknit(queue: &MessageOrigin) { super::mock_helpers::unknit::(queue); } + +pub fn num_overweight_enqueued_events() -> u32 { + frame_system::Pallet::::events() + .into_iter() + .filter(|e| { + matches!(e.event, RuntimeEvent::MessageQueue(crate::Event::OverweightEnqueued { .. })) + }) + .count() as u32 +} diff --git a/frame/message-queue/src/mock_helpers.rs b/frame/message-queue/src/mock_helpers.rs index 716a60782ec7f..257691cae4171 100644 --- a/frame/message-queue/src/mock_helpers.rs +++ b/frame/message-queue/src/mock_helpers.rs @@ -74,11 +74,11 @@ where } /// Create a message from the given data. -pub fn msg>(x: &'static str) -> BoundedSlice { +pub fn msg>(x: &str) -> BoundedSlice { BoundedSlice::defensive_truncate_from(x.as_bytes()) } -pub fn vmsg(x: &'static str) -> Vec { +pub fn vmsg(x: &str) -> Vec { x.as_bytes().to_vec() } diff --git a/frame/message-queue/src/tests.rs b/frame/message-queue/src/tests.rs index d3b0555f281f7..35340ddd78abf 100644 --- a/frame/message-queue/src/tests.rs +++ b/frame/message-queue/src/tests.rs @@ -1083,6 +1083,99 @@ fn execute_overweight_works() { assert_eq!(consumed, Err(ExecuteOverweightError::NotFound)); assert!(QueueChanges::take().is_empty()); assert!(!Pages::::contains_key(origin, 0), "Page is gone"); + // The book should have been unknit from the ready ring. + assert!(!ServiceHead::::exists(), "No ready book"); + }); +} + +#[test] +fn permanently_overweight_book_unknits() { + use MessageOrigin::*; + + new_test_ext::().execute_with(|| { + set_weight("bump_service_head", 1.into_weight()); + set_weight("service_queue_base", 1.into_weight()); + set_weight("service_page_base_completion", 1.into_weight()); + + MessageQueue::enqueue_messages([msg("weight=9")].into_iter(), Here); + + // It is the only ready book. + assert_ring(&[Here]); + // Mark the message as overweight. + assert_eq!(MessageQueue::service_queues(8.into_weight()), 4.into_weight()); + assert_last_event::( + Event::OverweightEnqueued { + hash: ::Hashing::hash(b"weight=9"), + origin: Here, + message_index: 0, + page_index: 0, + } + .into(), + ); + // The book is not ready anymore. + assert_ring(&[]); + assert_eq!(MessagesProcessed::take().len(), 0); + assert_eq!(BookStateFor::::get(Here).message_count, 1); + // Now if we enqueue another message, it will become ready again. + MessageQueue::enqueue_messages([msg("weight=1")].into_iter(), Here); + assert_ring(&[Here]); + assert_eq!(MessageQueue::service_queues(8.into_weight()), 5.into_weight()); + assert_eq!(MessagesProcessed::take().len(), 1); + assert_ring(&[]); + }); +} + +#[test] +fn permanently_overweight_book_unknits_multiple() { + use MessageOrigin::*; + + new_test_ext::().execute_with(|| { + set_weight("bump_service_head", 1.into_weight()); + set_weight("service_queue_base", 1.into_weight()); + set_weight("service_page_base_completion", 1.into_weight()); + + MessageQueue::enqueue_messages( + [msg("weight=1"), msg("weight=9"), msg("weight=9")].into_iter(), + Here, + ); + + assert_ring(&[Here]); + // Process the first message. + assert_eq!(MessageQueue::service_queues(4.into_weight()), 4.into_weight()); + assert_eq!(num_overweight_enqueued_events(), 0); + assert_eq!(MessagesProcessed::take().len(), 1); + + // Book is still ready since it was not marked as overweight yet. + assert_ring(&[Here]); + assert_eq!(MessageQueue::service_queues(8.into_weight()), 5.into_weight()); + assert_eq!(num_overweight_enqueued_events(), 2); + assert_eq!(MessagesProcessed::take().len(), 0); + // Now it is overweight. + assert_ring(&[]); + // Enqueue another message. + MessageQueue::enqueue_messages([msg("weight=1")].into_iter(), Here); + assert_ring(&[Here]); + assert_eq!(MessageQueue::service_queues(4.into_weight()), 4.into_weight()); + assert_eq!(MessagesProcessed::take().len(), 1); + assert_ring(&[]); + }); +} + +/// We don't want empty books in the ready ring, but if they somehow make their way in there, it should not panic. +#[test] +#[cfg(not(debug_assertions))] +fn ready_but_empty_does_not_panic() { + use MessageOrigin::*; + + new_test_ext::().execute_with(|| { + // One empty book in the ring. + BookStateFor::::insert(Here, empty_book::()); + BookStateFor::::insert(There, empty_book::()); + BookStateFor::::insert(Everywhere(0), empty_book::()); + + knit(&Here); + assert_ring(&[Here]); + assert_eq!(MessageQueue::service_queues(Weight::MAX), 0.into_weight()); }); } From 666b67db4fde8ab17d2babcbae98d892719d8f08 Mon Sep 17 00:00:00 2001 From: Oliver Tale-Yazdi Date: Fri, 3 Mar 2023 15:47:36 +0100 Subject: [PATCH 3/5] fmt Signed-off-by: Oliver Tale-Yazdi --- frame/message-queue/src/tests.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/frame/message-queue/src/tests.rs b/frame/message-queue/src/tests.rs index 35340ddd78abf..aebd98cc693d2 100644 --- a/frame/message-queue/src/tests.rs +++ b/frame/message-queue/src/tests.rs @@ -1161,7 +1161,8 @@ fn permanently_overweight_book_unknits_multiple() { }); } -/// We don't want empty books in the ready ring, but if they somehow make their way in there, it should not panic. +/// We don't want empty books in the ready ring, but if they somehow make their way in there, it +/// should not panic. #[test] #[cfg(not(debug_assertions))] fn ready_but_empty_does_not_panic() { From 4da95ee0eafdff2b54047f4e96645a898d3b8fc1 Mon Sep 17 00:00:00 2001 From: Oliver Tale-Yazdi Date: Fri, 3 Mar 2023 17:09:46 +0100 Subject: [PATCH 4/5] One more tests Signed-off-by: Oliver Tale-Yazdi --- frame/message-queue/src/tests.rs | 27 ++++++++++++++++++++++++--- 1 file changed, 24 insertions(+), 3 deletions(-) diff --git a/frame/message-queue/src/tests.rs b/frame/message-queue/src/tests.rs index aebd98cc693d2..15bb905738531 100644 --- a/frame/message-queue/src/tests.rs +++ b/frame/message-queue/src/tests.rs @@ -1164,19 +1164,40 @@ fn permanently_overweight_book_unknits_multiple() { /// We don't want empty books in the ready ring, but if they somehow make their way in there, it /// should not panic. #[test] -#[cfg(not(debug_assertions))] +#[cfg(not(debug_assertions))] // Would trigger a defensive failure otherwise. fn ready_but_empty_does_not_panic() { use MessageOrigin::*; new_test_ext::().execute_with(|| { - // One empty book in the ring. BookStateFor::::insert(Here, empty_book::()); BookStateFor::::insert(There, empty_book::()); - BookStateFor::::insert(Everywhere(0), empty_book::()); + knit(&Here); + knit(&There); + assert_ring(&[Here, There]); + + assert_eq!(MessageQueue::service_queues(Weight::MAX), 0.into_weight()); + assert_ring(&[]); + }); +} + +/// We don't want permanently books in the ready ring, but if they somehow make their way in there, +/// it should not panic. +#[test] +#[cfg(not(debug_assertions))] // Would trigger a defensive failure otherwise. +fn ready_but_perm_overweight_does_not_panic() { + use MessageOrigin::*; + + new_test_ext::().execute_with(|| { + MessageQueue::enqueue_message(msg("weight=9"), Here); + assert_eq!(MessageQueue::service_queues(8.into_weight()), 0.into_weight()); + assert_ring(&[]); + // Force it back into the ready ring. knit(&Here); assert_ring(&[Here]); assert_eq!(MessageQueue::service_queues(Weight::MAX), 0.into_weight()); + // Unready again. + assert_ring(&[]); }); } From f6845ec43bddb4d80c8f9631eb635157d5dd3d69 Mon Sep 17 00:00:00 2001 From: command-bot <> Date: Mon, 6 Mar 2023 19:25:06 +0000 Subject: [PATCH 5/5] ".git/.scripts/commands/bench/bench.sh" pallet dev pallet-message-queue --- frame/message-queue/src/weights.rs | 104 ++++++++++++----------------- 1 file changed, 42 insertions(+), 62 deletions(-) diff --git a/frame/message-queue/src/weights.rs b/frame/message-queue/src/weights.rs index d1ccb338e66c3..fd788f2ba4052 100644 --- a/frame/message-queue/src/weights.rs +++ b/frame/message-queue/src/weights.rs @@ -18,7 +18,7 @@ //! Autogenerated weights for pallet_message_queue //! //! THIS FILE WAS AUTO-GENERATED USING THE SUBSTRATE BENCHMARK CLI VERSION 4.0.0-dev -//! DATE: 2023-02-27, STEPS: `50`, REPEAT: `20`, LOW RANGE: `[]`, HIGH RANGE: `[]` +//! DATE: 2023-03-06, STEPS: `50`, REPEAT: `20`, LOW RANGE: `[]`, HIGH RANGE: `[]` //! WORST CASE MAP SIZE: `1000000` //! HOSTNAME: `bm3`, CPU: `Intel(R) Core(TM) i7-7700K CPU @ 4.20GHz` //! EXECUTION: Some(Wasm), WASM-EXECUTION: Compiled, CHAIN: Some("dev"), DB CACHE: 1024 @@ -34,7 +34,7 @@ // --wasm-execution=compiled // --heap-pages=4096 // --json-file=/var/lib/gitlab-runner/builds/zyw4fam_/0/parity/mirrors/substrate/.git/.artifacts/bench.json -// --pallet=pallet_message_queue +// --pallet=pallet-message-queue // --chain=dev // --header=./HEADER-APACHE2 // --output=./frame/message-queue/src/weights.rs @@ -72,9 +72,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `295` // Estimated: `7527` - // Minimum execution time: 12_538 nanoseconds. - Weight::from_parts(12_799_000, 0) - .saturating_add(Weight::from_parts(0, 7527)) + // Minimum execution time: 12_283_000 picoseconds. + Weight::from_parts(12_554_000, 7527) .saturating_add(T::DbWeight::get().reads(3_u64)) .saturating_add(T::DbWeight::get().writes(2_u64)) } @@ -86,9 +85,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `295` // Estimated: `7527` - // Minimum execution time: 11_727 nanoseconds. - Weight::from_parts(12_177_000, 0) - .saturating_add(Weight::from_parts(0, 7527)) + // Minimum execution time: 11_484_000 picoseconds. + Weight::from_parts(11_900_000, 7527) .saturating_add(T::DbWeight::get().reads(3_u64)) .saturating_add(T::DbWeight::get().writes(3_u64)) } @@ -98,9 +96,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `42` // Estimated: `3514` - // Minimum execution time: 4_983 nanoseconds. - Weight::from_parts(5_174_000, 0) - .saturating_add(Weight::from_parts(0, 3514)) + // Minimum execution time: 4_793_000 picoseconds. + Weight::from_parts(4_990_000, 3514) .saturating_add(T::DbWeight::get().reads(1_u64)) .saturating_add(T::DbWeight::get().writes(1_u64)) } @@ -110,9 +107,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `113` // Estimated: `69049` - // Minimum execution time: 6_299 nanoseconds. - Weight::from_parts(6_670_000, 0) - .saturating_add(Weight::from_parts(0, 69049)) + // Minimum execution time: 6_231_000 picoseconds. + Weight::from_parts(6_442_000, 69049) .saturating_add(T::DbWeight::get().reads(1_u64)) .saturating_add(T::DbWeight::get().writes(1_u64)) } @@ -122,9 +118,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `113` // Estimated: `69049` - // Minimum execution time: 6_762 nanoseconds. - Weight::from_parts(7_059_000, 0) - .saturating_add(Weight::from_parts(0, 69049)) + // Minimum execution time: 6_660_000 picoseconds. + Weight::from_parts(6_825_000, 69049) .saturating_add(T::DbWeight::get().reads(1_u64)) .saturating_add(T::DbWeight::get().writes(1_u64)) } @@ -132,9 +127,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `0` // Estimated: `0` - // Minimum execution time: 72_681 nanoseconds. - Weight::from_parts(73_147_000, 0) - .saturating_add(Weight::from_parts(0, 0)) + // Minimum execution time: 72_805_000 picoseconds. + Weight::from_parts(74_650_000, 0) } /// Storage: MessageQueue ServiceHead (r:1 w:1) /// Proof: MessageQueue ServiceHead (max_values: Some(1), max_size: Some(4), added: 499, mode: MaxEncodedLen) @@ -144,9 +138,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `172` // Estimated: `5003` - // Minimum execution time: 7_066 nanoseconds. - Weight::from_parts(7_214_000, 0) - .saturating_add(Weight::from_parts(0, 5003)) + // Minimum execution time: 7_078_000 picoseconds. + Weight::from_parts(7_230_000, 5003) .saturating_add(T::DbWeight::get().reads(2_u64)) .saturating_add(T::DbWeight::get().writes(1_u64)) } @@ -158,9 +151,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `65742` // Estimated: `72563` - // Minimum execution time: 57_778 nanoseconds. - Weight::from_parts(58_778_000, 0) - .saturating_add(Weight::from_parts(0, 72563)) + // Minimum execution time: 56_799_000 picoseconds. + Weight::from_parts(57_634_000, 72563) .saturating_add(T::DbWeight::get().reads(2_u64)) .saturating_add(T::DbWeight::get().writes(2_u64)) } @@ -172,9 +164,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `65742` // Estimated: `72563` - // Minimum execution time: 72_144 nanoseconds. - Weight::from_parts(72_942_000, 0) - .saturating_add(Weight::from_parts(0, 72563)) + // Minimum execution time: 72_290_000 picoseconds. + Weight::from_parts(72_754_000, 72563) .saturating_add(T::DbWeight::get().reads(2_u64)) .saturating_add(T::DbWeight::get().writes(2_u64)) } @@ -186,9 +177,8 @@ impl WeightInfo for SubstrateWeight { // Proof Size summary in bytes: // Measured: `65742` // Estimated: `72563` - // Minimum execution time: 84_890 nanoseconds. - Weight::from_parts(86_073_000, 0) - .saturating_add(Weight::from_parts(0, 72563)) + // Minimum execution time: 84_987_000 picoseconds. + Weight::from_parts(85_562_000, 72563) .saturating_add(T::DbWeight::get().reads(2_u64)) .saturating_add(T::DbWeight::get().writes(2_u64)) } @@ -204,9 +194,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `295` // Estimated: `7527` - // Minimum execution time: 12_538 nanoseconds. - Weight::from_parts(12_799_000, 0) - .saturating_add(Weight::from_parts(0, 7527)) + // Minimum execution time: 12_283_000 picoseconds. + Weight::from_parts(12_554_000, 7527) .saturating_add(RocksDbWeight::get().reads(3_u64)) .saturating_add(RocksDbWeight::get().writes(2_u64)) } @@ -218,9 +207,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `295` // Estimated: `7527` - // Minimum execution time: 11_727 nanoseconds. - Weight::from_parts(12_177_000, 0) - .saturating_add(Weight::from_parts(0, 7527)) + // Minimum execution time: 11_484_000 picoseconds. + Weight::from_parts(11_900_000, 7527) .saturating_add(RocksDbWeight::get().reads(3_u64)) .saturating_add(RocksDbWeight::get().writes(3_u64)) } @@ -230,9 +218,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `42` // Estimated: `3514` - // Minimum execution time: 4_983 nanoseconds. - Weight::from_parts(5_174_000, 0) - .saturating_add(Weight::from_parts(0, 3514)) + // Minimum execution time: 4_793_000 picoseconds. + Weight::from_parts(4_990_000, 3514) .saturating_add(RocksDbWeight::get().reads(1_u64)) .saturating_add(RocksDbWeight::get().writes(1_u64)) } @@ -242,9 +229,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `113` // Estimated: `69049` - // Minimum execution time: 6_299 nanoseconds. - Weight::from_parts(6_670_000, 0) - .saturating_add(Weight::from_parts(0, 69049)) + // Minimum execution time: 6_231_000 picoseconds. + Weight::from_parts(6_442_000, 69049) .saturating_add(RocksDbWeight::get().reads(1_u64)) .saturating_add(RocksDbWeight::get().writes(1_u64)) } @@ -254,9 +240,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `113` // Estimated: `69049` - // Minimum execution time: 6_762 nanoseconds. - Weight::from_parts(7_059_000, 0) - .saturating_add(Weight::from_parts(0, 69049)) + // Minimum execution time: 6_660_000 picoseconds. + Weight::from_parts(6_825_000, 69049) .saturating_add(RocksDbWeight::get().reads(1_u64)) .saturating_add(RocksDbWeight::get().writes(1_u64)) } @@ -264,9 +249,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `0` // Estimated: `0` - // Minimum execution time: 72_681 nanoseconds. - Weight::from_parts(73_147_000, 0) - .saturating_add(Weight::from_parts(0, 0)) + // Minimum execution time: 72_805_000 picoseconds. + Weight::from_parts(74_650_000, 0) } /// Storage: MessageQueue ServiceHead (r:1 w:1) /// Proof: MessageQueue ServiceHead (max_values: Some(1), max_size: Some(4), added: 499, mode: MaxEncodedLen) @@ -276,9 +260,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `172` // Estimated: `5003` - // Minimum execution time: 7_066 nanoseconds. - Weight::from_parts(7_214_000, 0) - .saturating_add(Weight::from_parts(0, 5003)) + // Minimum execution time: 7_078_000 picoseconds. + Weight::from_parts(7_230_000, 5003) .saturating_add(RocksDbWeight::get().reads(2_u64)) .saturating_add(RocksDbWeight::get().writes(1_u64)) } @@ -290,9 +273,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `65742` // Estimated: `72563` - // Minimum execution time: 57_778 nanoseconds. - Weight::from_parts(58_778_000, 0) - .saturating_add(Weight::from_parts(0, 72563)) + // Minimum execution time: 56_799_000 picoseconds. + Weight::from_parts(57_634_000, 72563) .saturating_add(RocksDbWeight::get().reads(2_u64)) .saturating_add(RocksDbWeight::get().writes(2_u64)) } @@ -304,9 +286,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `65742` // Estimated: `72563` - // Minimum execution time: 72_144 nanoseconds. - Weight::from_parts(72_942_000, 0) - .saturating_add(Weight::from_parts(0, 72563)) + // Minimum execution time: 72_290_000 picoseconds. + Weight::from_parts(72_754_000, 72563) .saturating_add(RocksDbWeight::get().reads(2_u64)) .saturating_add(RocksDbWeight::get().writes(2_u64)) } @@ -318,9 +299,8 @@ impl WeightInfo for () { // Proof Size summary in bytes: // Measured: `65742` // Estimated: `72563` - // Minimum execution time: 84_890 nanoseconds. - Weight::from_parts(86_073_000, 0) - .saturating_add(Weight::from_parts(0, 72563)) + // Minimum execution time: 84_987_000 picoseconds. + Weight::from_parts(85_562_000, 72563) .saturating_add(RocksDbWeight::get().reads(2_u64)) .saturating_add(RocksDbWeight::get().writes(2_u64)) }