aura/slot_based: Reduce authoring duration of the last produced block

cumulus/client/consensus/aura/src/collators/slot_based/block_builder_task.rs

@@ -139,7 +139,6 @@ where
 	P::Signature: TryFrom<Vec<u8>> + Member + Codec,
 {
 	async move {
-		tracing::info!(target: LOG_TARGET, "Starting slot-based block-builder task.");
 		let BuilderTaskParams {
 			relay_client,
 			create_inherent_data_providers,
@@ -158,6 +157,8 @@ where
 			max_pov_percentage,
 		} = params;
 
+		tracing::info!(target: LOG_TARGET, ?para_id, ?authoring_duration, ?relay_chain_slot_duration, "Starting slot-based block-builder task.");
+
 		let mut slot_timer = SlotTimer::<_, _, P>::new_with_offset(
 			para_client.clone(),
 			slot_offset,
@@ -386,11 +387,8 @@ where
 				validation_data.max_pov_size * 85 / 100
 			} as usize;
 
-			let adjusted_authoring_duration = match slot_timer.time_until_next_slot() {
-				Ok((duration, _slot)) => std::cmp::min(authoring_duration, duration),
-				Err(_) => authoring_duration,
-			};
-
+			let adjusted_authoring_duration =
+				slot_timer.adjust_authoring_duration(authoring_duration);
 			tracing::debug!(target: crate::LOG_TARGET, duration = ?adjusted_authoring_duration, "Adjusted proposal duration.");
 
 			let Ok(Some(candidate)) = collator

cumulus/client/consensus/aura/src/collators/slot_based/slot_timer.rs

@@ -37,6 +37,10 @@ use std::{
 /// Defensive mechanism, corresponds to 12 cores at 6 second block time.
 const BLOCK_PRODUCTION_MINIMUM_INTERVAL_MS: Duration = Duration::from_millis(500);
 
+/// The amount of time the authoring duration of the last block production attempt
+/// should be reduced by to fit into the slot timing.
+const BLOCK_PRODUCTION_ADJUSTMENT_MS: Duration = Duration::from_millis(500);
+
 #[derive(Debug)]
 pub(crate) struct SlotInfo {
 	pub timestamp: Timestamp,
@@ -46,7 +50,7 @@ pub(crate) struct SlotInfo {
 /// Manages block-production timings based on chain parameters and assigned cores.
 #[derive(Debug)]
 pub(crate) struct SlotTimer<Block, Client, P> {
-	/// Client that is used for runtime calls
+	/// Parachain client that is used for runtime calls
 	client: Arc<Client>,
 	/// Offset the current time by this duration.
 	time_offset: Duration,
@@ -56,10 +60,47 @@ pub(crate) struct SlotTimer<Block, Client, P> {
 	/// attempts we should trigger per relay chain block.
 	relay_slot_duration: Duration,
 	/// Stores the latest slot that was reported by [`Self::wait_until_next_slot`].
-	last_reported_slot: Option<Slot>,
+	last_reported_slot: LastReportedSlot,
 	_marker: std::marker::PhantomData<(Block, Box<dyn Fn(P) + Send + Sync + 'static>)>,
 }
 
+/// Information about the last reported slot.
+#[derive(Debug, Default, Clone, Copy)]
+struct LastReportedSlot {
+	/// The reported slot.
+	slot: Option<Slot>,
+	/// The number of blocks produced for that slot.
+	blocks_produced: usize,
+}
+
+impl LastReportedSlot {
+	/// Increment the number of blocks produced for the slot.
+	///
+	/// Returns the incremented number of blocks produced.
+	fn increment_blocks_produced(&mut self) -> usize {
+		self.blocks_produced = self.blocks_produced.saturating_add(1);
+		self.blocks_produced
+	}
+
+	/// Set a new slot, resetting the blocks produced if the slot changed.
+	fn set_new_slot(&mut self, slot: Slot) {
+		match self.slot {
+			Some(s) if s == slot => return,
+			_ => {},
+		};
+
+		tracing::debug!(
+			target: LOG_TARGET,
+			previous_slot = ?self.slot,
+			next_slot = ?slot,
+			"Resetting blocks produced for new slot."
+		);
+
+		self.slot = Some(slot);
+		self.blocks_produced = 0;
+	}
+}
+
 /// Compute when to try block-authoring next.
 /// The exact time point is determined by the slot duration of relay- and parachain as
 /// well as the last observed core count. If more cores are available, we attempt to author blocks
@@ -147,7 +188,7 @@ where
 			time_offset,
 			last_reported_core_num: None,
 			relay_slot_duration,
-			last_reported_slot: None,
+			last_reported_slot: LastReportedSlot::default(),
 			_marker: Default::default(),
 		}
 	}
@@ -173,6 +214,61 @@ where
 		))
 	}
 
+	/// Adjust the authoring duration to fit into the slot timing.
+	///
+	/// Returns the adjusted authoring duration and the slot that it corresponds to.
+	pub fn adjust_authoring_duration(&mut self, authoring_duration: Duration) -> Duration {
+		// Update the number of parachain blocks produced.
+		let blocks_produced_so_far = self.last_reported_slot.increment_blocks_produced();
+
+		let Ok((duration, slot)) = self.time_until_next_slot() else {
+			tracing::error!(
+				target: LOG_TARGET,
+				"Failed to fetch slot duration from runtime. Using unadjusted authoring duration."
+			);
+			return authoring_duration;
+		};
+
+		// Determine how many parachain blocks are produced per relay slot
+		// based on the authoring duration.
+		let blocks_produced_per_relay_slot = (self.relay_slot_duration.as_millis() /
+			authoring_duration.as_millis() as u128) as usize;
+
+		tracing::debug!(
+			target: LOG_TARGET,
+			blocks_produced_for_slot = ?blocks_produced_so_far,
+			?blocks_produced_per_relay_slot,
+			?authoring_duration,
+			?duration,
+			"Adjusting authoring duration for slot.",
+		);
+
+		// If the next attempt duration is less than the authoring duration,
+		// ensure we fit into the slot.
+		let mut authoring_duration = authoring_duration.min(duration);
+
+		// The authoring of the last block that fits into the relay chain is reduced to fit into the
+		// slot timing. For example, when the block is full we need sufficient time to
+		// propagate and import it before the next slot starts.
+		if blocks_produced_so_far >= blocks_produced_per_relay_slot {
+			authoring_duration = std::cmp::max(
+				authoring_duration.saturating_sub(BLOCK_PRODUCTION_ADJUSTMENT_MS),
+				BLOCK_PRODUCTION_MINIMUM_INTERVAL_MS,
+			);
+
+			tracing::debug!(
+				target: LOG_TARGET,
+				aura_slot = ?slot,
+				blocks_produced_for_slot = ?blocks_produced_so_far,
+				?blocks_produced_per_relay_slot,
+				?authoring_duration,
+				"Adjusted the last block production attempt for the slot."
+			);
+		}
+
+		authoring_duration
+	}
+
 	/// Returns a future that resolves when the next block production should be attempted.
 	pub async fn wait_until_next_slot(&mut self) -> Result<(), ()> {
 		let Ok(slot_duration) = crate::slot_duration(&*self.client) else {
@@ -185,10 +281,13 @@ where
 		match self.last_reported_slot {
 			// If we already reported a slot, we don't want to skip a slot. But we also don't want
 			// to go through all the slots if a node was halted for some reason.
-			Some(ls) if ls + 1 < next_aura_slot && next_aura_slot <= ls + 3 => {
-				next_aura_slot = ls + 1u64;
+			LastReportedSlot { slot: Some(slot), .. }
+				if slot + 1 < next_aura_slot && next_aura_slot <= slot + 3 =>
+			{
+				next_aura_slot = slot + 1u64;
 			},
-			None | Some(_) => {
+			_ => {
+				tracing::trace!(target: LOG_TARGET, ?time_until_next_attempt, "Sleeping until the next slot.");
 				tokio::time::sleep(time_until_next_attempt).await;
 			},
 		}
@@ -200,7 +299,8 @@ where
 			"New block production opportunity."
 		);
 
-		self.last_reported_slot = Some(next_aura_slot);
+		self.last_reported_slot.set_new_slot(next_aura_slot);
+
 		Ok(())
 	}
 }

prdoc/pr_10154.prdoc

@@ -0,0 +1,83 @@
+title: 'aura/slot_based: Reduce authoring duration of the last produced block '
+doc:
+- audience: Node Dev
+  description: "This PR reduces the authoring duration of the last parachain produced\
+    \ block. Effectively ensures that the next author has sufficient time to import\
+    \ the previous block.\n\n- Only the last authoring duration is reduced by 500ms\
+    \ (`BLOCK_PRODUCTION_ADJUSTMENT_MS`)\n- The authorizing duration was already capped\
+    \ at a minimum of 500ms (`BLOCK_PRODUCTION_MINIMUM_INTERVAL_MS`)\n- The number\
+    \ of para blocks that the relay chain can fit is inferred by the `relay slot duration\
+    \ / default authoring time`\n- `SlotInfo` is adjusted to account for the number\
+    \ of para blocks produced so far\n- While at it, have added a few extra trace\
+    \ logs\n\n### Testing Done\n\nTested on top of:\n- https://github.com/paritytech/polkadot-sdk/pull/9880\n\
+    \n```\nDEBUG tokio-runtime-worker aura::cumulus: [Parachain] New block production\
+    \ opportunity. slot_duration=SlotDuration(6000) aura_slot=Slot(293621792)\nDEBUG\
+    \ tokio-runtime-worker aura::cumulus: [Parachain] Parachain slot adjusted to relay\
+    \ chain. timestamp=Timestamp(1761730746000) slot=Slot(293621791)\nDEBUG tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] Going to claim core relay_parent=0xa486a45c3a10e9ade7d4ddefef7615d4b001d47c962013386b95719d8f37aeae\
+    \ core_selector=CoreSelector(0) claim_queue_offset=ClaimQueueOffset(1)\nDEBUG\
+    \ tokio-runtime-worker aura::cumulus: [Parachain] Building block. unincluded_segment_len=0\
+    \ relay_parent=0xa486\u2026aeae relay_parent_num=61 relay_parent_offset=1 included_hash=0x21c3\u2026\
+    ac1b included_num=84 parent=0x21c3\u2026ac1b slot=Slot(293621791)\nDEBUG tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] Expected to produce for 3 cores but only have 1 slots.\
+    \ Attempting to produce multiple blocks per slot. block_production_interval=2s\n\
+    DEBUG tokio-runtime-worker aura::cumulus: [Parachain] Adjusting authoring duration\
+    \ for slot. blocks_produced_for_slot=1 blocks_produced_per_relay_slot=3 authoring_duration=2s\
+    \ duration=1.99s\nDEBUG tokio-runtime-worker aura::cumulus: [Parachain] Adjusted\
+    \ proposal duration. duration=1.99s\n\n INFO tokio-runtime-worker sc_basic_authorship::basic_authorship:\
+    \ [Parachain] \U0001F381 Prepared block for proposing at 85 (8 ms) hash: 0x7579638578324c2f7b5b9f8af0f2bb1aa238f665db70dfcd1ddcb77475733e28;\
+    \ parent_hash: 0x21c3\u2026ac1b; end: NoMoreTransactions; extrinsics_count: 2\n\
+    \ INFO tokio-runtime-worker substrate: [Parachain] \U0001F195 Imported #85 (0x21c3\u2026\
+    ac1b \u2192 0x183a\u20265b0d)\n\nDEBUG tokio-runtime-worker aura::cumulus: [Parachain]\
+    \ Expected to produce for 3 cores but only have 1 slots. Attempting to produce\
+    \ multiple blocks per slot. block_production_interval=2s\nTRACE tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] Determined next block production opportunity. time_until_next_attempt=1.977s\
+    \ aura_slot=Slot(293621792) last_reported=LastReportedSlot { slot: Some(Slot(293621792)),\
+    \ blocks_produced: 1 }\nTRACE tokio-runtime-worker aura::cumulus: [Parachain]\
+    \ Sleeping until the next slot. time_until_next_attempt=1.977s\nDEBUG tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] New block production opportunity. slot_duration=SlotDuration(6000)\
+    \ aura_slot=Slot(293621792)\nDEBUG tokio-runtime-worker aura::cumulus: [Parachain]\
+    \ Parachain slot adjusted to relay chain. timestamp=Timestamp(1761730746000) slot=Slot(293621791)\n\
+    DEBUG tokio-runtime-worker aura::cumulus: [Parachain] Going to claim core relay_parent=0xa486a45c3a10e9ade7d4ddefef7615d4b001d47c962013386b95719d8f37aeae\
+    \ core_selector=CoreSelector(1) claim_queue_offset=ClaimQueueOffset(1)\nDEBUG\
+    \ tokio-runtime-worker aura::cumulus: [Parachain] Building block. unincluded_segment_len=1\
+    \ relay_parent=0xa486\u2026aeae relay_parent_num=61 relay_parent_offset=1 included_hash=0x21c3\u2026\
+    ac1b included_num=84 parent=0x183a\u20265b0d slot=Slot(293621791)\nDEBUG tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] Expected to produce for 3 cores but only have 1 slots.\
+    \ Attempting to produce multiple blocks per slot. block_production_interval=2s\n\
+    DEBUG tokio-runtime-worker aura::cumulus: [Parachain] Adjusting authoring duration\
+    \ for slot. blocks_produced_for_slot=2 blocks_produced_per_relay_slot=3 authoring_duration=2s\
+    \ duration=1.988s\n\nDEBUG tokio-runtime-worker aura::cumulus: [Parachain] Adjusted\
+    \ proposal duration. duration=1.988s\n INFO tokio-runtime-worker sc_basic_authorship::basic_authorship:\
+    \ [Parachain] \U0001F381 Prepared block for proposing at 86 (232 ms) hash: 0x17b4f3fc6f13a8bad577d3e12f026a8c51b37fecd33551beb32e059fc510c941;\
+    \ parent_hash: 0x183a\u20265b0d; end: NoMoreTransactions; extrinsics_count: 2\n\
+    \ INFO tokio-runtime-worker substrate: [Parachain] \U0001F195 Imported #86 (0x183a\u2026\
+    5b0d \u2192 0x9504\u2026a66d)\nDEBUG tokio-runtime-worker aura::cumulus: [Parachain]\
+    \ Expected to produce for 3 cores but only have 1 slots. Attempting to produce\
+    \ multiple blocks per slot. block_production_interval=2s\nTRACE tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] Determined next block production opportunity. time_until_next_attempt=1.751s\
+    \ aura_slot=Slot(293621792) last_reported=LastReportedSlot { slot: Some(Slot(293621792)),\
+    \ blocks_produced: 2 }\nTRACE tokio-runtime-worker aura::cumulus: [Parachain]\
+    \ Sleeping until the next slot. time_until_next_attempt=1.751s\nDEBUG tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] New block production opportunity. slot_duration=SlotDuration(6000)\
+    \ aura_slot=Slot(293621792)\nDEBUG tokio-runtime-worker aura::cumulus: [Parachain]\
+    \ Parachain slot adjusted to relay chain. timestamp=Timestamp(1761730746000) slot=Slot(293621791)\n\
+    DEBUG tokio-runtime-worker aura::cumulus: [Parachain] Going to claim core relay_parent=0xa486a45c3a10e9ade7d4ddefef7615d4b001d47c962013386b95719d8f37aeae\
+    \ core_selector=CoreSelector(2) claim_queue_offset=ClaimQueueOffset(1)\nDEBUG\
+    \ tokio-runtime-worker aura::cumulus: [Parachain] Building block. unincluded_segment_len=2\
+    \ relay_parent=0xa486\u2026aeae relay_parent_num=61 relay_parent_offset=1 included_hash=0x21c3\u2026\
+    ac1b included_num=84 parent=0x9504\u2026a66d slot=Slot(293621791)\nDEBUG tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] Expected to produce for 3 cores but only have 1 slots.\
+    \ Attempting to produce multiple blocks per slot. block_production_interval=2s\n\
+    \nDEBUG tokio-runtime-worker aura::cumulus: [Parachain] Adjusting authoring duration\
+    \ for slot. blocks_produced_for_slot=3 blocks_produced_per_relay_slot=3 authoring_duration=2s\
+    \ duration=1.99s\nDEBUG tokio-runtime-worker aura::cumulus: [Parachain] Adjusted\
+    \ the last block production attempt for the slot. aura_slot=Slot(293621793) blocks_produced_for_slot=3\
+    \ blocks_produced_per_relay_slot=3 authoring_duration=1.49s\nDEBUG tokio-runtime-worker\
+    \ aura::cumulus: [Parachain] Adjusted proposal duration. duration=1.49s\n```\n\
+    \n- The first two blocks are adjusted to `duration=1.99s` and `duration=1.988s`\
+    \ respectively\n- The last block is adjusted to `duration=1.49s` (ie reduced by\
+    \ another 500ms)\n\nPart of: https://github.com/paritytech/polkadot-sdk/issues/9848"
+crates:
+- name: cumulus-client-consensus-aura
+  bump: patch