diff --git a/node/core/backing/src/lib.rs b/node/core/backing/src/lib.rs index e783e565fd21..96fb71021dad 100644 --- a/node/core/backing/src/lib.rs +++ b/node/core/backing/src/lib.rs @@ -417,8 +417,9 @@ async fn validate_and_make_available( let v = { let _span = span.as_ref().map(|s| { s.child_builder("request-validation") - .with_pov(&pov) - .build() + .with_pov(&pov) + .with_para_id(candidate.descriptor().para_id) + .build() }); request_candidate_validation(&mut tx_from, candidate.descriptor.clone(), pov.clone()).await? }; @@ -611,6 +612,7 @@ impl CandidateBackingJob { async fn validate_and_second( &mut self, parent_span: &jaeger::Span, + root_span: &jaeger::Span, candidate: &CandidateReceipt, pov: Arc, ) -> Result<(), Error> { @@ -623,7 +625,13 @@ impl CandidateBackingJob { } let candidate_hash = candidate.hash(); - let span = self.get_unbacked_validation_child(parent_span, candidate_hash); + let mut span = self.get_unbacked_validation_child( + root_span, + candidate_hash, + candidate.descriptor().para_id, + ); + + span.as_mut().map(|s| s.add_follows_from(parent_span)); tracing::debug!( target: LOG_TARGET, @@ -745,17 +753,17 @@ impl CandidateBackingJob { Ok(summary) } - #[tracing::instrument(level = "trace", skip(self, span), fields(subsystem = LOG_TARGET))] - async fn process_msg(&mut self, span: &jaeger::Span, msg: CandidateBackingMessage) -> Result<(), Error> { + #[tracing::instrument(level = "trace", skip(self, root_span), fields(subsystem = LOG_TARGET))] + async fn process_msg(&mut self, root_span: &jaeger::Span, msg: CandidateBackingMessage) -> Result<(), Error> { match msg { - CandidateBackingMessage::Second(_relay_parent, candidate, pov) => { + CandidateBackingMessage::Second(relay_parent, candidate, pov) => { let _timer = self.metrics.time_process_second(); - let span = span.child_builder("second") + let span = root_span.child_builder("second") .with_stage(jaeger::Stage::CandidateBacking) .with_pov(&pov) .with_candidate(&candidate.hash()) - .with_relay_parent(&_relay_parent) + .with_relay_parent(&relay_parent) .build(); // Sanity check that candidate is from our assignment. @@ -772,20 +780,20 @@ impl CandidateBackingJob { if !self.issued_statements.contains(&candidate_hash) { let pov = Arc::new(pov); - self.validate_and_second(&span, &candidate, pov).await?; + self.validate_and_second(&span, &root_span, &candidate, pov).await?; } } } CandidateBackingMessage::Statement(_relay_parent, statement) => { let _timer = self.metrics.time_process_statement(); - let span = span.child_builder("statement") + let span = root_span.child_builder("statement") .with_stage(jaeger::Stage::CandidateBacking) .with_candidate(&statement.payload().candidate_hash()) .with_relay_parent(&_relay_parent) .build(); self.check_statement_signature(&statement)?; - match self.maybe_validate_and_import(&span, statement).await { + match self.maybe_validate_and_import(&span, &root_span, statement).await { Err(Error::ValidationFailed(_)) => return Ok(()), Err(e) => return Err(e), Ok(()) => (), @@ -865,12 +873,17 @@ impl CandidateBackingJob { async fn maybe_validate_and_import( &mut self, parent_span: &jaeger::Span, + root_span: &jaeger::Span, statement: SignedFullStatement, ) -> Result<(), Error> { if let Some(summary) = self.import_statement(&statement, parent_span).await? { if let Statement::Seconded(_) = statement.payload() { if Some(summary.group_id) == self.assignment { - let span = self.get_unbacked_validation_child(parent_span, summary.candidate); + let span = self.get_unbacked_validation_child( + root_span, + summary.candidate, + summary.group_id, + ); self.kick_off_validation_work(summary, span).await?; } @@ -910,11 +923,23 @@ impl CandidateBackingJob { } /// Insert or get the unbacked-span for the given candidate hash. - fn insert_or_get_unbacked_span(&mut self, parent_span: &jaeger::Span, hash: CandidateHash) -> Option<&jaeger::Span> { + fn insert_or_get_unbacked_span( + &mut self, + parent_span: &jaeger::Span, + hash: CandidateHash, + para_id: Option + ) -> Option<&jaeger::Span> { if !self.backed.contains(&hash) { // only add if we don't consider this backed. let span = self.unbacked_candidates.entry(hash).or_insert_with(|| { - parent_span.child_with_candidate("unbacked-candidate", &hash) + let s = parent_span.child_builder("unbacked-candidate").with_candidate(&hash); + let s = if let Some(para_id) = para_id { + s.with_para_id(para_id) + } else { + s + }; + + s.build() }); Some(span) } else { @@ -922,8 +947,13 @@ impl CandidateBackingJob { } } - fn get_unbacked_validation_child(&mut self, parent_span: &jaeger::Span, hash: CandidateHash) -> Option { - self.insert_or_get_unbacked_span(parent_span, hash) + fn get_unbacked_validation_child( + &mut self, + parent_span: &jaeger::Span, + hash: CandidateHash, + para_id: ParaId, + ) -> Option { + self.insert_or_get_unbacked_span(parent_span, hash, Some(para_id)) .map(|span| { span.child_builder("validation") .with_candidate(&hash) @@ -938,7 +968,7 @@ impl CandidateBackingJob { hash: CandidateHash, validator: ValidatorIndex, ) -> Option { - self.insert_or_get_unbacked_span(parent_span, hash).map(|span| { + self.insert_or_get_unbacked_span(parent_span, hash, None).map(|span| { span.child_builder("import-statement") .with_candidate(&hash) .with_validator_index(validator) @@ -1055,8 +1085,7 @@ impl util::JobTrait for CandidateBackingJob { }; drop(_span); - let _span = span.child("calc-validator-groups"); - + let mut assignments_span = span.child("compute-assignments"); let mut groups = HashMap::new(); @@ -1085,11 +1114,18 @@ impl util::JobTrait for CandidateBackingJob { }; let (assignment, required_collator) = match assignment { - None => (None, None), - Some((assignment, required_collator)) => (Some(assignment), required_collator), + None => { + assignments_span.add_string_tag("assigned", "false"); + (None, None) + } + Some((assignment, required_collator)) => { + assignments_span.add_string_tag("assigned", "true"); + assignments_span.add_para_id(assignment); + (Some(assignment), required_collator) + } }; - drop(_span); + drop(assignments_span); let _span = span.child("wait-for-job"); let (background_tx, background_rx) = mpsc::channel(16); diff --git a/node/core/candidate-selection/src/lib.rs b/node/core/candidate-selection/src/lib.rs index 47de46e9d7fa..a7cd459632f1 100644 --- a/node/core/candidate-selection/src/lib.rs +++ b/node/core/candidate-selection/src/lib.rs @@ -121,7 +121,7 @@ impl JobTrait for CandidateSelectionJob { let cores = try_runtime_api!(cores); drop(_span); - let _span = span.child_builder("find-assignment") + let _span = span.child_builder("validator-construction") .with_relay_parent(&relay_parent) .with_stage(jaeger::Stage::CandidateSelection) .build(); @@ -134,6 +134,11 @@ impl JobTrait for CandidateSelectionJob { Err(err) => return Err(Error::Util(err)), }; + let mut assignment_span = span.child_builder("find-assignment") + .with_relay_parent(&relay_parent) + .with_stage(jaeger::Stage::CandidateSelection) + .build(); + let mut assignment = None; for (idx, core) in cores.into_iter().enumerate() { @@ -151,11 +156,19 @@ impl JobTrait for CandidateSelectionJob { } let assignment = match assignment { - Some(assignment) => assignment, - None => return Ok(()), + Some(assignment) => { + assignment_span.add_string_tag("assigned", "true"); + assignment_span.add_para_id(assignment); + + assignment + } + None => { + assignment_span.add_string_tag("assigned", "false"); + return Ok(()) + } }; - drop(_span); + drop(assignment_span); CandidateSelectionJob::new(assignment, metrics, sender, receiver).run_loop(&span).await }.boxed() diff --git a/node/core/provisioner/src/lib.rs b/node/core/provisioner/src/lib.rs index 4a2aa096f3e2..64486bbf272f 100644 --- a/node/core/provisioner/src/lib.rs +++ b/node/core/provisioner/src/lib.rs @@ -198,10 +198,10 @@ impl ProvisioningJob { } } Some(ProvisionableData(_, data)) => { - let _span = span.child("provisionable-data"); + let span = span.child("provisionable-data"); let _timer = self.metrics.time_provisionable_data(); - self.note_provisionable_data(data); + self.note_provisionable_data(&span, data); } None => break, }, @@ -239,12 +239,14 @@ impl ProvisioningJob { } #[tracing::instrument(level = "trace", skip(self), fields(subsystem = LOG_TARGET))] - fn note_provisionable_data(&mut self, provisionable_data: ProvisionableData) { + fn note_provisionable_data(&mut self, span: &jaeger::Span, provisionable_data: ProvisionableData) { match provisionable_data { ProvisionableData::Bitfield(_, signed_bitfield) => { self.signed_bitfields.push(signed_bitfield) } ProvisionableData::BackedCandidate(backed_candidate) => { + let mut span = span.child("provisionable-backed"); + span.add_para_id(backed_candidate.descriptor().para_id); self.backed_candidates.push(backed_candidate) } _ => {} diff --git a/node/jaeger/src/lib.rs b/node/jaeger/src/lib.rs index 179734e84fe2..d376c4a7562f 100644 --- a/node/jaeger/src/lib.rs +++ b/node/jaeger/src/lib.rs @@ -45,7 +45,7 @@ //! ``` use sp_core::traits::SpawnNamed; -use polkadot_primitives::v1::{CandidateHash, Hash, PoV, ValidatorIndex, BlakeTwo256, HashT}; +use polkadot_primitives::v1::{CandidateHash, Hash, PoV, ValidatorIndex, BlakeTwo256, HashT, Id as ParaId}; use parity_scale_codec::Encode; use sc_network::PeerId; @@ -204,6 +204,14 @@ impl SpanBuilder { self.span.add_string_tag("candidate-hash", &format!("{:?}", candidate_hash.0)); self } + + /// Attach a para-id to the span. + #[inline(always)] + pub fn with_para_id(mut self, para_id: ParaId) -> Self { + self.span.add_para_id(para_id); + self + } + /// Attach a candidate stage. /// Should always come with a `CandidateHash`. #[inline(always)] @@ -305,6 +313,11 @@ impl Span { } } + /// Add the para-id to the span. + pub fn add_para_id(&mut self, para_id: ParaId) { + self.add_int_tag("para-id", u32::from(para_id) as i64); + } + /// Add an additional tag to the span. pub fn add_string_tag(&mut self, tag: &str, value: &str) { match self { diff --git a/node/network/collator-protocol/src/validator_side.rs b/node/network/collator-protocol/src/validator_side.rs index a3a8216e5fc7..7079d9c2de5c 100644 --- a/node/network/collator-protocol/src/validator_side.rs +++ b/node/network/collator-protocol/src/validator_side.rs @@ -137,6 +137,9 @@ struct CollationRequest { // The id of this request. request_id: RequestId, + + // A jaeger span corresponding to the lifetime of the request. + span: Option, } impl CollationRequest { @@ -147,11 +150,18 @@ impl CollationRequest { received, timeout, request_id, + mut span, } = self; match received.timeout(timeout).await { - None => Timeout(request_id), - Some(_) => Received(request_id), + None => { + span.as_mut().map(|s| s.add_string_tag("success", "false")); + Timeout(request_id) + } + Some(_) => { + span.as_mut().map(|s| s.add_string_tag("success", "true")); + Received(request_id) + } } } } @@ -466,6 +476,11 @@ where received: rx, timeout: state.request_timeout, request_id, + span: state.span_per_relay_parent.get(&relay_parent).map(|s| { + s.child_builder("collation-request") + .with_para_id(para_id) + .build() + }), }; state.requested_collations.insert((relay_parent, para_id.clone(), peer_id.clone()), request_id);