MessageQueue: unknit permanently overweight books (#13528)

* 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 <oliver.tale-yazdi@parity.io>

* Add tests

Signed-off-by: Oliver Tale-Yazdi <oliver.tale-yazdi@parity.io>

* fmt

Signed-off-by: Oliver Tale-Yazdi <oliver.tale-yazdi@parity.io>

* One more tests

Signed-off-by: Oliver Tale-Yazdi <oliver.tale-yazdi@parity.io>

* ".git/.scripts/commands/bench/bench.sh" pallet dev pallet-message-queue

---------

Signed-off-by: Oliver Tale-Yazdi <oliver.tale-yazdi@parity.io>
Co-authored-by: command-bot <>

substrate/frame/message-queue/src/lib.rs

@@ -961,11 +961,11 @@ impl<T: Config> Pallet<T> {
 			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");
 			}
 		}

substrate/frame/message-queue/src/mock.rs

@@ -320,3 +320,12 @@ pub fn knit(queue: &MessageOrigin) {
 pub fn unknit(queue: &MessageOrigin) {
 	super::mock_helpers::unknit::<Test>(queue);
 }
+
+pub fn num_overweight_enqueued_events() -> u32 {
+	frame_system::Pallet::<Test>::events()
+		.into_iter()
+		.filter(|e| {
+			matches!(e.event, RuntimeEvent::MessageQueue(crate::Event::OverweightEnqueued { .. }))
+		})
+		.count() as u32
+}

substrate/frame/message-queue/src/mock_helpers.rs

@@ -74,11 +74,11 @@ where
 }
 
 /// Create a message from the given data.
-pub fn msg<N: Get<u32>>(x: &'static str) -> BoundedSlice<u8, N> {
+pub fn msg<N: Get<u32>>(x: &str) -> BoundedSlice<u8, N> {
 	BoundedSlice::defensive_truncate_from(x.as_bytes())
 }
 
-pub fn vmsg(x: &'static str) -> Vec<u8> {
+pub fn vmsg(x: &str) -> Vec<u8> {
 	x.as_bytes().to_vec()
 }
 

substrate/frame/message-queue/src/tests.rs

@@ -1083,6 +1083,121 @@ fn execute_overweight_works() {
 		assert_eq!(consumed, Err(ExecuteOverweightError::NotFound));
 		assert!(QueueChanges::take().is_empty());
 		assert!(!Pages::<Test>::contains_key(origin, 0), "Page is gone");
+		// The book should have been unknit from the ready ring.
+		assert!(!ServiceHead::<Test>::exists(), "No ready book");
+	});
+}
+
+#[test]
+fn permanently_overweight_book_unknits() {
+	use MessageOrigin::*;
+
+	new_test_ext::<Test>().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::<Test>(
+			Event::OverweightEnqueued {
+				hash: <Test as frame_system::Config>::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::<Test>::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::<Test>().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))] // Would trigger a defensive failure otherwise.
+fn ready_but_empty_does_not_panic() {
+	use MessageOrigin::*;
+
+	new_test_ext::<Test>().execute_with(|| {
+		BookStateFor::<Test>::insert(Here, empty_book::<Test>());
+		BookStateFor::<Test>::insert(There, empty_book::<Test>());
+
+		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::<Test>().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(&[]);
 	});
 }
 

substrate/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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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<T: frame_system::Config> WeightInfo for SubstrateWeight<T> {
 		// 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))
 	}