approval-distribution: moar metrics (#2734)

node/network/approval-distribution/src/lib.rs

@@ -172,7 +172,7 @@ impl State {
 				})
 			}
 			NetworkBridgeEvent::PeerViewChange(peer_id, view) => {
-				self.handle_peer_view_change(ctx, peer_id, view).await;
+				self.handle_peer_view_change(ctx, metrics, peer_id, view).await;
 			}
 			NetworkBridgeEvent::OurViewChange(view) => {
 				tracing::trace!(
@@ -229,6 +229,8 @@ impl State {
 		);
 
 		{
+			let _timer = metrics.time_import_pending_now_known();
+
 			let pending_now_known = self.pending_known.keys()
 				.filter(|k| self.blocks.contains_key(k))
 				.copied()
@@ -269,8 +271,9 @@ impl State {
 				view.finalized_number,
 			);
 			Self::unify_with_peer(
-				&mut self.blocks,
 				ctx,
+				metrics,
+				&mut self.blocks,
 				peer_id.clone(),
 				view_intersection,
 			).await;
@@ -342,6 +345,7 @@ impl State {
 	async fn handle_peer_view_change(
 		&mut self,
 		ctx: &mut impl SubsystemContext<Message = ApprovalDistributionMessage>,
+		metrics: &Metrics,
 		peer_id: PeerId,
 		view: View,
 	) {
@@ -350,7 +354,13 @@ impl State {
 			?view,
 			"Peer view change",
 		);
-		Self::unify_with_peer(&mut self.blocks, ctx, peer_id.clone(), view.clone()).await;
+		Self::unify_with_peer(
+			ctx,
+			metrics,
+			&mut self.blocks,
+			peer_id.clone(),
+			view.clone(),
+		).await;
 		let finalized_number = view.finalized_number;
 		let old_view = self.peer_views.insert(peer_id.clone(), view);
 		let old_finalized_number = old_view.map(|v| v.finalized_number).unwrap_or(0);
@@ -695,6 +705,7 @@ impl State {
 				tx,
 			))).await;
 
+			let timer = metrics.time_awaiting_approval_voting();
 			let result = match rx.await {
 				Ok(result) => result,
 				Err(_) => {
@@ -705,6 +716,7 @@ impl State {
 					return;
 				}
 			};
+			drop(timer);
 
 			tracing::trace!(
 				target: LOG_TARGET,
@@ -823,11 +835,14 @@ impl State {
 	}
 
 	async fn unify_with_peer(
-		entries: &mut HashMap<Hash, BlockEntry>,
 		ctx: &mut impl SubsystemContext<Message = ApprovalDistributionMessage>,
+		metrics: &Metrics,
+		entries: &mut HashMap<Hash, BlockEntry>,
 		peer_id: PeerId,
 		view: View,
 	) {
+		metrics.on_unify_with_peer();
+		let _timer = metrics.time_unify_with_peer();
 		let mut to_send = HashSet::new();
 
 		let view_finalized_number = view.finalized_number;
@@ -1067,6 +1082,11 @@ pub struct Metrics(Option<MetricsInner>);
 struct MetricsInner {
 	assignments_imported_total: prometheus::Counter<prometheus::U64>,
 	approvals_imported_total: prometheus::Counter<prometheus::U64>,
+	unified_with_peer_total: prometheus::Counter<prometheus::U64>,
+
+	time_unify_with_peer: prometheus::Histogram,
+	time_import_pending_now_known: prometheus::Histogram,
+	time_awaiting_approval_voting: prometheus::Histogram,
 }
 
 impl Metrics {
@@ -1081,6 +1101,24 @@ impl Metrics {
 			metrics.approvals_imported_total.inc();
 		}
 	}
+
+	fn on_unify_with_peer(&self) {
+		if let Some(metrics) = &self.0 {
+			metrics.unified_with_peer_total.inc();
+		}
+	}
+
+	fn time_unify_with_peer(&self) -> Option<metrics::prometheus::prometheus::HistogramTimer> {
+		self.0.as_ref().map(|metrics| metrics.time_unify_with_peer.start_timer())
+	}
+
+	fn time_import_pending_now_known(&self) -> Option<metrics::prometheus::prometheus::HistogramTimer> {
+		self.0.as_ref().map(|metrics| metrics.time_import_pending_now_known.start_timer())
+	}
+
+	fn time_awaiting_approval_voting(&self) -> Option<metrics::prometheus::prometheus::HistogramTimer> {
+		self.0.as_ref().map(|metrics| metrics.time_awaiting_approval_voting.start_timer())
+	}
 }
 
 impl metrics::Metrics for Metrics {
@@ -1100,6 +1138,40 @@ impl metrics::Metrics for Metrics {
 				)?,
 				registry,
 			)?,
+			unified_with_peer_total: prometheus::register(
+				prometheus::Counter::new(
+					"parachain_unified_with_peer_total",
+					"Number of times `unify_with_peer` is called.",
+				)?,
+				registry,
+			)?,
+			time_unify_with_peer: prometheus::register(
+				prometheus::Histogram::with_opts(
+					prometheus::HistogramOpts::new(
+						"parachain_time_unify_with_peer",
+						"Time spent within fn `unify_with_peer`.",
+					)
+				)?,
+				registry,
+			)?,
+			time_import_pending_now_known: prometheus::register(
+				prometheus::Histogram::with_opts(
+					prometheus::HistogramOpts::new(
+						"parachain_time_import_pending_now_known",
+						"Time spent on importing pending assignments and approvals.",
+					)
+				)?,
+				registry,
+			)?,
+			time_awaiting_approval_voting: prometheus::register(
+				prometheus::Histogram::with_opts(
+					prometheus::HistogramOpts::new(
+						"parachain_time_awaiting_approval_voting",
+						"Time spent awaiting a reply from the Approval Voting Subsystem.",
+					)
+				)?,
+				registry,
+			)?,
 		};
 		Ok(Metrics(Some(metrics)))
 	}