some initial spans for approval voting (#2525)

* some initial spans for approval voting

* add stage earlier

polkadot/Cargo.lock

@@ -5257,6 +5257,7 @@ dependencies = [
  "merlin",
  "parity-scale-codec",
  "parking_lot 0.11.1",
+ "polkadot-node-jaeger",
  "polkadot-node-primitives",
  "polkadot-node-subsystem",
  "polkadot-node-subsystem-test-helpers",
@@ -5464,6 +5465,7 @@ dependencies = [
  "lazy_static",
  "log",
  "mick-jaeger",
+ "parity-scale-codec",
  "parking_lot 0.11.1",
  "polkadot-primitives",
  "sc-network",

polkadot/node/core/approval-voting/Cargo.toml

@@ -21,6 +21,7 @@ polkadot-subsystem = { package = "polkadot-node-subsystem", path = "../../subsys
 polkadot-overseer = { path = "../../overseer" }
 polkadot-primitives = { path = "../../../primitives" }
 polkadot-node-primitives = { path = "../../primitives" }
+polkadot-node-jaeger = { path = "../../jaeger" }
 
 sc-client-api = { git = "https://github.com/paritytech/substrate", branch = "master", default-features = false }
 sc-keystore = { git = "https://github.com/paritytech/substrate", branch = "master", default-features = false }

polkadot/node/core/approval-voting/src/import.rs

@@ -531,6 +531,8 @@ pub(crate) async fn handle_new_head(
 ) -> SubsystemResult<Vec<BlockImportedCandidates>> {
 	// Update session info based on most recent head.
 
+	let mut span = polkadot_node_jaeger::hash_span(&head, "approval-checking-import");
+
 	let header = {
 		let (h_tx, h_rx) = oneshot::channel();
 		ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx).into()).await;
@@ -572,6 +574,10 @@ pub(crate) async fn handle_new_head(
 		.map_err(|e| SubsystemError::with_origin("approval-voting", e))
 		.await?;
 
+	span.add_string_tag("new-blocks", &format!("{}", new_blocks.len()));
+
+	if new_blocks.is_empty() { return Ok(Vec::new()) }
+
 	let mut approval_meta: Vec<BlockApprovalMeta> = Vec::with_capacity(new_blocks.len());
 	let mut imported_candidates = Vec::with_capacity(new_blocks.len());
 

polkadot/node/core/approval-voting/src/lib.rs

@@ -41,6 +41,7 @@ use polkadot_node_primitives::ValidationResult;
 use polkadot_node_primitives::approval::{
 	IndirectAssignmentCert, IndirectSignedApprovalVote, ApprovalVote, DelayTranche,
 };
+use polkadot_node_jaeger::Stage as JaegerStage;
 use parity_scale_codec::Encode;
 use sc_keystore::LocalKeystore;
 use sp_consensus_slots::Slot;
@@ -193,7 +194,7 @@ impl Wakeups {
 	}
 
 	// Returns the next wakeup. this future never returns if there are no wakeups.
-	async fn next(&mut self, clock: &(dyn Clock + Sync)) -> (Hash, CandidateHash) {
+	async fn next(&mut self, clock: &(dyn Clock + Sync)) -> (Tick, Hash, CandidateHash) {
 		match self.first() {
 			None => future::pending().await,
 			Some(tick) => {
@@ -210,7 +211,7 @@ impl Wakeups {
 
 						self.reverse_wakeups.remove(&(hash, candidate_hash));
 
-						(hash, candidate_hash)
+						(tick, hash, candidate_hash)
 					}
 				}
 			}
@@ -330,11 +331,12 @@ async fn run<C>(
 
 	loop {
 		let actions = futures::select! {
-			(woken_block, woken_candidate) = wakeups.next(&*state.clock).fuse() => {
+			(tick, woken_block, woken_candidate) = wakeups.next(&*state.clock).fuse() => {
 				process_wakeup(
 					&mut state,
 					woken_block,
 					woken_candidate,
+					tick,
 				)?
 			}
 			next_msg = ctx.recv().fuse() => {
@@ -576,6 +578,9 @@ async fn handle_approved_ancestor(
 
 	use bitvec::{order::Lsb0, vec::BitVec};
 
+	let mut span = polkadot_node_jaeger::hash_span(&target, "approved-ancestor");
+	span.add_stage(JaegerStage::ApprovalChecking);
+
 	let mut all_approved_max = None;
 
 	let target_number = {
@@ -592,6 +597,9 @@ async fn handle_approved_ancestor(
 
 	if target_number <= lower_bound { return Ok(None) }
 
+	span.add_string_tag("target-number", &format!("{}", target_number));
+	span.add_string_tag("target-hash", &format!("{}", target));
+
 	// request ancestors up to but not including the lower bound,
 	// as a vote on the lower bound is implied if we cannot find
 	// anything else.
@@ -672,6 +680,16 @@ async fn handle_approved_ancestor(
 		},
 	);
 
+	match all_approved_max {
+		Some((ref hash, ref number)) => {
+			span.add_string_tag("approved-number", &format!("{}", number));
+			span.add_string_tag("approved-hash", &format!("{:?}", hash));
+		}
+		None => {
+			span.add_string_tag("reached-lower-bound", "true");
+		}
+	}
+
 	Ok(all_approved_max)
 }
 
@@ -1131,7 +1149,18 @@ fn process_wakeup(
 	state: &State<impl DBReader>,
 	relay_block: Hash,
 	candidate_hash: CandidateHash,
+	expected_tick: Tick,
 ) -> SubsystemResult<Vec<Action>> {
+	let mut span = polkadot_node_jaeger::descriptor_span(
+		(relay_block, candidate_hash, expected_tick),
+		"process-approval-wakeup",
+	);
+
+	span.add_string_tag("relay-parent", &format!("{:?}", relay_block));
+	span.add_string_tag("candidate-hash", &format!("{:?}", candidate_hash));
+	span.add_string_tag("tick", &format!("{:?}", expected_tick));
+	span.add_stage(JaegerStage::ApprovalChecking);
+
 	let block_entry = state.db.load_block_entry(&relay_block)?;
 	let candidate_entry = state.db.load_candidate_entry(&candidate_hash)?;
 

polkadot/node/core/approval-voting/src/tests.rs

@@ -1228,9 +1228,9 @@ fn wakeups_next() {
 	let clock_aux = clock.clone();
 
 	let test_fut = Box::pin(async move {
-		assert_eq!(wakeups.next(&clock).await, (b_a, c_a));
-		assert_eq!(wakeups.next(&clock).await, (b_b, c_b));
-		assert_eq!(wakeups.next(&clock).await, (b_a, c_b));
+		assert_eq!(wakeups.next(&clock).await, (1, b_a, c_a));
+		assert_eq!(wakeups.next(&clock).await, (3, b_b, c_b));
+		assert_eq!(wakeups.next(&clock).await, (4, b_a, c_b));
 		assert!(wakeups.first().is_none());
 		assert!(wakeups.wakeups.is_empty());
 	});
@@ -1259,7 +1259,7 @@ fn wakeup_earlier_supersedes_later() {
 	let clock_aux = clock.clone();
 
 	let test_fut = Box::pin(async move {
-		assert_eq!(wakeups.next(&clock).await, (b_a, c_a));
+		assert_eq!(wakeups.next(&clock).await, (2, b_a, c_a));
 		assert!(wakeups.first().is_none());
 		assert!(wakeups.reverse_wakeups.is_empty());
 	});
@@ -1645,6 +1645,7 @@ fn process_wakeup_trigger_assignment_launch_approval() {
 		&state,
 		block_hash,
 		candidate_hash,
+		1,
 	).unwrap();
 
 	assert!(actions.is_empty());
@@ -1667,6 +1668,7 @@ fn process_wakeup_trigger_assignment_launch_approval() {
 		&state,
 		block_hash,
 		candidate_hash,
+		1,
 	).unwrap();
 
 	assert_eq!(actions.len(), 3);
@@ -1744,6 +1746,7 @@ fn process_wakeup_schedules_wakeup() {
 		&state,
 		block_hash,
 		candidate_hash,
+		1,
 	).unwrap();
 
 	assert_eq!(actions.len(), 1);

polkadot/node/jaeger/Cargo.toml

@@ -15,3 +15,4 @@ sc-network = { git = "https://github.com/paritytech/substrate", branch = "master
 sp-core = { git = "https://github.com/paritytech/substrate", branch = "master" }
 thiserror = "1.0.23"
 log = "0.4.13"
+parity-scale-codec = { version = "2.0.0", default-features = false }

polkadot/node/jaeger/src/lib.rs

@@ -45,7 +45,8 @@
 //! ```
 
 use sp_core::traits::SpawnNamed;
-use polkadot_primitives::v1::{CandidateHash, Hash, PoV, ValidatorIndex};
+use polkadot_primitives::v1::{CandidateHash, Hash, PoV, ValidatorIndex, BlakeTwo256, HashT};
+use parity_scale_codec::Encode;
 use sc_network::PeerId;
 
 use parking_lot::RwLock;
@@ -176,6 +177,7 @@ pub enum Stage {
 	AvailabilityDistribution = 5,
 	AvailabilityRecovery = 6,
 	BitfieldDistribution = 7,
+	ApprovalChecking = 8,
 	// Expand as needed, numbers should be ascending according to the stage
 	// through the inclusion pipeline, or according to the descriptions
 	// in [the path of a para chain block]
@@ -381,6 +383,15 @@ pub fn hash_span(hash: &Hash, span_name: &'static str) -> Span {
 	span
 }
 
+/// Creates a `Span` referring to the given descriptor, which should be unique.
+#[inline(always)]
+pub fn descriptor_span(descriptor: impl Encode, span_name: &'static str) -> Span {
+	INSTANCE.read_recursive().span(
+		|| { BlakeTwo256::hash_of(&descriptor) },
+		span_name,
+	).into()
+}
+
 /// Stateful convenience wrapper around [`mick_jaeger`].
 pub enum Jaeger {
 	/// Launched and operational state.