diff --git a/polkadot/Cargo.lock b/polkadot/Cargo.lock index 6d67edb14f..10dcd08ba4 100644 --- a/polkadot/Cargo.lock +++ b/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", diff --git a/polkadot/node/core/approval-voting/Cargo.toml b/polkadot/node/core/approval-voting/Cargo.toml index c924128806..84577e41df 100644 --- a/polkadot/node/core/approval-voting/Cargo.toml +++ b/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 } diff --git a/polkadot/node/core/approval-voting/src/import.rs b/polkadot/node/core/approval-voting/src/import.rs index 8fc4b90b38..e3e0a17c47 100644 --- a/polkadot/node/core/approval-voting/src/import.rs +++ b/polkadot/node/core/approval-voting/src/import.rs @@ -531,6 +531,8 @@ pub(crate) async fn handle_new_head( ) -> SubsystemResult> { // 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 = Vec::with_capacity(new_blocks.len()); let mut imported_candidates = Vec::with_capacity(new_blocks.len()); diff --git a/polkadot/node/core/approval-voting/src/lib.rs b/polkadot/node/core/approval-voting/src/lib.rs index 963f91563e..4e9346b1f2 100644 --- a/polkadot/node/core/approval-voting/src/lib.rs +++ b/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( 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, relay_block: Hash, candidate_hash: CandidateHash, + expected_tick: Tick, ) -> SubsystemResult> { + 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)?; diff --git a/polkadot/node/core/approval-voting/src/tests.rs b/polkadot/node/core/approval-voting/src/tests.rs index 7afe0a1a27..48aa76fc9d 100644 --- a/polkadot/node/core/approval-voting/src/tests.rs +++ b/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); diff --git a/polkadot/node/jaeger/Cargo.toml b/polkadot/node/jaeger/Cargo.toml index 86b1db3eda..32aa4491f9 100644 --- a/polkadot/node/jaeger/Cargo.toml +++ b/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 } diff --git a/polkadot/node/jaeger/src/lib.rs b/polkadot/node/jaeger/src/lib.rs index 1c9985da74..12fe3d20e6 100644 --- a/polkadot/node/jaeger/src/lib.rs +++ b/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.