Merge pull request #486 from paritytech/vstakhov-backing-context

Show backing context size in the tracker

essentials/src/collector/candidate_record.rs

@@ -38,6 +38,8 @@ pub struct CandidateInclusionRecord<T: Encode + Decode + Clone> {
 	pub core_idx: Option<u32>,
 	/// Stated relay parent
 	pub relay_parent: T,
+	/// Stated relay parent number
+	pub relay_parent_number: u32,
 }
 
 /// Outcome of the dispute + timestamp
@@ -122,6 +124,14 @@ impl CandidateRecord {
 		}
 	}
 
+	/// Returns backing context time for a candidate
+	#[allow(dead_code)]
+	pub fn backing_time(&self) -> Option<u32> {
+		self.candidate_inclusion
+			.backed
+			.checked_sub(self.candidate_inclusion.relay_parent_number)
+	}
+
 	/// Returns dispute resolution time
 	#[allow(dead_code)]
 	pub fn dispute_resolution_time(&self) -> Option<u32> {

essentials/src/collector/mod.rs

@@ -620,10 +620,12 @@ impl Collector {
 						)
 						.await;
 
-					if let Some(_relay_parent) = maybe_relay_parent {
+					if let Some(relay_parent) = maybe_relay_parent {
+						let relay_parent: SubstrateHeader<u32, BlakeTwo256> = relay_parent.into_inner()?;
 						let relay_block_number = self.state.current_relay_chain_block_number;
 						let candidate_inclusion = CandidateInclusionRecord {
 							relay_parent: change_event.candidate_descriptor.relay_parent,
+							relay_parent_number: relay_parent.number,
 							parachain_id: change_event.parachain_id,
 							backed: relay_block_number,
 							core_idx: None,

parachain-tracer/src/main.rs

@@ -330,7 +330,7 @@ async fn process_tracker_update(
 ) -> color_eyre::Result<()> {
 	match tracker.inject_block(relay_hash, relay_parent_number).await {
 		Ok(_) => {
-			if let Some(progress) = tracker.progress(metrics) {
+			if let Some(progress) = tracker.progress(metrics).await {
 				if is_cli {
 					println!("{}", progress);
 				}

parachain-tracer/src/prometheus.rs

@@ -69,6 +69,8 @@ struct MetricsInner {
 	bitfields: IntGaugeVec,
 	/// Average candidate inclusion time measured in relay chain blocks.
 	para_block_times: HistogramVec,
+	/// Average candidate backing time measured in relay chain blocks (will be 1 for non async-backing case)
+	para_backing_times: HistogramVec,
 	/// Average candidate inclusion time measured in seconds.
 	para_block_times_sec: HistogramVec,
 	/// Finality lag
@@ -159,10 +161,12 @@ impl Metrics {
 		}
 	}
 
+	/// Update metrics on candidate inclusion
 	pub(crate) fn on_included(
 		&self,
 		relay_parent_number: u32,
 		previous_included: Option<u32>,
+		backed_in: Option<u32>,
 		para_block_time_sec: Option<Duration>,
 		para_id: u32,
 	) {
@@ -182,6 +186,12 @@ impl Metrics {
 					.with_label_values(&[&para_str[..]])
 					.observe(time.as_secs_f64());
 			}
+			if let Some(backed_in) = backed_in {
+				metrics
+					.para_backing_times
+					.with_label_values(&[&para_str[..]])
+					.observe(backed_in as f64);
+			}
 		}
 	}
 
@@ -302,6 +312,14 @@ fn register_metrics(registry: &Registry) -> Result<Metrics> {
 			)?,
 			registry,
 		)?,
+		para_backing_times: prometheus_endpoint::register(
+			HistogramVec::new(
+				HistogramOpts::new("pc_para_backing_time", "Parachain backing time measured in relay chain blocks.")
+					.buckets(HISTOGRAM_TIME_BUCKETS_BLOCKS.into()),
+				&["parachain_id"],
+			)?,
+			registry,
+		)?,
 		finality_lag: prometheus_endpoint::register(
 			Gauge::new("pc_finality_lag", "Finality lag")?,
 			registry,

parachain-tracer/src/stats.rs

@@ -163,6 +163,8 @@ pub struct ParachainStats {
 	bitfields: AvgBucket<u32>,
 	/// Average included time in relay parent blocks
 	included_times: AvgBucket<u16>,
+	/// Average backing time in relay parent blocks
+	backed_times: AvgBucket<u16>,
 }
 
 impl ParachainStats {
@@ -186,13 +188,17 @@ impl ParachainStats {
 	}
 
 	/// Update included counter
-	pub fn on_included(&mut self, relay_parent_number: u32, previous_included: Option<u32>) {
+	pub fn on_included(&mut self, relay_parent_number: u32, previous_included: Option<u32>, backed_in: Option<u32>) {
 		self.included_count += 1;
 
 		if let Some(previous_block_number) = previous_included {
 			self.included_times
 				.update(relay_parent_number.saturating_sub(previous_block_number) as u16);
 		}
+
+		if let Some(backed_in) = backed_in {
+			self.backed_times.update(backed_in as u16);
+		}
 	}
 
 	/// Update disputed counter
@@ -254,10 +260,16 @@ impl Display for ParachainStats {
 		)?;
 		writeln!(
 			f,
-			"Average parachain block time: {} relay parent blocks ({} parachain blocks processed)",
+			"Average parachain block inclusion time: {} relay parent blocks ({} parachain blocks processed)",
 			format!("{:.2}", self.included_times.value()).bold(),
 			self.included_times.count()
 		)?;
+		writeln!(
+			f,
+			"Average parachain block backing time: {} relay parent blocks ({} parachain blocks processed)",
+			format!("{:.2}", self.backed_times.value()).bold(),
+			self.backed_times.count()
+		)?;
 		writeln!(
 			f,
 			"Skipped slots: {}, slow availability: {}, slow bitfields propagation: {}",

parachain-tracer/src/tracker.rs

@@ -25,7 +25,7 @@ use log::{debug, error, info, warn};
 use polkadot_introspector_essentials::{
 	api::subxt_wrapper::{InherentData, RequestExecutor, SubxtHrmpChannel},
 	chain_events::SubxtDisputeResult,
-	collector::{CollectorPrefixType, CollectorStorageApi, DisputeInfo},
+	collector::{candidate_record::CandidateRecord, CollectorPrefixType, CollectorStorageApi, DisputeInfo},
 	metadata::{polkadot, polkadot_primitives},
 	types::{AccountId32, BlockNumber, Timestamp, H256},
 };
@@ -59,7 +59,7 @@ pub trait ParachainBlockTracker {
 	async fn new_session(&mut self, new_session_index: u32);
 
 	/// Update current parachain progress.
-	fn progress(&mut self, metrics: &Metrics) -> Option<ParachainProgressUpdate>;
+	async fn progress(&mut self, metrics: &Metrics) -> Option<ParachainProgressUpdate>;
 }
 
 /// An outcome for a dispute
@@ -248,7 +248,7 @@ impl ParachainBlockTracker for SubxtTracker {
 		}
 	}
 
-	fn progress(&mut self, metrics: &Metrics) -> Option<ParachainProgressUpdate> {
+	async fn progress(&mut self, metrics: &Metrics) -> Option<ParachainProgressUpdate> {
 		if self.current_relay_block.is_none() {
 			// return writeln!(f, "{}", "No relay block processed".to_string().bold().red(),)
 			self.update = None;
@@ -294,7 +294,7 @@ impl ParachainBlockTracker for SubxtTracker {
 					metrics.on_backed(self.para_id);
 				},
 			ParachainBlockState::PendingAvailability | ParachainBlockState::Included => {
-				self.progress_availability(metrics);
+				self.progress_availability(metrics).await;
 			},
 		}
 
@@ -696,7 +696,7 @@ impl SubxtTracker {
 		}
 	}
 
-	fn progress_availability(&mut self, metrics: &Metrics) {
+	async fn progress_availability(&mut self, metrics: &Metrics) {
 		let (relay_block_number, _) = self.current_relay_block.expect("Checked by caller; qed");
 		let relay_block_ts = self.current_relay_block_ts.expect("Checked by caller; qed");
 
@@ -717,10 +717,29 @@ impl SubxtTracker {
 						self.current_candidate.max_av_bits,
 					));
 				}
-				self.stats.on_included(relay_block_number, self.last_included_block);
+
+				// Extract stored candidate from the collector if any
+				let stored_candidate = self
+					.api
+					.storage()
+					.storage_read_prefixed(CollectorPrefixType::Candidate(self.para_id), candidate_hash)
+					.await;
+				let mut backed_in = None;
+				if let Some(stored_candidate) = stored_candidate {
+					let stored_candidate: CandidateRecord =
+						stored_candidate.into_inner().expect("must be able to decode what we encode");
+					backed_in = Some(
+						stored_candidate
+							.candidate_inclusion
+							.backed
+							.saturating_sub(stored_candidate.candidate_inclusion.relay_parent_number),
+					);
+				}
+				self.stats.on_included(relay_block_number, self.last_included_block, backed_in);
 				metrics.on_included(
 					relay_block_number,
 					self.last_included_block,
+					backed_in,
 					self.get_candidate_time(),
 					self.para_id,
 				);