From e16f15119f937a2a7bea09dc0724dd266d14c242 Mon Sep 17 00:00:00 2001 From: Oliver Tale-Yazdi Date: Tue, 7 Mar 2023 12:31:57 +0100 Subject: [PATCH] `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 * Add tests Signed-off-by: Oliver Tale-Yazdi * fmt Signed-off-by: Oliver Tale-Yazdi * One more tests Signed-off-by: Oliver Tale-Yazdi * ".git/.scripts/commands/bench/bench.sh" pallet dev pallet-message-queue --------- Signed-off-by: Oliver Tale-Yazdi Co-authored-by: command-bot <> --- substrate/frame/message-queue/src/lib.rs | 4 +- substrate/frame/message-queue/src/mock.rs | 9 ++ .../frame/message-queue/src/mock_helpers.rs | 4 +- substrate/frame/message-queue/src/tests.rs | 115 ++++++++++++++++++ substrate/frame/message-queue/src/weights.rs | 104 +++++++--------- 5 files changed, 170 insertions(+), 66 deletions(-) diff --git a/substrate/frame/message-queue/src/lib.rs b/substrate/frame/message-queue/src/lib.rs index 409503d317..bed131e5f0 100644 --- a/substrate/frame/message-queue/src/lib.rs +++ b/substrate/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"); } } diff --git a/substrate/frame/message-queue/src/mock.rs b/substrate/frame/message-queue/src/mock.rs index 28a599bcf8..a0fe010567 100644 --- a/substrate/frame/message-queue/src/mock.rs +++ b/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::(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/substrate/frame/message-queue/src/mock_helpers.rs b/substrate/frame/message-queue/src/mock_helpers.rs index 716a60782e..257691cae4 100644 --- a/substrate/frame/message-queue/src/mock_helpers.rs +++ b/substrate/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/substrate/frame/message-queue/src/tests.rs b/substrate/frame/message-queue/src/tests.rs index d3b0555f28..15bb905738 100644 --- a/substrate/frame/message-queue/src/tests.rs +++ b/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::::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))] // Would trigger a defensive failure otherwise. +fn ready_but_empty_does_not_panic() { + use MessageOrigin::*; + + new_test_ext::().execute_with(|| { + BookStateFor::::insert(Here, empty_book::()); + BookStateFor::::insert(There, 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(&[]); }); } diff --git a/substrate/frame/message-queue/src/weights.rs b/substrate/frame/message-queue/src/weights.rs index d1ccb338e6..fd788f2ba4 100644 --- a/substrate/frame/message-queue/src/weights.rs +++ b/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 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)) }