From 7786864f0fe304e12ef4f5856cf6a48799b67f2c Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 20 Dec 2022 12:48:32 +0000 Subject: [PATCH 01/82] Pass the PerLeafSpan as mutable reference to handle_new_head function --- node/core/approval-voting/src/import.rs | 5 +---- node/core/approval-voting/src/lib.rs | 4 ++-- node/jaeger/src/spans.rs | 7 +++++++ 3 files changed, 10 insertions(+), 6 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 2331b50b6bb1..4a2f6cf72496 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -327,15 +327,12 @@ pub(crate) async fn handle_new_head( db: &mut OverlayedBackend<'_, B>, head: Hash, finalized_number: &Option, + span: &mut jaeger::PerLeafSpan, ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; - - let mut span = jaeger::Span::new(head, "approval-checking-import"); - let header = { let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; - match h_rx.await? { Err(e) => { gum::debug!( diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 14fc87761c42..61c8ddb1d77e 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1140,10 +1140,10 @@ async fn handle_from_overseer( let actions = match x { FromOrchestra::Signal(OverseerSignal::ActiveLeaves(update)) => { let mut actions = Vec::new(); - if let Some(activated) = update.activated { let head = activated.hash; - match import::handle_new_head(ctx, state, db, head, &*last_finalized_height).await { + let mut span = jaeger::PerLeafSpan::new(activated.span, "approval-voting"); + match import::handle_new_head(ctx, state, db, head, &*last_finalized_height, &mut span).await { Err(e) => return Err(SubsystemError::with_origin("db", e)), Ok(block_imported_candidates) => { // Schedule wakeups for all imported candidates. diff --git a/node/jaeger/src/spans.rs b/node/jaeger/src/spans.rs index 56902571b88c..cf8f4c6474a3 100644 --- a/node/jaeger/src/spans.rs +++ b/node/jaeger/src/spans.rs @@ -135,6 +135,13 @@ impl std::ops::Deref for PerLeafSpan { } } +/// Returns a mutable reference to the child span. +impl std::ops::DerefMut for PerLeafSpan { + fn deref_mut(&mut self) -> &mut Self::Target { + &mut self.span + } +} + /// A helper to annotate the stage with a numerical value /// to ease the life of the tooling team creating viable /// statistical metrics for which stage of the inclusion From 538a7acb7f55bda34bc29efb72b55663b35794c2 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 20 Dec 2022 12:53:29 +0000 Subject: [PATCH 02/82] cargo +nightly fmt --all --- node/core/approval-voting/src/lib.rs | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 61c8ddb1d77e..56a29b0157ba 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1143,7 +1143,16 @@ async fn handle_from_overseer( if let Some(activated) = update.activated { let head = activated.hash; let mut span = jaeger::PerLeafSpan::new(activated.span, "approval-voting"); - match import::handle_new_head(ctx, state, db, head, &*last_finalized_height, &mut span).await { + match import::handle_new_head( + ctx, + state, + db, + head, + &*last_finalized_height, + &mut span, + ) + .await + { Err(e) => return Err(SubsystemError::with_origin("db", e)), Ok(block_imported_candidates) => { // Schedule wakeups for all imported candidates. From cfd424959432ce06e1f0f836e3418643284de3b3 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 21 Dec 2022 09:10:13 +0000 Subject: [PATCH 03/82] Add mock span for test --- node/core/approval-voting/src/import.rs | 22 +++++++++++++++++++--- node/core/approval-voting/src/lib.rs | 2 +- node/jaeger/src/spans.rs | 7 +++++++ 3 files changed, 27 insertions(+), 4 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 4a2f6cf72496..cd4eb72655ea 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -327,7 +327,7 @@ pub(crate) async fn handle_new_head( db: &mut OverlayedBackend<'_, B>, head: Hash, finalized_number: &Option, - span: &mut jaeger::PerLeafSpan, + span: Option<&mut jaeger::PerLeafSpan>, ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; let header = { @@ -388,7 +388,22 @@ pub(crate) async fn handle_new_head( .map_err(|e| SubsystemError::with_origin("approval-voting", e)) .await?; - span.add_uint_tag("new-blocks", new_blocks.len() as u64); + match span { + Some(span) => { + span.add_uint_tag("new-blocks", new_blocks.len() as u64); + gum::trace!{ + target: LOG_TARGET, + ?new_blocks, + "New blocks tag added to 'approval-voting' span", + } + }, + None => { + gum::trace!{ + target: LOG_TARGET, + "No 'approval-voting' span to tag" + } + } + } if new_blocks.is_empty() { return Ok(Vec::new()) @@ -1243,8 +1258,9 @@ pub(crate) mod tests { let test_fut = { Box::pin(async move { + let mut mock_span = jaeger::PerLeafSpan::default(); let mut overlay_db = OverlayedBackend::new(&db); - let result = handle_new_head(&mut ctx, &mut state, &mut overlay_db, hash, &Some(1)) + let result = handle_new_head(&mut ctx, &mut state, &mut overlay_db, hash, &Some(1), Some(&mut mock_span)) .await .unwrap(); diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 56a29b0157ba..6f6e2146086f 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1149,7 +1149,7 @@ async fn handle_from_overseer( db, head, &*last_finalized_height, - &mut span, + Some(&mut span), ) .await { diff --git a/node/jaeger/src/spans.rs b/node/jaeger/src/spans.rs index cf8f4c6474a3..d6e6d98365c1 100644 --- a/node/jaeger/src/spans.rs +++ b/node/jaeger/src/spans.rs @@ -126,6 +126,13 @@ impl PerLeafSpan { } } +/// Default implementation, can be handy in tests dependent upon a mocked PerLeafSpan. +impl std::default::Default for PerLeafSpan { + fn default() -> Self { + Self::new(Arc::new(Span::Disabled), "default") + } +} + /// Returns a reference to the child span. impl std::ops::Deref for PerLeafSpan { type Target = Span; From 926c7e6d6050628b1e13454fe2da0cfae74eb1aa Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 21 Dec 2022 09:12:58 +0000 Subject: [PATCH 04/82] cargo +nightly fmt --all --- node/core/approval-voting/src/import.rs | 19 +++++++++++++------ 1 file changed, 13 insertions(+), 6 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index cd4eb72655ea..2c9272b9e6c1 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -391,18 +391,18 @@ pub(crate) async fn handle_new_head( match span { Some(span) => { span.add_uint_tag("new-blocks", new_blocks.len() as u64); - gum::trace!{ + gum::trace! { target: LOG_TARGET, ?new_blocks, "New blocks tag added to 'approval-voting' span", } }, None => { - gum::trace!{ + gum::trace! { target: LOG_TARGET, "No 'approval-voting' span to tag" } - } + }, } if new_blocks.is_empty() { @@ -1260,9 +1260,16 @@ pub(crate) mod tests { Box::pin(async move { let mut mock_span = jaeger::PerLeafSpan::default(); let mut overlay_db = OverlayedBackend::new(&db); - let result = handle_new_head(&mut ctx, &mut state, &mut overlay_db, hash, &Some(1), Some(&mut mock_span)) - .await - .unwrap(); + let result = handle_new_head( + &mut ctx, + &mut state, + &mut overlay_db, + hash, + &Some(1), + Some(&mut mock_span), + ) + .await + .unwrap(); let write_ops = overlay_db.into_write_ops(); db.write(write_ops).unwrap(); From dbd38baf558b00472c6e70be3857d2ced9b1f6e1 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 21 Dec 2022 14:27:41 +0000 Subject: [PATCH 05/82] add new-blocks-hashes to span --- node/core/approval-voting/src/import.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 2c9272b9e6c1..ca4830895411 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -390,12 +390,13 @@ pub(crate) async fn handle_new_head( match span { Some(span) => { - span.add_uint_tag("new-blocks", new_blocks.len() as u64); + span.add_uint_tag("new-blocks-count", new_blocks.len() as u64); + span.add_string_tag("new-blocks-hashes", format!("{:?}", new_blocks)); gum::trace! { target: LOG_TARGET, ?new_blocks, "New blocks tag added to 'approval-voting' span", - } + }; }, None => { gum::trace! { From baba9073faab8a013f33a425cd18d1c1c876e7cf Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 10:13:56 +0000 Subject: [PATCH 06/82] ref span in match statement, set span to disabled if not passed --- node/core/approval-voting/src/import.rs | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index ca4830895411..a9296b3d886a 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -330,7 +330,14 @@ pub(crate) async fn handle_new_head( span: Option<&mut jaeger::PerLeafSpan>, ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; + + let handle_new_head_span = match span { + Some(ref span) => span.child("handle-new-head"), + None => jaeger::Span::Disabled + }; + let header = { + let mut get_header_span = handle_new_head_span.child("get-header"); let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; match h_rx.await? { @@ -340,14 +347,20 @@ pub(crate) async fn handle_new_head( "Chain API subsystem temporarily unreachable {}", e, ); - + // May be a better way of handling errors here. + get_header_span.add_string_tag("error", "Chain API unreachable"); return Ok(Vec::new()) }, Ok(None) => { gum::warn!(target: LOG_TARGET, "Missing header for new head {}", head); + // May be a better way of handling warnings here. + get_header_span.add_string_tag("warn", "Missing header"); return Ok(Vec::new()) }, - Ok(Some(h)) => h, + Ok(Some(h)) => { + get_header_span.add_string_tag("header", format!("{:?}", h)); + h + }, } }; From 0202014b5e65d8a65aa795c11f49b902c6540576 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 10:22:53 +0000 Subject: [PATCH 07/82] remove second match clause, make handle_new_head_span mutable --- node/core/approval-voting/src/import.rs | 21 +++------------------ 1 file changed, 3 insertions(+), 18 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index a9296b3d886a..614fb25db371 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -331,7 +331,7 @@ pub(crate) async fn handle_new_head( ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; - let handle_new_head_span = match span { + let mut handle_new_head_span = match span { Some(ref span) => span.child("handle-new-head"), None => jaeger::Span::Disabled }; @@ -401,23 +401,8 @@ pub(crate) async fn handle_new_head( .map_err(|e| SubsystemError::with_origin("approval-voting", e)) .await?; - match span { - Some(span) => { - span.add_uint_tag("new-blocks-count", new_blocks.len() as u64); - span.add_string_tag("new-blocks-hashes", format!("{:?}", new_blocks)); - gum::trace! { - target: LOG_TARGET, - ?new_blocks, - "New blocks tag added to 'approval-voting' span", - }; - }, - None => { - gum::trace! { - target: LOG_TARGET, - "No 'approval-voting' span to tag" - } - }, - } + handle_new_head_span.add_uint_tag("new-blocks-count", new_blocks.len() as u64); + handle_new_head_span.add_string_tag("new-blocks-hashes", format!("{:?}", new_blocks)); if new_blocks.is_empty() { return Ok(Vec::new()) From f51e2c19abc91d2b1f498fc7f929ee90d97bd627 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 10:38:32 +0000 Subject: [PATCH 08/82] cargo +nightly fmt --all --- node/core/approval-voting/src/import.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 614fb25db371..1402d0860f6a 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -330,10 +330,10 @@ pub(crate) async fn handle_new_head( span: Option<&mut jaeger::PerLeafSpan>, ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; - + let mut handle_new_head_span = match span { Some(ref span) => span.child("handle-new-head"), - None => jaeger::Span::Disabled + None => jaeger::Span::Disabled, }; let header = { From e7aa6de46e95d0ce6205f80f74d9b3ac66944ac3 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 10:44:19 +0000 Subject: [PATCH 09/82] improve tag on error and warning --- node/core/approval-voting/src/import.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 1402d0860f6a..8ca50e6ac10e 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -348,13 +348,13 @@ pub(crate) async fn handle_new_head( e, ); // May be a better way of handling errors here. - get_header_span.add_string_tag("error", "Chain API unreachable"); + get_header_span.add_string_tag("error", format!("{:?}", e)); return Ok(Vec::new()) }, Ok(None) => { gum::warn!(target: LOG_TARGET, "Missing header for new head {}", head); // May be a better way of handling warnings here. - get_header_span.add_string_tag("warn", "Missing header"); + get_header_span.add_string_tag("warn", format!("Missing header for new head {}", head)); return Ok(Vec::new()) }, Ok(Some(h)) => { From 20bd43a41d16df27cd6d68efa735699576b5ce6f Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 11:55:36 +0000 Subject: [PATCH 10/82] add imported blocks and info span --- node/core/approval-voting/src/import.rs | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 8ca50e6ac10e..649a2765f663 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -402,7 +402,6 @@ pub(crate) async fn handle_new_head( .await?; handle_new_head_span.add_uint_tag("new-blocks-count", new_blocks.len() as u64); - handle_new_head_span.add_string_tag("new-blocks-hashes", format!("{:?}", new_blocks)); if new_blocks.is_empty() { return Ok(Vec::new()) @@ -413,6 +412,7 @@ pub(crate) async fn handle_new_head( // `determine_new_blocks` gives us a vec in backwards order. we want to move forwards. let imported_blocks_and_info = { + let mut imported_blocks_and_info_span = handle_new_head_span.child("imported-blocks-and-info"); let mut imported_blocks_and_info = Vec::with_capacity(new_blocks.len()); for (block_hash, block_header) in new_blocks.into_iter().rev() { let env = ImportedBlockInfoEnv { @@ -422,7 +422,10 @@ pub(crate) async fn handle_new_head( }; match imported_block_info(ctx, env, block_hash, &block_header).await { - Ok(i) => imported_blocks_and_info.push((block_hash, block_header, i)), + Ok(i) => { + imported_blocks_and_info.push((block_hash, block_header, i)); + imported_blocks_and_info_span.add_string_tag("block-hash", format!("{:?}", block_hash)); + }, Err(error) => { // It's possible that we've lost a race with finality. let (tx, rx) = oneshot::channel(); From eb283d9e53f7cc2d9abdcfcf47d17c7bdd0faab4 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 14:33:30 +0000 Subject: [PATCH 11/82] cargo +nightly fmt --all --- node/core/approval-voting/src/import.rs | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 649a2765f663..9088dd9bc9a2 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -354,7 +354,8 @@ pub(crate) async fn handle_new_head( Ok(None) => { gum::warn!(target: LOG_TARGET, "Missing header for new head {}", head); // May be a better way of handling warnings here. - get_header_span.add_string_tag("warn", format!("Missing header for new head {}", head)); + get_header_span + .add_string_tag("warn", format!("Missing header for new head {}", head)); return Ok(Vec::new()) }, Ok(Some(h)) => { @@ -412,7 +413,8 @@ pub(crate) async fn handle_new_head( // `determine_new_blocks` gives us a vec in backwards order. we want to move forwards. let imported_blocks_and_info = { - let mut imported_blocks_and_info_span = handle_new_head_span.child("imported-blocks-and-info"); + let mut imported_blocks_and_info_span = + handle_new_head_span.child("imported-blocks-and-info"); let mut imported_blocks_and_info = Vec::with_capacity(new_blocks.len()); for (block_hash, block_header) in new_blocks.into_iter().rev() { let env = ImportedBlockInfoEnv { @@ -424,7 +426,8 @@ pub(crate) async fn handle_new_head( match imported_block_info(ctx, env, block_hash, &block_header).await { Ok(i) => { imported_blocks_and_info.push((block_hash, block_header, i)); - imported_blocks_and_info_span.add_string_tag("block-hash", format!("{:?}", block_hash)); + imported_blocks_and_info_span + .add_string_tag("block-hash", format!("{:?}", block_hash)); }, Err(error) => { // It's possible that we've lost a race with finality. From 2506e147c014bbd14582c5119fb1464ec131418f Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 14:54:33 +0000 Subject: [PATCH 12/82] Improve error for imported_blocks_and_info trace --- node/core/approval-voting/src/import.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 9088dd9bc9a2..0ca80987671c 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -449,6 +449,8 @@ pub(crate) async fn handle_new_head( (block_hash, block_header.number), error, ); + imported_blocks_and_info_span + .add_string_tag("error", format!("Skipping chain: unable to gather info about imported block: {}, due to {:?}", block_hash, error)); } return Ok(Vec::new()) From 67838d9714c57db7c49c31c5b341216dc519c102 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 17:19:23 +0000 Subject: [PATCH 13/82] format tags on get_header_span --- node/core/approval-voting/src/import.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 0ca80987671c..4d196d1ed85d 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -359,7 +359,10 @@ pub(crate) async fn handle_new_head( return Ok(Vec::new()) }, Ok(Some(h)) => { - get_header_span.add_string_tag("header", format!("{:?}", h)); + get_header_span.add_string_tag("parent-hash", format!("{:?}", h.parent_hash)); + get_header_span.add_string_tag("number", format!("{:?}", h.number)); + get_header_span.add_string_tag("state_root", format!("{:?}", h.state_root)); + get_header_span.add_string_tag("extrinsics_root", format!("{:?}", h.extrinsics_root)); h }, } From 59ecc9e6a6dd2af6c07867757493470b60bceffe Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 17:24:05 +0000 Subject: [PATCH 14/82] add lost-to-finality tag --- node/core/approval-voting/src/import.rs | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 4d196d1ed85d..0404564a83df 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -439,7 +439,11 @@ pub(crate) async fn handle_new_head( .await; let lost_to_finality = match rx.await { - Ok(Ok(Some(h))) if h != block_hash => true, + Ok(Ok(Some(h))) if h != block_hash => { + imported_blocks_and_info_span + .add_string_tag("lost-to-finality", format!("{:?}", true); + true + }, _ => false, }; @@ -453,7 +457,7 @@ pub(crate) async fn handle_new_head( error, ); imported_blocks_and_info_span - .add_string_tag("error", format!("Skipping chain: unable to gather info about imported block: {}, due to {:?}", block_hash, error)); + .add_string_tag("error", format!("Skipping chain: unable to gather info about imported block with hash {} due to {:?}", block_hash, error)); } return Ok(Vec::new()) From c799dc487e266c6455228afbbbaa2eb72da4552c Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 22 Dec 2022 17:26:01 +0000 Subject: [PATCH 15/82] add missing bracket --- node/core/approval-voting/src/import.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 0404564a83df..56fd7fcb896c 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -441,7 +441,7 @@ pub(crate) async fn handle_new_head( let lost_to_finality = match rx.await { Ok(Ok(Some(h))) if h != block_hash => { imported_blocks_and_info_span - .add_string_tag("lost-to-finality", format!("{:?}", true); + .add_string_tag("lost-to-finality", format!("{:?}", true)); true }, _ => false, From 241bc1844ef8e7923b2295c053a2da2a9bec36cc Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 3 Jan 2023 11:52:17 +0000 Subject: [PATCH 16/82] - Add bitfield child span - Add block db insertion span --- node/core/approval-voting/src/import.rs | 34 ++++++++++++++++++++++--- 1 file changed, 31 insertions(+), 3 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 56fd7fcb896c..334aa04cfb65 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -362,7 +362,8 @@ pub(crate) async fn handle_new_head( get_header_span.add_string_tag("parent-hash", format!("{:?}", h.parent_hash)); get_header_span.add_string_tag("number", format!("{:?}", h.number)); get_header_span.add_string_tag("state_root", format!("{:?}", h.state_root)); - get_header_span.add_string_tag("extrinsics_root", format!("{:?}", h.extrinsics_root)); + get_header_span + .add_string_tag("extrinsics_root", format!("{:?}", h.extrinsics_root)); h }, } @@ -473,8 +474,9 @@ pub(crate) async fn handle_new_head( imported_blocks = imported_blocks_and_info.len(), "Inserting imported blocks into database" ); - for (block_hash, block_header, imported_block_info) in imported_blocks_and_info { + let mut block_insertion_span = handle_new_head_span.child("block-db-insertion"); + let ImportedBlockInfo { included_candidates, session_index, @@ -490,6 +492,7 @@ pub(crate) async fn handle_new_head( .as_ref() .and_then(|s| s.session_info(session_index)) .expect("imported_block_info requires session info to be available; qed"); + block_insertion_span.add_string_tag("session-info", format!("{:?}", session_info)); let (block_tick, no_show_duration) = { let block_tick = slot_number_to_tick(state.slot_duration_millis, slot); @@ -499,12 +502,18 @@ pub(crate) async fn handle_new_head( ); (block_tick, no_show_duration) }; + block_insertion_span.add_uint_tag("block-tick", block_tick); + block_insertion_span.add_uint_tag("no-show-duration", no_show_duration); + let needed_approvals = session_info.needed_approvals; let validator_group_lens: Vec = session_info.validator_groups.iter().map(|v| v.len()).collect(); // insta-approve candidates on low-node testnets: // cf. https://github.com/paritytech/polkadot/issues/2411 let num_candidates = included_candidates.len(); + let mut bitfield_span = block_insertion_span.child("bitfield"); + bitfield_span.add_uint_tag("num-candidates", num_candidates); + bitfield_span.add_uint_tag("needed-approvals", needed_approvals); let approved_bitfield = { if needed_approvals == 0 { gum::debug!( @@ -512,15 +521,29 @@ pub(crate) async fn handle_new_head( block_hash = ?block_hash, "Insta-approving all candidates", ); + bitfield_span.add_string_tag( + "approved", + format!("{:?}, insta-approval as needed approvals is set to 0.", true), + ); bitvec::bitvec![u8, BitOrderLsb0; 1; num_candidates] } else { let mut result = bitvec::bitvec![u8, BitOrderLsb0; 0; num_candidates]; for (i, &(_, _, _, backing_group)) in included_candidates.iter().enumerate() { let backing_group_size = validator_group_lens.get(backing_group.0 as usize).copied().unwrap_or(0); + + bitfield_span.add_uint_tag("backing-group-size", backing_group_size); let needed_approvals = usize::try_from(needed_approvals).expect("usize is at least u32; qed"); if n_validators.saturating_sub(backing_group_size) < needed_approvals { + bitfield_span.add_string_tag( + "update-bitfield", + format!( + "approving bitfield {:?} as {:?} less than needed approvals", + i, + n_validators.saturating_sub(backing_group_size) + ), + ); result.set(i, true); } } @@ -532,14 +555,19 @@ pub(crate) async fn handle_new_head( result.count_ones(), result.len(), ); + bitfield_span.add_string_tag( + "approved", + format!("{:?}, insta-approval as number of validators too low.", true), + ); } - result } }; // If all bits are already set, then send an approve message. if approved_bitfield.count_ones() == approved_bitfield.len() { + bitfield_span + .add_string_tag("approved", format!("{:?}, all bitfields are set to 1.", true)); ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; } From a478d34e4f63060fb1ff8df1c91ee04d8e9e39a5 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 3 Jan 2023 12:14:34 +0000 Subject: [PATCH 17/82] - fix update-bitfield span tag --- node/core/approval-voting/src/import.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 334aa04cfb65..fd70fd962a59 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -539,9 +539,9 @@ pub(crate) async fn handle_new_head( bitfield_span.add_string_tag( "update-bitfield", format!( - "approving bitfield {:?} as {:?} less than needed approvals", + "updating bitfield index {:?} as validators less backing group size (which equals {:?}) is less than the number of needed approvals ({:?}).", i, - n_validators.saturating_sub(backing_group_size) + n_validators.saturating_sub(backing_group_size), ), ); result.set(i, true); From 3251f88285e8015055eae07ec2b040e049c306b2 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 3 Jan 2023 12:25:31 +0000 Subject: [PATCH 18/82] - Fix type conversion to u64 - Add missing argument --- node/core/approval-voting/src/import.rs | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index fd70fd962a59..5b83730a2268 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -512,8 +512,8 @@ pub(crate) async fn handle_new_head( // cf. https://github.com/paritytech/polkadot/issues/2411 let num_candidates = included_candidates.len(); let mut bitfield_span = block_insertion_span.child("bitfield"); - bitfield_span.add_uint_tag("num-candidates", num_candidates); - bitfield_span.add_uint_tag("needed-approvals", needed_approvals); + bitfield_span.add_uint_tag("num-candidates", num_candidates.try_into().unwrap()); + bitfield_span.add_uint_tag("needed-approvals", needed_approvals.into()); let approved_bitfield = { if needed_approvals == 0 { gum::debug!( @@ -532,16 +532,17 @@ pub(crate) async fn handle_new_head( let backing_group_size = validator_group_lens.get(backing_group.0 as usize).copied().unwrap_or(0); - bitfield_span.add_uint_tag("backing-group-size", backing_group_size); + bitfield_span.add_uint_tag("backing-group-size", backing_group_size.try_into().unwrap()); let needed_approvals = usize::try_from(needed_approvals).expect("usize is at least u32; qed"); if n_validators.saturating_sub(backing_group_size) < needed_approvals { bitfield_span.add_string_tag( "update-bitfield", format!( - "updating bitfield index {:?} as validators less backing group size (which equals {:?}) is less than the number of needed approvals ({:?}).", + "updated bitfield index {:?} as validators less backing group size (which equals {:?}) is less than the number of needed approvals ({:?}).", i, n_validators.saturating_sub(backing_group_size), + needed_approvals ), ); result.set(i, true); From c5eb91049d26a53f19cfff1862bdd1aaa44aac5b Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 3 Jan 2023 13:29:18 +0000 Subject: [PATCH 19/82] - Cargo fmt --- node/core/approval-voting/src/import.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 5b83730a2268..0404004a98c6 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -532,7 +532,8 @@ pub(crate) async fn handle_new_head( let backing_group_size = validator_group_lens.get(backing_group.0 as usize).copied().unwrap_or(0); - bitfield_span.add_uint_tag("backing-group-size", backing_group_size.try_into().unwrap()); + bitfield_span + .add_uint_tag("backing-group-size", backing_group_size.try_into().unwrap()); let needed_approvals = usize::try_from(needed_approvals).expect("usize is at least u32; qed"); if n_validators.saturating_sub(backing_group_size) < needed_approvals { From 582da100ea9b2540103f4157f7a4850959fac793 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 3 Jan 2023 16:32:22 +0000 Subject: [PATCH 20/82] - Test add_follows_from --- node/core/approval-voting/src/import.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 0404004a98c6..e015d4f9d12a 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -337,7 +337,7 @@ pub(crate) async fn handle_new_head( }; let header = { - let mut get_header_span = handle_new_head_span.child("get-header"); + let mut get_header_span = handle_new_head_span.add_follows_from("get-header"); let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; match h_rx.await? { From a81a7fcceb96e44e3c1cc7d36b7a0898f4e543c6 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 3 Jan 2023 16:50:32 +0000 Subject: [PATCH 21/82] - Revert as relationship between spans not working correctly --- node/core/approval-voting/src/import.rs | 10 +--------- 1 file changed, 1 insertion(+), 9 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index e015d4f9d12a..faa4b60831d7 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -337,7 +337,7 @@ pub(crate) async fn handle_new_head( }; let header = { - let mut get_header_span = handle_new_head_span.add_follows_from("get-header"); + let mut get_header_span = handle_new_head_span.child("get-header"); let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; match h_rx.await? { @@ -417,8 +417,6 @@ pub(crate) async fn handle_new_head( // `determine_new_blocks` gives us a vec in backwards order. we want to move forwards. let imported_blocks_and_info = { - let mut imported_blocks_and_info_span = - handle_new_head_span.child("imported-blocks-and-info"); let mut imported_blocks_and_info = Vec::with_capacity(new_blocks.len()); for (block_hash, block_header) in new_blocks.into_iter().rev() { let env = ImportedBlockInfoEnv { @@ -430,8 +428,6 @@ pub(crate) async fn handle_new_head( match imported_block_info(ctx, env, block_hash, &block_header).await { Ok(i) => { imported_blocks_and_info.push((block_hash, block_header, i)); - imported_blocks_and_info_span - .add_string_tag("block-hash", format!("{:?}", block_hash)); }, Err(error) => { // It's possible that we've lost a race with finality. @@ -441,8 +437,6 @@ pub(crate) async fn handle_new_head( let lost_to_finality = match rx.await { Ok(Ok(Some(h))) if h != block_hash => { - imported_blocks_and_info_span - .add_string_tag("lost-to-finality", format!("{:?}", true)); true }, _ => false, @@ -457,8 +451,6 @@ pub(crate) async fn handle_new_head( (block_hash, block_header.number), error, ); - imported_blocks_and_info_span - .add_string_tag("error", format!("Skipping chain: unable to gather info about imported block with hash {} due to {:?}", block_hash, error)); } return Ok(Vec::new()) From bec69fc2afc802e186ab54a2a96ca73ba0ac22ea Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 3 Jan 2023 17:34:12 +0000 Subject: [PATCH 22/82] - use drop to test if parent-child relationship can be re-established --- node/core/approval-voting/src/import.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index faa4b60831d7..3e3d2ae2b12d 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -335,9 +335,8 @@ pub(crate) async fn handle_new_head( Some(ref span) => span.child("handle-new-head"), None => jaeger::Span::Disabled, }; - + let mut get_header_span = handle_new_head_span.child("get-header"); let header = { - let mut get_header_span = handle_new_head_span.child("get-header"); let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; match h_rx.await? { @@ -368,6 +367,7 @@ pub(crate) async fn handle_new_head( }, } }; + drop(get_header_span); // Update session info based on most recent head. match state.cache_session_info_for_head(ctx, head).await { From c4e6f4f9e1dd6e389a7b9baac391e83b780f8f4f Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 09:25:24 +0000 Subject: [PATCH 23/82] - remove bitfield span, check if parent-child relationship can be reestablished --- node/core/approval-voting/src/import.rs | 29 ++----------------------- 1 file changed, 2 insertions(+), 27 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 3e3d2ae2b12d..9f7cfa864c1e 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -335,8 +335,9 @@ pub(crate) async fn handle_new_head( Some(ref span) => span.child("handle-new-head"), None => jaeger::Span::Disabled, }; - let mut get_header_span = handle_new_head_span.child("get-header"); + let header = { + let mut get_header_span = handle_new_head_span.child("get-header"); let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; match h_rx.await? { @@ -367,7 +368,6 @@ pub(crate) async fn handle_new_head( }, } }; - drop(get_header_span); // Update session info based on most recent head. match state.cache_session_info_for_head(ctx, head).await { @@ -467,8 +467,6 @@ pub(crate) async fn handle_new_head( "Inserting imported blocks into database" ); for (block_hash, block_header, imported_block_info) in imported_blocks_and_info { - let mut block_insertion_span = handle_new_head_span.child("block-db-insertion"); - let ImportedBlockInfo { included_candidates, session_index, @@ -484,7 +482,6 @@ pub(crate) async fn handle_new_head( .as_ref() .and_then(|s| s.session_info(session_index)) .expect("imported_block_info requires session info to be available; qed"); - block_insertion_span.add_string_tag("session-info", format!("{:?}", session_info)); let (block_tick, no_show_duration) = { let block_tick = slot_number_to_tick(state.slot_duration_millis, slot); @@ -494,8 +491,6 @@ pub(crate) async fn handle_new_head( ); (block_tick, no_show_duration) }; - block_insertion_span.add_uint_tag("block-tick", block_tick); - block_insertion_span.add_uint_tag("no-show-duration", no_show_duration); let needed_approvals = session_info.needed_approvals; let validator_group_lens: Vec = @@ -504,8 +499,6 @@ pub(crate) async fn handle_new_head( // cf. https://github.com/paritytech/polkadot/issues/2411 let num_candidates = included_candidates.len(); let mut bitfield_span = block_insertion_span.child("bitfield"); - bitfield_span.add_uint_tag("num-candidates", num_candidates.try_into().unwrap()); - bitfield_span.add_uint_tag("needed-approvals", needed_approvals.into()); let approved_bitfield = { if needed_approvals == 0 { gum::debug!( @@ -513,31 +506,15 @@ pub(crate) async fn handle_new_head( block_hash = ?block_hash, "Insta-approving all candidates", ); - bitfield_span.add_string_tag( - "approved", - format!("{:?}, insta-approval as needed approvals is set to 0.", true), - ); bitvec::bitvec![u8, BitOrderLsb0; 1; num_candidates] } else { let mut result = bitvec::bitvec![u8, BitOrderLsb0; 0; num_candidates]; for (i, &(_, _, _, backing_group)) in included_candidates.iter().enumerate() { let backing_group_size = validator_group_lens.get(backing_group.0 as usize).copied().unwrap_or(0); - - bitfield_span - .add_uint_tag("backing-group-size", backing_group_size.try_into().unwrap()); let needed_approvals = usize::try_from(needed_approvals).expect("usize is at least u32; qed"); if n_validators.saturating_sub(backing_group_size) < needed_approvals { - bitfield_span.add_string_tag( - "update-bitfield", - format!( - "updated bitfield index {:?} as validators less backing group size (which equals {:?}) is less than the number of needed approvals ({:?}).", - i, - n_validators.saturating_sub(backing_group_size), - needed_approvals - ), - ); result.set(i, true); } } @@ -560,8 +537,6 @@ pub(crate) async fn handle_new_head( // If all bits are already set, then send an approve message. if approved_bitfield.count_ones() == approved_bitfield.len() { - bitfield_span - .add_string_tag("approved", format!("{:?}, all bitfields are set to 1.", true)); ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; } From 123a5a50809d69bfde4ec92f63c4e9cf571d7050 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 09:38:16 +0000 Subject: [PATCH 24/82] - Remove dangling bitfield span which is not used, to see if parent-child relationship can be re-established --- node/core/approval-voting/src/import.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 9f7cfa864c1e..25da42648461 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -498,7 +498,6 @@ pub(crate) async fn handle_new_head( // insta-approve candidates on low-node testnets: // cf. https://github.com/paritytech/polkadot/issues/2411 let num_candidates = included_candidates.len(); - let mut bitfield_span = block_insertion_span.child("bitfield"); let approved_bitfield = { if needed_approvals == 0 { gum::debug!( From e8a4c70036bf28277a9c653c9204509b278bcdf5 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 10:02:58 +0000 Subject: [PATCH 25/82] Another dangling bitfield span --- node/core/approval-voting/src/import.rs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 25da42648461..54daed267a28 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -525,10 +525,6 @@ pub(crate) async fn handle_new_head( result.count_ones(), result.len(), ); - bitfield_span.add_string_tag( - "approved", - format!("{:?}, insta-approval as number of validators too low.", true), - ); } result } From 6c4636a5b0e4d460753b325f71e9e3463d1d1d08 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 10:03:26 +0000 Subject: [PATCH 26/82] cargo fmt --- node/core/approval-voting/src/import.rs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 54daed267a28..a4471a72a870 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -436,9 +436,7 @@ pub(crate) async fn handle_new_head( .await; let lost_to_finality = match rx.await { - Ok(Ok(Some(h))) if h != block_hash => { - true - }, + Ok(Ok(Some(h))) if h != block_hash => true, _ => false, }; From f477139b0ead3564944f5b54e7afcd4340088c87 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 12:54:03 +0000 Subject: [PATCH 27/82] - add imported blocks and info span - add candidate span per candidate --- node/core/approval-voting/src/import.rs | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index a4471a72a870..03a6d503c86f 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -417,8 +417,12 @@ pub(crate) async fn handle_new_head( // `determine_new_blocks` gives us a vec in backwards order. we want to move forwards. let imported_blocks_and_info = { + let mut imported_blocks_and_info_span = + handle_new_head_span.child("imported-blocks-and-info"); + imported_blocks_and_info_span.add_uint_tag("new-blocks-count", new_blocks.len() as u64); let mut imported_blocks_and_info = Vec::with_capacity(new_blocks.len()); for (block_hash, block_header) in new_blocks.into_iter().rev() { + let mut candidate_span = imported_blocks_and_info_span.child("candidate"); let env = ImportedBlockInfoEnv { session_window: &state.session_window, assignment_criteria: &*state.assignment_criteria, @@ -428,8 +432,20 @@ pub(crate) async fn handle_new_head( match imported_block_info(ctx, env, block_hash, &block_header).await { Ok(i) => { imported_blocks_and_info.push((block_hash, block_header, i)); + candidate_span.with_candidate(candidate_hash); + candidate_span + .add_string_tag("parent-hash", format!("{:?}", block_header.parent_hash)); + candidate_span.add_string_tag("number", format!("{:?}", block_header.number)); + candidate_span + .add_string_tag("state-root", format!("{:?}", block_header.state_root)); + candidate_span.add_string_tag( + "extrinsics-root", + format!("{:?}", block_header.extrinsics_root), + ); }, Err(error) => { + candidate_span + .add_string_tag("imported-block-info-error", format!("{:?}", error)); // It's possible that we've lost a race with finality. let (tx, rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::FinalizedBlockHash(block_header.number, tx)) From fd32807d1cdc21b15776474f7243640df1d67b69 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 13:10:03 +0000 Subject: [PATCH 28/82] add tags before moving block_header to push scope --- node/core/approval-voting/src/import.rs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 03a6d503c86f..f2c63fad7ac7 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -431,17 +431,17 @@ pub(crate) async fn handle_new_head( match imported_block_info(ctx, env, block_hash, &block_header).await { Ok(i) => { - imported_blocks_and_info.push((block_hash, block_header, i)); - candidate_span.with_candidate(candidate_hash); + candidate_span.add_string_tag("candidate-hash", format!("{:?}", &block_hash)); candidate_span - .add_string_tag("parent-hash", format!("{:?}", block_header.parent_hash)); - candidate_span.add_string_tag("number", format!("{:?}", block_header.number)); + .add_string_tag("parent-hash", format!("{:?}", &block_header.parent_hash)); + candidate_span.add_string_tag("number", format!("{:?}", &block_header.number)); candidate_span - .add_string_tag("state-root", format!("{:?}", block_header.state_root)); + .add_string_tag("state-root", format!("{:?}", &block_header.state_root)); candidate_span.add_string_tag( "extrinsics-root", - format!("{:?}", block_header.extrinsics_root), + format!("{:?}", &block_header.extrinsics_root), ); + imported_blocks_and_info.push((block_hash, block_header, i)); }, Err(error) => { candidate_span From 94a4e47fe09dcad692655d8801121def3e467fa4 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 17:47:53 +0000 Subject: [PATCH 29/82] - Add db-insertion span --- node/core/approval-voting/src/import.rs | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index f2c63fad7ac7..6b00987a5ca2 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -481,6 +481,7 @@ pub(crate) async fn handle_new_head( "Inserting imported blocks into database" ); for (block_hash, block_header, imported_block_info) in imported_blocks_and_info { + let mut db_insertion_span = handle_new_head_span.child("block-db-insertion"); let ImportedBlockInfo { included_candidates, session_index, @@ -507,11 +508,13 @@ pub(crate) async fn handle_new_head( }; let needed_approvals = session_info.needed_approvals; + db_insertion_span.add_uint_tag("needed-approvals", needed_approvals as u64); let validator_group_lens: Vec = session_info.validator_groups.iter().map(|v| v.len()).collect(); // insta-approve candidates on low-node testnets: // cf. https://github.com/paritytech/polkadot/issues/2411 let num_candidates = included_candidates.len(); + db_insertion_span.add_uint_tag("num-candidates", num_candidates as u64); let approved_bitfield = { if needed_approvals == 0 { gum::debug!( @@ -523,10 +526,14 @@ pub(crate) async fn handle_new_head( } else { let mut result = bitvec::bitvec![u8, BitOrderLsb0; 0; num_candidates]; for (i, &(_, _, _, backing_group)) in included_candidates.iter().enumerate() { + let mut bitfield_span = db_insertion_span.child("bitfield"); + bitfield_span.add_uint_tag("candidate-index", i as u64); let backing_group_size = validator_group_lens.get(backing_group.0 as usize).copied().unwrap_or(0); + bitfield_span.add_uint_tag("backing-group-size", backing_group_size as u64); let needed_approvals = usize::try_from(needed_approvals).expect("usize is at least u32; qed"); + bitfield_span.add_uint_tag("needed-approvals", needed_approvals as u64); if n_validators.saturating_sub(backing_group_size) < needed_approvals { result.set(i, true); } @@ -543,7 +550,7 @@ pub(crate) async fn handle_new_head( result } }; - + db_insertion_span.add_uint_tag("approved-bitfields", format!("{:?}", approved_bitfield.count_ones())); // If all bits are already set, then send an approve message. if approved_bitfield.count_ones() == approved_bitfield.len() { ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; @@ -563,6 +570,13 @@ pub(crate) async fn handle_new_head( approved_bitfield, children: Vec::new(), }; + db_insertion_span.add_string_tag("block-hash", format!("{:?}", block_hash)); + db_insertion_span.add_string_tag("parent-hash", format!("{:?}", block_header.parent_hash)); + db_insertion_span.add_string_tag("block-number", format!("{:?}", block_header.number)); + db_insertion_span.add_uint_tag("session", session_index); + db_insertion_span.add_uint_tag("slot", slot); + db_insertion_span.add_string_tag("candidates", format!("{:?}", block_entry.candidates)); + db_insertion_span.add_string_tag("approved-bitfield", format!("{:?}", approved_bitfield)); gum::trace!( target: LOG_TARGET, From 1ce049543aeb62e5fe5b47492a4d4fd6070fdc20 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 17:48:30 +0000 Subject: [PATCH 30/82] cargo fmt --- node/core/approval-voting/src/import.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 6b00987a5ca2..cd678fef1b2f 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -550,7 +550,8 @@ pub(crate) async fn handle_new_head( result } }; - db_insertion_span.add_uint_tag("approved-bitfields", format!("{:?}", approved_bitfield.count_ones())); + db_insertion_span + .add_uint_tag("approved-bitfields", format!("{:?}", approved_bitfield.count_ones())); // If all bits are already set, then send an approve message. if approved_bitfield.count_ones() == approved_bitfield.len() { ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; From 93878c64bdaab86d8f11493695c66cc2672c1ecb Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 4 Jan 2023 18:41:59 +0000 Subject: [PATCH 31/82] fix types --- node/core/approval-voting/src/import.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index cd678fef1b2f..d8d89252bd31 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -551,7 +551,7 @@ pub(crate) async fn handle_new_head( } }; db_insertion_span - .add_uint_tag("approved-bitfields", format!("{:?}", approved_bitfield.count_ones())); + .add_uint_tag("approved-bitfields", approved_bitfield.count_ones() as u64); // If all bits are already set, then send an approve message. if approved_bitfield.count_ones() == approved_bitfield.len() { ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; @@ -573,11 +573,11 @@ pub(crate) async fn handle_new_head( }; db_insertion_span.add_string_tag("block-hash", format!("{:?}", block_hash)); db_insertion_span.add_string_tag("parent-hash", format!("{:?}", block_header.parent_hash)); - db_insertion_span.add_string_tag("block-number", format!("{:?}", block_header.number)); - db_insertion_span.add_uint_tag("session", session_index); - db_insertion_span.add_uint_tag("slot", slot); + db_insertion_span.add_uint_tag("block-number", block_header.number as u64); + db_insertion_span.add_uint_tag("session", session_index as u64); + db_insertion_span.add_uint_tag("slot", *slot); db_insertion_span.add_string_tag("candidates", format!("{:?}", block_entry.candidates)); - db_insertion_span.add_string_tag("approved-bitfield", format!("{:?}", approved_bitfield)); + db_insertion_span.add_string_tag("approved-bitfield", format!("{:?}", block_entry.approved_bitfield)); gum::trace!( target: LOG_TARGET, From 6dc83f9a669a53ab9e74e3cf705b62edadd036aa Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 1 Feb 2023 18:03:12 +0000 Subject: [PATCH 32/82] * Pass mutable reference to span in handle_new_head * Change get-header-span tags in handle_new_head * Create cache-session-info span in handle_new_head * Create optional argument in determine_new_blocks * Pass mutable reference to handle_new_head_span in determine_new_blocks in handle_new_head function * Add candidate-hash, candidate-number, lost-to-finality tags to candidate_span in handle_new_head function * Manually drop db_insertion_span and remove superfluous tags to it, only keeping approved-bitfields tag * Add ApprovalVoting stage in jaeger --- node/core/approval-voting/src/import.rs | 71 ++++++++++--------------- node/jaeger/src/spans.rs | 1 + 2 files changed, 30 insertions(+), 42 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index fbf1100c6cae..afc6ab6f32b1 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -327,17 +327,12 @@ pub(crate) async fn handle_new_head( db: &mut OverlayedBackend<'_, B>, head: Hash, finalized_number: &Option, - span: Option<&mut jaeger::PerLeafSpan>, + span: &mut jaeger::Span, ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; - - let mut handle_new_head_span = match span { - Some(ref span) => span.child("handle-new-head"), - None => jaeger::Span::Disabled, - }; - + let mut handle_new_head_span = span.child("handle-new-head"); let header = { - let mut get_header_span = handle_new_head_span.child("get-header"); + let mut get_header_span = handle_new_head_span.child("get-block-header"); let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; match h_rx.await? { @@ -348,14 +343,15 @@ pub(crate) async fn handle_new_head( e, ); // May be a better way of handling errors here. - get_header_span.add_string_tag("error", format!("{:?}", e)); + get_header_span + .add_string_tag("header", format!("Error from Chain API subsystem: {:?}", e)); return Ok(Vec::new()) }, Ok(None) => { gum::warn!(target: LOG_TARGET, "Missing header for new head {}", head); // May be a better way of handling warnings here. get_header_span - .add_string_tag("warn", format!("Missing header for new head {}", head)); + .add_string_tag("header", format!("Missing header for new head {}", head)); return Ok(Vec::new()) }, Ok(Some(h)) => { @@ -370,6 +366,7 @@ pub(crate) async fn handle_new_head( }; // Update session info based on most recent head. + let mut cache_session_span = handle_new_head_span.child("cache-session-info"); match state.cache_session_info_for_head(ctx, head).await { Err(e) => { gum::debug!( @@ -378,7 +375,7 @@ pub(crate) async fn handle_new_head( ?e, "Could not cache session info when processing head.", ); - + drop(cache_session_span); return Ok(Vec::new()) }, Ok(Some(a @ SessionWindowUpdate::Advanced { .. })) => { @@ -387,8 +384,11 @@ pub(crate) async fn handle_new_head( update = ?a, "Advanced session window for approvals", ); + drop(cache_session_span); + }, + Ok(_) => { + drop(cache_session_span); }, - Ok(_) => {}, } // If we've just started the node and are far behind, @@ -402,12 +402,11 @@ pub(crate) async fn handle_new_head( head, &header, lower_bound_number, + Some(&mut handle_new_head_span), ) .map_err(|e| SubsystemError::with_origin("approval-voting", e)) .await?; - handle_new_head_span.add_uint_tag("new-blocks-count", new_blocks.len() as u64); - if new_blocks.is_empty() { return Ok(Vec::new()) } @@ -423,6 +422,9 @@ pub(crate) async fn handle_new_head( let mut imported_blocks_and_info = Vec::with_capacity(new_blocks.len()); for (block_hash, block_header) in new_blocks.into_iter().rev() { let mut candidate_span = imported_blocks_and_info_span.child("candidate"); + candidate_span.add_string_tag("candidate-hash", format!("{:?}", block_hash)); + candidate_span.add_uint_tag("candidate-number", block_header.number as u64); + let env = ImportedBlockInfoEnv { session_window: &state.session_window, assignment_criteria: &*state.assignment_criteria, @@ -431,16 +433,6 @@ pub(crate) async fn handle_new_head( match imported_block_info(ctx, env, block_hash, &block_header).await { Ok(i) => { - candidate_span.add_string_tag("candidate-hash", format!("{:?}", &block_hash)); - candidate_span - .add_string_tag("parent-hash", format!("{:?}", &block_header.parent_hash)); - candidate_span.add_string_tag("number", format!("{:?}", &block_header.number)); - candidate_span - .add_string_tag("state-root", format!("{:?}", &block_header.state_root)); - candidate_span.add_string_tag( - "extrinsics-root", - format!("{:?}", &block_header.extrinsics_root), - ); imported_blocks_and_info.push((block_hash, block_header, i)); }, Err(error) => { @@ -452,8 +444,16 @@ pub(crate) async fn handle_new_head( .await; let lost_to_finality = match rx.await { - Ok(Ok(Some(h))) if h != block_hash => true, - _ => false, + Ok(Ok(Some(h))) if h != block_hash => { + candidate_span + .add_string_tag("lost-to-finality", format!("{:?}", true)); + true + }, + _ => { + candidate_span + .add_string_tag("lost-to-finality", format!("{:?}", false)); + false + }, }; if !lost_to_finality { @@ -480,8 +480,9 @@ pub(crate) async fn handle_new_head( imported_blocks = imported_blocks_and_info.len(), "Inserting imported blocks into database" ); + let mut db_insertion_span = handle_new_head_span.child("block-db-insertion"); + for (block_hash, block_header, imported_block_info) in imported_blocks_and_info { - let mut db_insertion_span = handle_new_head_span.child("block-db-insertion"); let ImportedBlockInfo { included_candidates, session_index, @@ -508,13 +509,11 @@ pub(crate) async fn handle_new_head( }; let needed_approvals = session_info.needed_approvals; - db_insertion_span.add_uint_tag("needed-approvals", needed_approvals as u64); let validator_group_lens: Vec = session_info.validator_groups.iter().map(|v| v.len()).collect(); // insta-approve candidates on low-node testnets: // cf. https://github.com/paritytech/polkadot/issues/2411 let num_candidates = included_candidates.len(); - db_insertion_span.add_uint_tag("num-candidates", num_candidates as u64); let approved_bitfield = { if needed_approvals == 0 { gum::debug!( @@ -526,14 +525,10 @@ pub(crate) async fn handle_new_head( } else { let mut result = bitvec::bitvec![u8, BitOrderLsb0; 0; num_candidates]; for (i, &(_, _, _, backing_group)) in included_candidates.iter().enumerate() { - let mut bitfield_span = db_insertion_span.child("bitfield"); - bitfield_span.add_uint_tag("candidate-index", i as u64); let backing_group_size = validator_group_lens.get(backing_group.0 as usize).copied().unwrap_or(0); - bitfield_span.add_uint_tag("backing-group-size", backing_group_size as u64); let needed_approvals = usize::try_from(needed_approvals).expect("usize is at least u32; qed"); - bitfield_span.add_uint_tag("needed-approvals", needed_approvals as u64); if n_validators.saturating_sub(backing_group_size) < needed_approvals { result.set(i, true); } @@ -550,8 +545,7 @@ pub(crate) async fn handle_new_head( result } }; - db_insertion_span - .add_uint_tag("approved-bitfields", approved_bitfield.count_ones() as u64); + db_insertion_span.add_uint_tag("approved-bitfields", approved_bitfield.count_ones() as u64); // If all bits are already set, then send an approve message. if approved_bitfield.count_ones() == approved_bitfield.len() { ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; @@ -571,13 +565,6 @@ pub(crate) async fn handle_new_head( approved_bitfield, children: Vec::new(), }; - db_insertion_span.add_string_tag("block-hash", format!("{:?}", block_hash)); - db_insertion_span.add_string_tag("parent-hash", format!("{:?}", block_header.parent_hash)); - db_insertion_span.add_uint_tag("block-number", block_header.number as u64); - db_insertion_span.add_uint_tag("session", session_index as u64); - db_insertion_span.add_uint_tag("slot", *slot); - db_insertion_span.add_string_tag("candidates", format!("{:?}", block_entry.candidates)); - db_insertion_span.add_string_tag("approved-bitfield", format!("{:?}", block_entry.approved_bitfield)); gum::trace!( target: LOG_TARGET, diff --git a/node/jaeger/src/spans.rs b/node/jaeger/src/spans.rs index a6183b5d25ea..6bed03c6ee27 100644 --- a/node/jaeger/src/spans.rs +++ b/node/jaeger/src/spans.rs @@ -163,6 +163,7 @@ pub enum Stage { AvailabilityRecovery = 6, BitfieldDistribution = 7, ApprovalChecking = 8, + ApprovalVoting = 9, // 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] From a7eccdfc6496310ba3137d526925b90367345392 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 1 Feb 2023 18:04:17 +0000 Subject: [PATCH 33/82] * Pass mutable reference to jaeger::Span in stead of PerLeafSpan * Add block-import span --- node/core/approval-voting/src/lib.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index c96f0de5612e..c7ae0e3fa293 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1142,19 +1142,20 @@ async fn handle_from_overseer( let mut actions = Vec::new(); if let Some(activated) = update.activated { let head = activated.hash; - let mut span = jaeger::PerLeafSpan::new(activated.span, "approval-voting"); + let mut span = jaeger::Span::new(&head, "approval-voting"); match import::handle_new_head( ctx, state, db, head, &*last_finalized_height, - Some(&mut span), + &mut span, ) .await { Err(e) => return Err(SubsystemError::with_origin("db", e)), Ok(block_imported_candidates) => { + let mut block_import_span = span.child("block-import"); // Schedule wakeups for all imported candidates. for block_batch in block_imported_candidates { gum::debug!( From 9c07ac19bb5789b0e9331bd016cbaed639337642 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 1 Feb 2023 18:06:05 +0000 Subject: [PATCH 34/82] *Pass optional_span (optional argument) to determine_new_blocks util function --- node/core/av-store/src/lib.rs | 1 + node/core/chain-selection/src/lib.rs | 1 + .../src/determine_new_blocks.rs | 26 +++++++++++++++---- 3 files changed, 23 insertions(+), 5 deletions(-) diff --git a/node/core/av-store/src/lib.rs b/node/core/av-store/src/lib.rs index 4509c5712188..1c77df7baab8 100644 --- a/node/core/av-store/src/lib.rs +++ b/node/core/av-store/src/lib.rs @@ -632,6 +632,7 @@ async fn process_block_activated( activated, &block_header, subsystem.finalized_number.unwrap_or(block_number.saturating_sub(1)), + None, ) .await?; diff --git a/node/core/chain-selection/src/lib.rs b/node/core/chain-selection/src/lib.rs index 529b297a4dea..4dc3fd4b6c77 100644 --- a/node/core/chain-selection/src/lib.rs +++ b/node/core/chain-selection/src/lib.rs @@ -577,6 +577,7 @@ async fn handle_active_leaf( hash, &header, lower_bound, + None, ) .await?; diff --git a/node/subsystem-util/src/determine_new_blocks.rs b/node/subsystem-util/src/determine_new_blocks.rs index 5a032c38aa1e..e5d0fdb6931a 100644 --- a/node/subsystem-util/src/determine_new_blocks.rs +++ b/node/subsystem-util/src/determine_new_blocks.rs @@ -17,6 +17,7 @@ //! A utility for fetching all unknown blocks based on a new chain-head hash. use futures::{channel::oneshot, prelude::*}; +use polkadot_node_jaeger::Span; use polkadot_node_subsystem::{messages::ChainApiMessage, SubsystemSender}; use polkadot_primitives::{BlockNumber, Hash, Header}; @@ -37,13 +38,20 @@ pub async fn determine_new_blocks( head: Hash, header: &Header, lower_bound_number: BlockNumber, + optional_span: Option<&mut Span>, ) -> Result, E> where Sender: SubsystemSender, { const ANCESTRY_STEP: usize = 4; + let mut span = match optional_span { + Some(s) => s.child("determine-new-blocks"), + None => Span::Disabled, + }; + let min_block_needed = lower_bound_number + 1; + span.add_uint_tag("minimum-block-needed", min_block_needed as u64); // Early exit if the block is in the DB or too early. { @@ -65,6 +73,7 @@ where } 'outer: loop { + let mut outer_loop_span = span.child("determine-new-blocks-outer-loop"); let &(ref last_hash, ref last_header) = ancestry .last() .expect("ancestry has length 1 at initialization and is only added to; qed"); @@ -104,6 +113,8 @@ where } }; + outer_loop_span.add_uint_tag("batch-hashes-len", batch_hashes.len() as u64); + let batch_headers = { let (batch_senders, batch_receivers) = (0..batch_hashes.len()) .map(|_| oneshot::channel()) @@ -129,6 +140,7 @@ where let batch_headers: Vec<_> = requests.flat_map(|x: Option
| stream::iter(x)).collect().await; + outer_loop_span.add_uint_tag("batch-headers-len", batch_headers.len() as u64); // Any failed header fetch of the batch will yield a `None` result that will // be skipped. Any failure at this stage means we'll just ignore those blocks // as the chain DB has failed us. @@ -290,6 +302,7 @@ mod tests { head_hash, &head, lower_bound_number, + None, ) .await .unwrap(); @@ -363,6 +376,7 @@ mod tests { head_hash, &head, lower_bound_number, + None, ) .await .unwrap(); @@ -422,6 +436,7 @@ mod tests { head_hash, &head, lower_bound_number, + None, ) .await .unwrap(); @@ -458,6 +473,7 @@ mod tests { head_hash, &head, lower_bound_number, + None, ) .await .unwrap(); @@ -484,17 +500,17 @@ mod tests { let test_fut = Box::pin(async move { let after_finality = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 17) + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 17, None) .await .unwrap(); let at_finality = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 18) + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 18, None) .await .unwrap(); let before_finality = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 19) + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 19, None) .await .unwrap(); @@ -526,7 +542,7 @@ mod tests { let test_fut = Box::pin(async move { let ancestry = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 0) + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 0, None) .await .unwrap(); @@ -564,7 +580,7 @@ mod tests { let test_fut = Box::pin(async move { let ancestry = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 0) + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 0, None) .await .unwrap(); From 363833ea02226ceefa490de595c3aa55d047d127 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 1 Feb 2023 18:08:08 +0000 Subject: [PATCH 35/82] * Add num-candidates int tag to block_import_span --- node/core/approval-voting/src/lib.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index c7ae0e3fa293..a454f63c0bb7 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1156,6 +1156,7 @@ async fn handle_from_overseer( Err(e) => return Err(SubsystemError::with_origin("db", e)), Ok(block_imported_candidates) => { let mut block_import_span = span.child("block-import"); + block_import_span.add_uint_tag("num-candidates", block_imported_candidates.len() as u64); // Schedule wakeups for all imported candidates. for block_batch in block_imported_candidates { gum::debug!( From e9fbb2a3efeb0f5669c77225f66a7b1f5a96c42e Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 1 Feb 2023 18:09:13 +0000 Subject: [PATCH 36/82] * Add head tag to cache_session_span --- node/core/approval-voting/src/import.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index afc6ab6f32b1..d14c450d7bca 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -367,6 +367,7 @@ pub(crate) async fn handle_new_head( // Update session info based on most recent head. let mut cache_session_span = handle_new_head_span.child("cache-session-info"); + cache_session_span.add_string_tag("head", format!("{:?}", head)); match state.cache_session_info_for_head(ctx, head).await { Err(e) => { gum::debug!( From 6453bf4136055f3540f2605f2a1186ce912e2aa4 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 2 Feb 2023 09:43:50 +0000 Subject: [PATCH 37/82] * Create PerLeafSpan in handle_from_overseer (this is required to establish parent-child relationship between approval-voting span, and leaf-activated root span) --- node/core/approval-voting/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index a454f63c0bb7..91e445f83c82 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1142,7 +1142,7 @@ async fn handle_from_overseer( let mut actions = Vec::new(); if let Some(activated) = update.activated { let head = activated.hash; - let mut span = jaeger::Span::new(&head, "approval-voting"); + let mut span = jaeger::PerLeafSpan::new(activated.span, "approval-voting"); match import::handle_new_head( ctx, state, From e671271bb06a2965762a8259d8e67b69d25e0da6 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 2 Feb 2023 10:15:48 +0000 Subject: [PATCH 38/82] * Add candidate-import-span as child of block-import-span * Add candidate-hash and num-approval tags to candidate-import-span --- node/core/approval-voting/src/lib.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 91e445f83c82..dacd144dc185 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1168,6 +1168,9 @@ async fn handle_from_overseer( ); for (c_hash, c_entry) in block_batch.imported_candidates { + let mut candidate_import_span = block_import_span.child("candidate-import"); + candidate_import_span.add_string_tag("candidate-hash", format!("{:?}", c_hash)); + candidate_import_span.add_uint_tag("num-approvals", c_entry.num_approvals() as u64); metrics.on_candidate_imported(); let our_tranche = c_entry From d8266f942b52f207099fa9e84fc3db6e949428be Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 2 Feb 2023 10:19:39 +0000 Subject: [PATCH 39/82] * Fix num-candidate tag to bitvec-len tag in candidate-import-span --- node/core/approval-voting/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index dacd144dc185..f68fed629683 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1170,7 +1170,7 @@ async fn handle_from_overseer( for (c_hash, c_entry) in block_batch.imported_candidates { let mut candidate_import_span = block_import_span.child("candidate-import"); candidate_import_span.add_string_tag("candidate-hash", format!("{:?}", c_hash)); - candidate_import_span.add_uint_tag("num-approvals", c_entry.num_approvals() as u64); + candidate_import_span.add_uint_tag("bitvec-len", c_entry.approvals.len() as u64); metrics.on_candidate_imported(); let our_tranche = c_entry From 9f6078b42808b26460463ee4df29a113bb986e6a Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 2 Feb 2023 10:38:19 +0000 Subject: [PATCH 40/82] *Fix imported_blocKs_and_info span to create new-block-span as not dealing with candidates --- node/core/approval-voting/src/import.rs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index d14c450d7bca..0bcf2c95795f 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -422,9 +422,9 @@ pub(crate) async fn handle_new_head( imported_blocks_and_info_span.add_uint_tag("new-blocks-count", new_blocks.len() as u64); let mut imported_blocks_and_info = Vec::with_capacity(new_blocks.len()); for (block_hash, block_header) in new_blocks.into_iter().rev() { - let mut candidate_span = imported_blocks_and_info_span.child("candidate"); - candidate_span.add_string_tag("candidate-hash", format!("{:?}", block_hash)); - candidate_span.add_uint_tag("candidate-number", block_header.number as u64); + let mut new_block_span = imported_blocks_and_info_span.child("new-block"); + new_block_span.add_string_tag("block-hash", format!("{:?}", block_hash)); + new_block_span.add_uint_tag("block-number", block_header.number as u64); let env = ImportedBlockInfoEnv { session_window: &state.session_window, @@ -437,7 +437,7 @@ pub(crate) async fn handle_new_head( imported_blocks_and_info.push((block_hash, block_header, i)); }, Err(error) => { - candidate_span + new_block_span .add_string_tag("imported-block-info-error", format!("{:?}", error)); // It's possible that we've lost a race with finality. let (tx, rx) = oneshot::channel(); @@ -446,12 +446,12 @@ pub(crate) async fn handle_new_head( let lost_to_finality = match rx.await { Ok(Ok(Some(h))) if h != block_hash => { - candidate_span + new_block_span .add_string_tag("lost-to-finality", format!("{:?}", true)); true }, _ => { - candidate_span + new_block_span .add_string_tag("lost-to-finality", format!("{:?}", false)); false }, From 75d4481f6410d41b31fa25398936fa9e8e5f8dcc Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Mon, 6 Feb 2023 18:09:40 +0000 Subject: [PATCH 41/82] Consider the future::select! block --- node/core/approval-voting/src/lib.rs | 42 ++++++++++++++++++---------- 1 file changed, 28 insertions(+), 14 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index f68fed629683..8441a24f01f4 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1142,20 +1142,20 @@ async fn handle_from_overseer( let mut actions = Vec::new(); if let Some(activated) = update.activated { let head = activated.hash; - let mut span = jaeger::PerLeafSpan::new(activated.span, "approval-voting"); + let mut from_overseer_span = jaeger::PerLeafSpan::new(activated.span, "approval-voting-handle-from-overseer"); match import::handle_new_head( ctx, state, db, head, &*last_finalized_height, - &mut span, + &mut from_overseer_span, ) .await { Err(e) => return Err(SubsystemError::with_origin("db", e)), Ok(block_imported_candidates) => { - let mut block_import_span = span.child("block-import"); + let mut block_import_span = from_overseer_span.child("block-import"); block_import_span.add_uint_tag("num-candidates", block_imported_candidates.len() as u64); // Schedule wakeups for all imported candidates. for block_batch in block_imported_candidates { @@ -1207,6 +1207,7 @@ async fn handle_from_overseer( actions }, FromOrchestra::Signal(OverseerSignal::BlockFinalized(block_hash, block_number)) => { + let mut finalized_span = jaeger::Span::new(block_hash, "approval-voting-block-finalized"); gum::debug!(target: LOG_TARGET, ?block_hash, ?block_number, "Block finalized"); *last_finalized_height = Some(block_number); @@ -1268,6 +1269,7 @@ async fn get_approval_signatures_for_candidate( candidate_hash: CandidateHash, tx: oneshot::Sender>, ) -> SubsystemResult<()> { + let mut span = jaeger::Span::new(candidate_hash, "approval-voting-get-approval-signatures"); let send_votes = |votes| { if let Err(_) = tx.send(votes) { gum::debug!( @@ -2137,14 +2139,11 @@ fn process_wakeup( expected_tick: Tick, metrics: &Metrics, ) -> SubsystemResult> { - let _span = jaeger::Span::from_encodable( - (relay_block, candidate_hash, expected_tick), - "process-approval-wakeup", - ) - .with_relay_parent(relay_block) - .with_candidate(candidate_hash) - .with_stage(jaeger::Stage::ApprovalChecking); + let mut span = jaeger::Span::new(relay_block, "approval-voting-process-wakeup") + .with_candidate(candidate_hash) + .with_relay_parent(relay_block); + let mut load_entries_span = span.child("load-entries"); let block_entry = db.load_block_entry(&relay_block)?; let candidate_entry = db.load_candidate_entry(&candidate_hash)?; @@ -2153,7 +2152,8 @@ fn process_wakeup( (Some(b), Some(c)) => (b, c), _ => return Ok(Vec::new()), }; - + + let mut info_from_entries_span = load_entries_span.child("info-from-entries"); let session_info = match state.session_info(block_entry.session()) { Some(i) => i, None => { @@ -2167,7 +2167,7 @@ fn process_wakeup( return Ok(Vec::new()) }, }; - + let block_tick = slot_number_to_tick(state.slot_duration_millis, block_entry.slot()); let no_show_duration = slot_number_to_tick( state.slot_duration_millis, @@ -2175,6 +2175,8 @@ fn process_wakeup( ); let tranche_now = state.clock.tranche_now(state.slot_duration_millis, block_entry.slot()); + info_from_entries_span.add_uint_tag("block-tick", block_tick); + info_from_entries_span.add_uint_tag("tranche-now", *&tranche_now as u64); gum::trace!( target: LOG_TARGET, @@ -2183,6 +2185,8 @@ fn process_wakeup( block_hash = ?relay_block, "Processing wakeup", ); + drop(load_entries_span); + let mut should_trigger_span = span.child("should-trigger"); let (should_trigger, backing_group) = { let approval_entry = match candidate_entry.approval_entry(&relay_block) { @@ -2206,9 +2210,10 @@ fn process_wakeup( tranche_now, ); + should_trigger_span.add_string_tag("should-trigger", format!("{:?}", &should_trigger)); + (should_trigger, approval_entry.backing_group()) }; - let mut actions = Vec::new(); let candidate_receipt = candidate_entry.candidate_receipt().clone(); @@ -2228,6 +2233,9 @@ fn process_wakeup( None }; + drop(should_trigger_span); + let mut assignment_span = span.child("assignment"); + if let Some((cert, val_index, tranche)) = maybe_cert { let indirect_cert = IndirectAssignmentCert { block_hash: relay_block, validator: val_index, cert }; @@ -2244,6 +2252,10 @@ fn process_wakeup( "Launching approval work.", ); + assignment_span.add_string_tag("candidate-hash", format!("{:?}", &candidate_hash)); + assignment_span.add_string_tag("para-id", format!("{:?}", &candidate_receipt.descriptor.para_id)); + assignment_span.add_string_tag("block-hash", format!("{:?}", &relay_block)); + // sanity: should always be present. actions.push(Action::LaunchApproval { candidate_hash, @@ -2257,7 +2269,8 @@ fn process_wakeup( }); } } - + drop(assignment_span); + let mut advanced_approval_state_span = span.child("advanced-approval-state"); // Although we checked approval earlier in this function, // this wakeup might have advanced the state to approved via // a no-show that was immediately covered and therefore @@ -2273,6 +2286,7 @@ fn process_wakeup( candidate_entry, ApprovalStateTransition::WakeupProcessed, )); + drop(advanced_approval_state_span); Ok(actions) } From 54e99cebb39f577a671dd73c9eee57b32a832037 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 9 Feb 2023 17:44:18 +0000 Subject: [PATCH 42/82] Use HashMap --- node/core/approval-voting/src/import.rs | 7 +- node/core/approval-voting/src/lib.rs | 119 ++++++++++-------- node/core/av-store/src/lib.rs | 1 - node/core/chain-selection/src/lib.rs | 1 - .../src/determine_new_blocks.rs | 82 +++++++----- 5 files changed, 118 insertions(+), 92 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 0bcf2c95795f..b6b8e8363ddd 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -327,10 +327,12 @@ pub(crate) async fn handle_new_head( db: &mut OverlayedBackend<'_, B>, head: Hash, finalized_number: &Option, - span: &mut jaeger::Span, ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; - let mut handle_new_head_span = span.child("handle-new-head"); + let handle_new_head_span = match state.spans.get(&head) { + Some(s) => s.child("handle-new-head"), + None => jaeger::Span::Disabled, + }; let header = { let mut get_header_span = handle_new_head_span.child("get-block-header"); let (h_tx, h_rx) = oneshot::channel(); @@ -403,7 +405,6 @@ pub(crate) async fn handle_new_head( head, &header, lower_bound_number, - Some(&mut handle_new_head_span), ) .map_err(|e| SubsystemError::with_origin("approval-voting", e)) .await?; diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 8441a24f01f4..68d5673d201f 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -639,6 +639,7 @@ struct State { // Require for `RollingSessionWindow`. db_config: DatabaseConfig, db: Arc, + spans: HashMap, } #[overseer::contextbounds(ApprovalVoting, prefix = self::overseer)] @@ -777,6 +778,7 @@ where assignment_criteria, db_config: subsystem.db_config, db: subsystem.db, + spans: HashMap::new(), }; let mut wakeups = Wakeups::default(); @@ -919,12 +921,16 @@ async fn handle_actions( actions: Vec, ) -> SubsystemResult { let mut conclude = false; - let mut actions_iter = actions.into_iter(); while let Some(action) = actions_iter.next() { match action { - Action::ScheduleWakeup { block_hash, block_number, candidate_hash, tick } => - wakeups.schedule(block_hash, block_number, candidate_hash, tick), + Action::ScheduleWakeup { block_hash, block_number, candidate_hash, tick } => { + let _span = match state.spans.get(&block_hash) { + Some(s) => s.child("schedule-wakeup"), + None => jaeger::Span::Disabled, + }; + wakeups.schedule(block_hash, block_number, candidate_hash, tick); + }, Action::IssueApproval(candidate_hash, approval_request) => { // Note that the IssueApproval action will create additional // actions that will need to all be processed before we can @@ -937,6 +943,10 @@ async fn handle_actions( // // Note that chaining these iterators is O(n) as we must consume // the prior iterator. + let _span = match state.spans.get(&approval_request.block_hash) { + Some(s) => s.child("issue-approval"), + None => jaeger::Span::Disabled, + }; let next_actions: Vec = issue_approval( ctx, state, @@ -963,6 +973,10 @@ async fn handle_actions( candidate, backing_group, } => { + let _span = match state.spans.get(&relay_block_hash) { + Some(s) => s.child("launch-approval"), + None => jaeger::Span::Disabled, + }; // Don't launch approval work if the node is syncing. if let Mode::Syncing(_) = *mode { continue @@ -1014,12 +1028,16 @@ async fn handle_actions( } }, Action::NoteApprovedInChainSelection(block_hash) => { + let _span = match state.spans.get(&block_hash) { + Some(s) => s.child("note-approved-in-chain-selection"), + None => jaeger::Span::Disabled, + }; ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; }, Action::BecomeActive => { *mode = Mode::Active; - let messages = distribution_messages_for_activation(overlayed_db)?; + let messages = distribution_messages_for_activation(overlayed_db, state)?; ctx.send_messages(messages.into_iter()).await; }, @@ -1034,6 +1052,7 @@ async fn handle_actions( fn distribution_messages_for_activation( db: &OverlayedBackend<'_, impl Backend>, + state: &mut State, ) -> SubsystemResult> { let all_blocks: Vec = db.load_all_blocks()?; @@ -1043,6 +1062,10 @@ fn distribution_messages_for_activation( messages.push(ApprovalDistributionMessage::NewBlocks(Vec::new())); // dummy value. for block_hash in all_blocks { + let mut span = match state.spans.get(&block_hash) { + Some(s) => s.child("distribution-messages-for-activation"), + None => jaeger::Span::Disabled, + }; let block_entry = match db.load_block_entry(&block_hash)? { Some(b) => b, None => { @@ -1051,6 +1074,8 @@ fn distribution_messages_for_activation( continue }, }; + span.add_string_tag("block-hash", &block_hash.to_string()); + span.add_string_tag("parent-hash", &block_entry.parent_hash().to_string()); approval_meta.push(BlockApprovalMeta { hash: block_hash, number: block_entry.block_number(), @@ -1061,6 +1086,7 @@ fn distribution_messages_for_activation( }); for (i, (_, candidate_hash)) in block_entry.candidates().iter().enumerate() { + let _candidate_span = span.child("candidate").with_candidate(*candidate_hash); let candidate_entry = match db.load_candidate_entry(&candidate_hash)? { Some(c) => c, None => { @@ -1142,21 +1168,12 @@ async fn handle_from_overseer( let mut actions = Vec::new(); if let Some(activated) = update.activated { let head = activated.hash; - let mut from_overseer_span = jaeger::PerLeafSpan::new(activated.span, "approval-voting-handle-from-overseer"); - match import::handle_new_head( - ctx, - state, - db, - head, - &*last_finalized_height, - &mut from_overseer_span, - ) - .await - { + let approval_voting_span = + jaeger::PerLeafSpan::new(activated.span, "approval-voting"); + state.spans.insert(head, approval_voting_span); + match import::handle_new_head(ctx, state, db, head, &*last_finalized_height).await { Err(e) => return Err(SubsystemError::with_origin("db", e)), Ok(block_imported_candidates) => { - let mut block_import_span = from_overseer_span.child("block-import"); - block_import_span.add_uint_tag("num-candidates", block_imported_candidates.len() as u64); // Schedule wakeups for all imported candidates. for block_batch in block_imported_candidates { gum::debug!( @@ -1168,9 +1185,6 @@ async fn handle_from_overseer( ); for (c_hash, c_entry) in block_batch.imported_candidates { - let mut candidate_import_span = block_import_span.child("candidate-import"); - candidate_import_span.add_string_tag("candidate-hash", format!("{:?}", c_hash)); - candidate_import_span.add_uint_tag("bitvec-len", c_entry.approvals.len() as u64); metrics.on_candidate_imported(); let our_tranche = c_entry @@ -1207,7 +1221,6 @@ async fn handle_from_overseer( actions }, FromOrchestra::Signal(OverseerSignal::BlockFinalized(block_hash, block_number)) => { - let mut finalized_span = jaeger::Span::new(block_hash, "approval-voting-block-finalized"); gum::debug!(target: LOG_TARGET, ?block_hash, ?block_number, "Block finalized"); *last_finalized_height = Some(block_number); @@ -1215,7 +1228,7 @@ async fn handle_from_overseer( .map_err(|e| SubsystemError::with_origin("db", e))?; wakeups.prune_finalized_wakeups(block_number); - + state.spans.remove(&block_hash); Vec::new() }, FromOrchestra::Signal(OverseerSignal::Conclude) => { @@ -1235,7 +1248,20 @@ async fn handle_from_overseer( })? .0, ApprovalVotingMessage::ApprovedAncestor(target, lower_bound, res) => { - match handle_approved_ancestor(ctx, db, target, lower_bound, wakeups).await { + let mut approved_ancestor_span = match state.spans.get(&target) { + Some(s) => s.child("approved-ancestor"), + None => jaeger::Span::Disabled, + }; + match handle_approved_ancestor( + ctx, + db, + target, + lower_bound, + wakeups, + &mut approved_ancestor_span, + ) + .await + { Ok(v) => { let _ = res.send(v); }, @@ -1269,7 +1295,6 @@ async fn get_approval_signatures_for_candidate( candidate_hash: CandidateHash, tx: oneshot::Sender>, ) -> SubsystemResult<()> { - let mut span = jaeger::Span::new(candidate_hash, "approval-voting-get-approval-signatures"); let send_votes = |votes| { if let Err(_) = tx.send(votes) { gum::debug!( @@ -1358,15 +1383,13 @@ async fn handle_approved_ancestor( target: Hash, lower_bound: BlockNumber, wakeups: &Wakeups, + span: &mut jaeger::Span, ) -> SubsystemResult> { const MAX_TRACING_WINDOW: usize = 200; const ABNORMAL_DEPTH_THRESHOLD: usize = 5; use bitvec::{order::Lsb0, vec::BitVec}; - let mut span = - jaeger::Span::new(&target, "approved-ancestor").with_stage(jaeger::Stage::ApprovalChecking); - let mut all_approved_max = None; let target_number = { @@ -1385,9 +1408,6 @@ async fn handle_approved_ancestor( return Ok(None) } - span.add_string_fmt_debug_tag("target-number", target_number); - span.add_string_fmt_debug_tag("target-hash", 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. @@ -1847,6 +1867,11 @@ fn check_and_import_approval( }, }; + let mut span = match state.spans.get(&block_entry.block_hash()) { + Some(s) => s.child("check-and-import-approval"), + None => jaeger::Span::Disabled, + }; + let session_info = match state.session_info(block_entry.session()) { Some(s) => s, None => { @@ -1863,6 +1888,8 @@ fn check_and_import_approval( )), }; + span.add_string_tag("candidate-hash", format!("{:?}", approved_candidate_hash)); + let pubkey = match session_info.validators.get(approval.validator) { Some(k) => k, None => respond_early!(ApprovalCheckResult::Bad( @@ -2136,14 +2163,13 @@ fn process_wakeup( db: &mut OverlayedBackend<'_, impl Backend>, relay_block: Hash, candidate_hash: CandidateHash, - expected_tick: Tick, + _expected_tick: Tick, metrics: &Metrics, ) -> SubsystemResult> { - let mut span = jaeger::Span::new(relay_block, "approval-voting-process-wakeup") - .with_candidate(candidate_hash) - .with_relay_parent(relay_block); - - let mut load_entries_span = span.child("load-entries"); + let _span = match state.spans.get(&relay_block) { + Some(s) => s.child("process-wakeup"), + None => jaeger::Span::Disabled, + }; let block_entry = db.load_block_entry(&relay_block)?; let candidate_entry = db.load_candidate_entry(&candidate_hash)?; @@ -2152,8 +2178,7 @@ fn process_wakeup( (Some(b), Some(c)) => (b, c), _ => return Ok(Vec::new()), }; - - let mut info_from_entries_span = load_entries_span.child("info-from-entries"); + let session_info = match state.session_info(block_entry.session()) { Some(i) => i, None => { @@ -2167,7 +2192,7 @@ fn process_wakeup( return Ok(Vec::new()) }, }; - + let block_tick = slot_number_to_tick(state.slot_duration_millis, block_entry.slot()); let no_show_duration = slot_number_to_tick( state.slot_duration_millis, @@ -2175,8 +2200,6 @@ fn process_wakeup( ); let tranche_now = state.clock.tranche_now(state.slot_duration_millis, block_entry.slot()); - info_from_entries_span.add_uint_tag("block-tick", block_tick); - info_from_entries_span.add_uint_tag("tranche-now", *&tranche_now as u64); gum::trace!( target: LOG_TARGET, @@ -2185,8 +2208,6 @@ fn process_wakeup( block_hash = ?relay_block, "Processing wakeup", ); - drop(load_entries_span); - let mut should_trigger_span = span.child("should-trigger"); let (should_trigger, backing_group) = { let approval_entry = match candidate_entry.approval_entry(&relay_block) { @@ -2210,8 +2231,6 @@ fn process_wakeup( tranche_now, ); - should_trigger_span.add_string_tag("should-trigger", format!("{:?}", &should_trigger)); - (should_trigger, approval_entry.backing_group()) }; let mut actions = Vec::new(); @@ -2233,9 +2252,6 @@ fn process_wakeup( None }; - drop(should_trigger_span); - let mut assignment_span = span.child("assignment"); - if let Some((cert, val_index, tranche)) = maybe_cert { let indirect_cert = IndirectAssignmentCert { block_hash: relay_block, validator: val_index, cert }; @@ -2252,10 +2268,6 @@ fn process_wakeup( "Launching approval work.", ); - assignment_span.add_string_tag("candidate-hash", format!("{:?}", &candidate_hash)); - assignment_span.add_string_tag("para-id", format!("{:?}", &candidate_receipt.descriptor.para_id)); - assignment_span.add_string_tag("block-hash", format!("{:?}", &relay_block)); - // sanity: should always be present. actions.push(Action::LaunchApproval { candidate_hash, @@ -2269,8 +2281,6 @@ fn process_wakeup( }); } } - drop(assignment_span); - let mut advanced_approval_state_span = span.child("advanced-approval-state"); // Although we checked approval earlier in this function, // this wakeup might have advanced the state to approved via // a no-show that was immediately covered and therefore @@ -2286,7 +2296,6 @@ fn process_wakeup( candidate_entry, ApprovalStateTransition::WakeupProcessed, )); - drop(advanced_approval_state_span); Ok(actions) } diff --git a/node/core/av-store/src/lib.rs b/node/core/av-store/src/lib.rs index dd23403a8f5c..d43dc0657d18 100644 --- a/node/core/av-store/src/lib.rs +++ b/node/core/av-store/src/lib.rs @@ -647,7 +647,6 @@ async fn process_block_activated( activated, &block_header, subsystem.finalized_number.unwrap_or(block_number.saturating_sub(1)), - None, ) .await?; diff --git a/node/core/chain-selection/src/lib.rs b/node/core/chain-selection/src/lib.rs index 4dc3fd4b6c77..529b297a4dea 100644 --- a/node/core/chain-selection/src/lib.rs +++ b/node/core/chain-selection/src/lib.rs @@ -577,7 +577,6 @@ async fn handle_active_leaf( hash, &header, lower_bound, - None, ) .await?; diff --git a/node/subsystem-util/src/determine_new_blocks.rs b/node/subsystem-util/src/determine_new_blocks.rs index e5d0fdb6931a..37f5870d1f75 100644 --- a/node/subsystem-util/src/determine_new_blocks.rs +++ b/node/subsystem-util/src/determine_new_blocks.rs @@ -17,7 +17,6 @@ //! A utility for fetching all unknown blocks based on a new chain-head hash. use futures::{channel::oneshot, prelude::*}; -use polkadot_node_jaeger::Span; use polkadot_node_subsystem::{messages::ChainApiMessage, SubsystemSender}; use polkadot_primitives::{BlockNumber, Hash, Header}; @@ -38,20 +37,13 @@ pub async fn determine_new_blocks( head: Hash, header: &Header, lower_bound_number: BlockNumber, - optional_span: Option<&mut Span>, ) -> Result, E> where Sender: SubsystemSender, { const ANCESTRY_STEP: usize = 4; - let mut span = match optional_span { - Some(s) => s.child("determine-new-blocks"), - None => Span::Disabled, - }; - let min_block_needed = lower_bound_number + 1; - span.add_uint_tag("minimum-block-needed", min_block_needed as u64); // Early exit if the block is in the DB or too early. { @@ -73,7 +65,6 @@ where } 'outer: loop { - let mut outer_loop_span = span.child("determine-new-blocks-outer-loop"); let &(ref last_hash, ref last_header) = ancestry .last() .expect("ancestry has length 1 at initialization and is only added to; qed"); @@ -113,8 +104,6 @@ where } }; - outer_loop_span.add_uint_tag("batch-hashes-len", batch_hashes.len() as u64); - let batch_headers = { let (batch_senders, batch_receivers) = (0..batch_hashes.len()) .map(|_| oneshot::channel()) @@ -140,7 +129,6 @@ where let batch_headers: Vec<_> = requests.flat_map(|x: Option
| stream::iter(x)).collect().await; - outer_loop_span.add_uint_tag("batch-headers-len", batch_headers.len() as u64); // Any failed header fetch of the batch will yield a `None` result that will // be skipped. Any failure at this stage means we'll just ignore those blocks // as the chain DB has failed us. @@ -499,20 +487,38 @@ mod tests { known.insert(parent_hash); let test_fut = Box::pin(async move { - let after_finality = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 17, None) - .await - .unwrap(); + let after_finality = determine_new_blocks( + ctx.sender(), + |h| known.is_known(h), + head_hash, + &head, + 17, + None, + ) + .await + .unwrap(); - let at_finality = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 18, None) - .await - .unwrap(); + let at_finality = determine_new_blocks( + ctx.sender(), + |h| known.is_known(h), + head_hash, + &head, + 18, + None, + ) + .await + .unwrap(); - let before_finality = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 19, None) - .await - .unwrap(); + let before_finality = determine_new_blocks( + ctx.sender(), + |h| known.is_known(h), + head_hash, + &head, + 19, + None, + ) + .await + .unwrap(); assert_eq!(after_finality, vec![(head_hash, head.clone())]); @@ -541,10 +547,16 @@ mod tests { .collect::>(); let test_fut = Box::pin(async move { - let ancestry = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 0, None) - .await - .unwrap(); + let ancestry = determine_new_blocks( + ctx.sender(), + |h| known.is_known(h), + head_hash, + &head, + 0, + None, + ) + .await + .unwrap(); assert_eq!(ancestry, expected_ancestry); }); @@ -579,10 +591,16 @@ mod tests { .collect::>(); let test_fut = Box::pin(async move { - let ancestry = - determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 0, None) - .await - .unwrap(); + let ancestry = determine_new_blocks( + ctx.sender(), + |h| known.is_known(h), + head_hash, + &head, + 0, + None, + ) + .await + .unwrap(); assert_eq!(ancestry, expected_ancestry); }); From aaec541fab54634bd2bfc1c2e715b84dd97ff30e Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 10 Feb 2023 09:39:34 +0000 Subject: [PATCH 43/82] Remove Stage 9 --- node/jaeger/src/spans.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/node/jaeger/src/spans.rs b/node/jaeger/src/spans.rs index 6bed03c6ee27..a6183b5d25ea 100644 --- a/node/jaeger/src/spans.rs +++ b/node/jaeger/src/spans.rs @@ -163,7 +163,6 @@ pub enum Stage { AvailabilityRecovery = 6, BitfieldDistribution = 7, ApprovalChecking = 8, - ApprovalVoting = 9, // 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] From ede34172c8d9a788ede01d8ae5f96196d57dddc0 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Sun, 12 Feb 2023 14:01:13 +0100 Subject: [PATCH 44/82] Add missing spans --- node/core/approval-voting/src/lib.rs | 106 +++++++++++++++++---------- 1 file changed, 66 insertions(+), 40 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 68d5673d201f..3013c1507cb8 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -925,10 +925,8 @@ async fn handle_actions( while let Some(action) = actions_iter.next() { match action { Action::ScheduleWakeup { block_hash, block_number, candidate_hash, tick } => { - let _span = match state.spans.get(&block_hash) { - Some(s) => s.child("schedule-wakeup"), - None => jaeger::Span::Disabled, - }; + let span = state.spans.get(&block_hash).unwrap(); + let _schedule_wakeup_span = span.child("schedule-wakeup").with_stage(jaeger::Stage::ApprovalChecking); wakeups.schedule(block_hash, block_number, candidate_hash, tick); }, Action::IssueApproval(candidate_hash, approval_request) => { @@ -943,10 +941,6 @@ async fn handle_actions( // // Note that chaining these iterators is O(n) as we must consume // the prior iterator. - let _span = match state.spans.get(&approval_request.block_hash) { - Some(s) => s.child("issue-approval"), - None => jaeger::Span::Disabled, - }; let next_actions: Vec = issue_approval( ctx, state, @@ -973,17 +967,20 @@ async fn handle_actions( candidate, backing_group, } => { - let _span = match state.spans.get(&relay_block_hash) { - Some(s) => s.child("launch-approval"), - None => jaeger::Span::Disabled, - }; + let span = state.spans.get(&relay_block_hash).unwrap(); + let mut launch_approval_span = + span.child("launch-approval").with_stage(jaeger::Stage::ApprovalChecking); // Don't launch approval work if the node is syncing. if let Mode::Syncing(_) = *mode { continue } + launch_approval_span + .add_string_tag("candidate-hash", format!("{:?}", candidate_hash)); metrics.on_assignment_produced(assignment_tranche); let block_hash = indirect_cert.block_hash; + launch_approval_span + .add_string_tag("block-hash", format!("{:?}", block_hash)); let validator_index = indirect_cert.validator; ctx.send_unbounded_message(ApprovalDistributionMessage::DistributeAssignment( @@ -1018,6 +1015,7 @@ async fn handle_actions( validator_index, block_hash, backing_group, + &launch_approval_span, ) .await }, @@ -1028,10 +1026,10 @@ async fn handle_actions( } }, Action::NoteApprovedInChainSelection(block_hash) => { - let _span = match state.spans.get(&block_hash) { - Some(s) => s.child("note-approved-in-chain-selection"), - None => jaeger::Span::Disabled, - }; + let span = state.spans.get(&block_hash).unwrap(); + let _note_approved_span = span + .child("note-approved-in-chain-selection") + .with_stage(jaeger::Stage::ApprovalChecking); ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; }, Action::BecomeActive => { @@ -1062,10 +1060,10 @@ fn distribution_messages_for_activation( messages.push(ApprovalDistributionMessage::NewBlocks(Vec::new())); // dummy value. for block_hash in all_blocks { - let mut span = match state.spans.get(&block_hash) { - Some(s) => s.child("distribution-messages-for-activation"), - None => jaeger::Span::Disabled, - }; + let span = state.spans.get(&block_hash).unwrap(); + let mut distribution_message_span = span + .child("distribution-messages-for-activation") + .with_stage(jaeger::Stage::ApprovalChecking); let block_entry = match db.load_block_entry(&block_hash)? { Some(b) => b, None => { @@ -1074,8 +1072,10 @@ fn distribution_messages_for_activation( continue }, }; - span.add_string_tag("block-hash", &block_hash.to_string()); - span.add_string_tag("parent-hash", &block_entry.parent_hash().to_string()); + + distribution_message_span.add_string_tag("block-hash", &block_hash.to_string()); + distribution_message_span + .add_string_tag("parent-hash", &block_entry.parent_hash().to_string()); approval_meta.push(BlockApprovalMeta { hash: block_hash, number: block_entry.block_number(), @@ -1086,7 +1086,8 @@ fn distribution_messages_for_activation( }); for (i, (_, candidate_hash)) in block_entry.candidates().iter().enumerate() { - let _candidate_span = span.child("candidate").with_candidate(*candidate_hash); + let _candidate_span = + distribution_message_span.child("candidate").with_candidate(*candidate_hash); let candidate_entry = match db.load_candidate_entry(&candidate_hash)? { Some(c) => c, None => { @@ -1248,10 +1249,10 @@ async fn handle_from_overseer( })? .0, ApprovalVotingMessage::ApprovedAncestor(target, lower_bound, res) => { - let mut approved_ancestor_span = match state.spans.get(&target) { - Some(s) => s.child("approved-ancestor"), - None => jaeger::Span::Disabled, - }; + let span = state.spans.get(&target).unwrap(); + let mut approved_ancestor_span = + span.child("approved-ancestor").with_stage(jaeger::Stage::ApprovalChecking); + approved_ancestor_span.add_string_tag("target", format!("{:?}", target)); match handle_approved_ancestor( ctx, db, @@ -1387,7 +1388,7 @@ async fn handle_approved_ancestor( ) -> SubsystemResult> { const MAX_TRACING_WINDOW: usize = 200; const ABNORMAL_DEPTH_THRESHOLD: usize = 5; - + let mut span = span.child("handle-approved-ancestor"); use bitvec::{order::Lsb0, vec::BitVec}; let mut all_approved_max = None; @@ -1404,6 +1405,8 @@ async fn handle_approved_ancestor( } }; + span.add_uint_tag("target-number", target_number as u64); + span.add_uint_tag("lower-bound", lower_bound as u64); if target_number <= lower_bound { return Ok(None) } @@ -1433,6 +1436,9 @@ async fn handle_approved_ancestor( let mut bits: BitVec = Default::default(); for (i, block_hash) in std::iter::once(target).chain(ancestry).enumerate() { + let mut entry_span = + span.child("load-block-entry").with_stage(jaeger::Stage::ApprovalChecking); + entry_span.add_string_tag("block-hash", format!("{:?}", block_hash)); // Block entries should be present as the assumption is that // nothing here is finalized. If we encounter any missing block // entries we can fail. @@ -1488,8 +1494,12 @@ async fn handle_approved_ancestor( unapproved.len(), entry.candidates().len(), ); - + entry_span.add_uint_tag("unapproved-candidates", unapproved.len() as u64); for candidate_hash in unapproved { + let mut candidate_span = entry_span + .child("load-candidate-entry") + .with_stage(jaeger::Stage::ApprovalChecking); + candidate_span.add_string_tag("candidate-hash", format!("{:?}", candidate_hash)); match db.load_candidate_entry(&candidate_hash)? { None => { gum::warn!( @@ -1712,6 +1722,11 @@ fn check_and_import_assignment( candidate_index: CandidateIndex, ) -> SubsystemResult<(AssignmentCheckResult, Vec)> { let tick_now = state.clock.tick_now(); + let span = state.spans.get(&assignment.block_hash).unwrap(); + let mut check_and_import_assignment_span = span + .child("check-and-import-assignment") + .with_stage(jaeger::Stage::ApprovalChecking); + check_and_import_assignment_span.add_string_tag("block-hash", format!("{:?}", assignment.block_hash)); let block_entry = match db.load_block_entry(&assignment.block_hash)? { Some(b) => b, @@ -1735,6 +1750,9 @@ fn check_and_import_assignment( )), }; + check_and_import_assignment_span.add_uint_tag("needed-approvals", session_info.needed_approvals as u64); + check_and_import_assignment_span.add_uint_tag("no-show-slots", session_info.no_show_slots as u64); + let (claimed_core_index, assigned_candidate_hash) = match block_entry.candidate(candidate_index as usize) { Some((c, h)) => (*c, *h), @@ -1746,6 +1764,8 @@ fn check_and_import_assignment( Vec::new(), )), // no candidate at core. }; + + check_and_import_assignment_span.add_string_tag("assigned-candidate-hash", format!("{:?}", assigned_candidate_hash)); let mut candidate_entry = match db.load_candidate_entry(&assigned_candidate_hash)? { Some(c) => c, @@ -1805,6 +1825,8 @@ fn check_and_import_assignment( }, }; + check_and_import_assignment_span.add_uint_tag("tranche", tranche as u64); + let is_duplicate = approval_entry.is_assigned(assignment.validator); approval_entry.import_assignment(tranche, assignment.validator, tick_now); @@ -1858,6 +1880,9 @@ fn check_and_import_approval( }}; } + let span = state.spans.get(&approval.block_hash).unwrap(); + let mut check_and_import_approval_span = span.child("check-and-import-approval"); + check_and_import_approval_span.add_string_tag("block-hash", format!("{:?}", approval.block_hash)); let block_entry = match db.load_block_entry(&approval.block_hash)? { Some(b) => b, None => { @@ -1867,11 +1892,6 @@ fn check_and_import_approval( }, }; - let mut span = match state.spans.get(&block_entry.block_hash()) { - Some(s) => s.child("check-and-import-approval"), - None => jaeger::Span::Disabled, - }; - let session_info = match state.session_info(block_entry.session()) { Some(s) => s, None => { @@ -1888,8 +1908,6 @@ fn check_and_import_approval( )), }; - span.add_string_tag("candidate-hash", format!("{:?}", approved_candidate_hash)); - let pubkey = match session_info.validators.get(approval.validator) { Some(k) => k, None => respond_early!(ApprovalCheckResult::Bad( @@ -1998,6 +2016,9 @@ fn advance_approval_state( mut candidate_entry: CandidateEntry, transition: ApprovalStateTransition, ) -> Vec { + let span = state.spans.get(&block_entry.block_hash()).unwrap(); + let _advance_approval_state_span = span.child("advance-approval-state").with_stage(jaeger::Stage::ApprovalChecking); + let validator_index = transition.validator_index(); let already_approved_by = validator_index.as_ref().map(|v| candidate_entry.mark_approval(*v)); @@ -2166,10 +2187,8 @@ fn process_wakeup( _expected_tick: Tick, metrics: &Metrics, ) -> SubsystemResult> { - let _span = match state.spans.get(&relay_block) { - Some(s) => s.child("process-wakeup"), - None => jaeger::Span::Disabled, - }; + let span = state.spans.get(&relay_block).unwrap(); + let _process_wakeup_span = span.child("process-wakeup").with_stage(jaeger::Stage::ApprovalChecking); let block_entry = db.load_block_entry(&relay_block)?; let candidate_entry = db.load_candidate_entry(&candidate_hash)?; @@ -2312,7 +2331,9 @@ async fn launch_approval( validator_index: ValidatorIndex, block_hash: Hash, backing_group: GroupIndex, + span: &jaeger::Span, ) -> SubsystemResult> { + let mut launched_work_span = span.child("launched-approval-work-future").with_stage(jaeger::Stage::ApprovalChecking); let (a_tx, a_rx) = oneshot::channel(); let (code_tx, code_rx) = oneshot::channel(); @@ -2343,6 +2364,8 @@ async fn launch_approval( let candidate_hash = candidate.hash(); let para_id = candidate.descriptor.para_id; + launched_work_span.add_string_tag("candidate-hash", format!("{:?}", &candidate_hash)); + launched_work_span.add_string_tag("para-id", format!("{:?}", ¶_id)); gum::trace!(target: LOG_TARGET, ?candidate_hash, ?para_id, "Recovering data."); @@ -2500,6 +2523,9 @@ async fn issue_approval( candidate_hash: CandidateHash, ApprovalVoteRequest { validator_index, block_hash }: ApprovalVoteRequest, ) -> SubsystemResult> { + let span = state.spans.get(&block_hash).unwrap(); + let mut issue_approval_span = span.child("issue-approval").with_stage(jaeger::Stage::ApprovalChecking); + issue_approval_span.add_string_tag("candidate-hash", format!("{:?}", candidate_hash)); let block_entry = match db.load_block_entry(&block_hash)? { Some(b) => b, None => { From 0ab2c7851ccf93f000d4672556d6fc4c536d8875 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Sun, 12 Feb 2023 18:47:57 +0100 Subject: [PATCH 45/82] cargo +nightly fmt --all --- node/core/approval-voting/src/lib.rs | 36 ++++++++++++++++++---------- 1 file changed, 23 insertions(+), 13 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 3013c1507cb8..bc2cd9b09114 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -926,7 +926,8 @@ async fn handle_actions( match action { Action::ScheduleWakeup { block_hash, block_number, candidate_hash, tick } => { let span = state.spans.get(&block_hash).unwrap(); - let _schedule_wakeup_span = span.child("schedule-wakeup").with_stage(jaeger::Stage::ApprovalChecking); + let _schedule_wakeup_span = + span.child("schedule-wakeup").with_stage(jaeger::Stage::ApprovalChecking); wakeups.schedule(block_hash, block_number, candidate_hash, tick); }, Action::IssueApproval(candidate_hash, approval_request) => { @@ -979,8 +980,7 @@ async fn handle_actions( metrics.on_assignment_produced(assignment_tranche); let block_hash = indirect_cert.block_hash; - launch_approval_span - .add_string_tag("block-hash", format!("{:?}", block_hash)); + launch_approval_span.add_string_tag("block-hash", format!("{:?}", block_hash)); let validator_index = indirect_cert.validator; ctx.send_unbounded_message(ApprovalDistributionMessage::DistributeAssignment( @@ -1726,7 +1726,8 @@ fn check_and_import_assignment( let mut check_and_import_assignment_span = span .child("check-and-import-assignment") .with_stage(jaeger::Stage::ApprovalChecking); - check_and_import_assignment_span.add_string_tag("block-hash", format!("{:?}", assignment.block_hash)); + check_and_import_assignment_span + .add_string_tag("block-hash", format!("{:?}", assignment.block_hash)); let block_entry = match db.load_block_entry(&assignment.block_hash)? { Some(b) => b, @@ -1750,8 +1751,10 @@ fn check_and_import_assignment( )), }; - check_and_import_assignment_span.add_uint_tag("needed-approvals", session_info.needed_approvals as u64); - check_and_import_assignment_span.add_uint_tag("no-show-slots", session_info.no_show_slots as u64); + check_and_import_assignment_span + .add_uint_tag("needed-approvals", session_info.needed_approvals as u64); + check_and_import_assignment_span + .add_uint_tag("no-show-slots", session_info.no_show_slots as u64); let (claimed_core_index, assigned_candidate_hash) = match block_entry.candidate(candidate_index as usize) { @@ -1764,8 +1767,9 @@ fn check_and_import_assignment( Vec::new(), )), // no candidate at core. }; - - check_and_import_assignment_span.add_string_tag("assigned-candidate-hash", format!("{:?}", assigned_candidate_hash)); + + check_and_import_assignment_span + .add_string_tag("assigned-candidate-hash", format!("{:?}", assigned_candidate_hash)); let mut candidate_entry = match db.load_candidate_entry(&assigned_candidate_hash)? { Some(c) => c, @@ -1882,7 +1886,8 @@ fn check_and_import_approval( let span = state.spans.get(&approval.block_hash).unwrap(); let mut check_and_import_approval_span = span.child("check-and-import-approval"); - check_and_import_approval_span.add_string_tag("block-hash", format!("{:?}", approval.block_hash)); + check_and_import_approval_span + .add_string_tag("block-hash", format!("{:?}", approval.block_hash)); let block_entry = match db.load_block_entry(&approval.block_hash)? { Some(b) => b, None => { @@ -2017,7 +2022,8 @@ fn advance_approval_state( transition: ApprovalStateTransition, ) -> Vec { let span = state.spans.get(&block_entry.block_hash()).unwrap(); - let _advance_approval_state_span = span.child("advance-approval-state").with_stage(jaeger::Stage::ApprovalChecking); + let _advance_approval_state_span = + span.child("advance-approval-state").with_stage(jaeger::Stage::ApprovalChecking); let validator_index = transition.validator_index(); @@ -2188,7 +2194,8 @@ fn process_wakeup( metrics: &Metrics, ) -> SubsystemResult> { let span = state.spans.get(&relay_block).unwrap(); - let _process_wakeup_span = span.child("process-wakeup").with_stage(jaeger::Stage::ApprovalChecking); + let _process_wakeup_span = + span.child("process-wakeup").with_stage(jaeger::Stage::ApprovalChecking); let block_entry = db.load_block_entry(&relay_block)?; let candidate_entry = db.load_candidate_entry(&candidate_hash)?; @@ -2333,7 +2340,9 @@ async fn launch_approval( backing_group: GroupIndex, span: &jaeger::Span, ) -> SubsystemResult> { - let mut launched_work_span = span.child("launched-approval-work-future").with_stage(jaeger::Stage::ApprovalChecking); + let mut launched_work_span = span + .child("launched-approval-work-future") + .with_stage(jaeger::Stage::ApprovalChecking); let (a_tx, a_rx) = oneshot::channel(); let (code_tx, code_rx) = oneshot::channel(); @@ -2524,7 +2533,8 @@ async fn issue_approval( ApprovalVoteRequest { validator_index, block_hash }: ApprovalVoteRequest, ) -> SubsystemResult> { let span = state.spans.get(&block_hash).unwrap(); - let mut issue_approval_span = span.child("issue-approval").with_stage(jaeger::Stage::ApprovalChecking); + let mut issue_approval_span = + span.child("issue-approval").with_stage(jaeger::Stage::ApprovalChecking); issue_approval_span.add_string_tag("candidate-hash", format!("{:?}", candidate_hash)); let block_entry = match db.load_block_entry(&block_hash)? { Some(b) => b, From a7a8379b4616887f8d002c7f68b6d743cdf7457c Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Sun, 12 Feb 2023 19:38:49 +0100 Subject: [PATCH 46/82] Remove optional span argument for determine_new_blocks --- node/subsystem-util/src/determine_new_blocks.rs | 9 --------- 1 file changed, 9 deletions(-) diff --git a/node/subsystem-util/src/determine_new_blocks.rs b/node/subsystem-util/src/determine_new_blocks.rs index 37f5870d1f75..5322e96dc7b5 100644 --- a/node/subsystem-util/src/determine_new_blocks.rs +++ b/node/subsystem-util/src/determine_new_blocks.rs @@ -290,7 +290,6 @@ mod tests { head_hash, &head, lower_bound_number, - None, ) .await .unwrap(); @@ -364,7 +363,6 @@ mod tests { head_hash, &head, lower_bound_number, - None, ) .await .unwrap(); @@ -424,7 +422,6 @@ mod tests { head_hash, &head, lower_bound_number, - None, ) .await .unwrap(); @@ -461,7 +458,6 @@ mod tests { head_hash, &head, lower_bound_number, - None, ) .await .unwrap(); @@ -493,7 +489,6 @@ mod tests { head_hash, &head, 17, - None, ) .await .unwrap(); @@ -504,7 +499,6 @@ mod tests { head_hash, &head, 18, - None, ) .await .unwrap(); @@ -515,7 +509,6 @@ mod tests { head_hash, &head, 19, - None, ) .await .unwrap(); @@ -553,7 +546,6 @@ mod tests { head_hash, &head, 0, - None, ) .await .unwrap(); @@ -597,7 +589,6 @@ mod tests { head_hash, &head, 0, - None, ) .await .unwrap(); From 7d9783f3264d935d7a4e5ae4d76df228ed29e10c Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Mon, 13 Feb 2023 17:49:59 +0100 Subject: [PATCH 47/82] * Remove no-longer needed default PerLeafSpan implementation * Remove no-longer necessary mock span given re-factoring of handle_new_head() no longer neeing mutable span * Split validation-result and request-data (availability and validation code) spans into two by dropping request_validation_data_spans * Remove drop statements for cache_session_info_span * --- node/core/approval-voting/src/import.rs | 20 ++---- node/core/approval-voting/src/lib.rs | 47 ++++++-------- node/jaeger/src/spans.rs | 7 -- .../src/determine_new_blocks.rs | 65 ++++++------------- 4 files changed, 45 insertions(+), 94 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index b6b8e8363ddd..58c71a318c20 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -378,7 +378,6 @@ pub(crate) async fn handle_new_head( ?e, "Could not cache session info when processing head.", ); - drop(cache_session_span); return Ok(Vec::new()) }, Ok(Some(a @ SessionWindowUpdate::Advanced { .. })) => { @@ -387,11 +386,8 @@ pub(crate) async fn handle_new_head( update = ?a, "Advanced session window for approvals", ); - drop(cache_session_span); - }, - Ok(_) => { - drop(cache_session_span); }, + Ok(_) => {}, } // If we've just started the node and are far behind, @@ -1280,18 +1276,10 @@ pub(crate) mod tests { let test_fut = { Box::pin(async move { - let mut mock_span = jaeger::PerLeafSpan::default(); let mut overlay_db = OverlayedBackend::new(&db); - let result = handle_new_head( - &mut ctx, - &mut state, - &mut overlay_db, - hash, - &Some(1), - Some(&mut mock_span), - ) - .await - .unwrap(); + let result = handle_new_head(&mut ctx, &mut state, &mut overlay_db, hash, &Some(1)) + .await + .unwrap(); let write_ops = overlay_db.into_write_ops(); db.write(write_ops).unwrap(); diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index bc2cd9b09114..6e234a934e4f 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -880,7 +880,6 @@ where if !overlayed_db.is_empty() { let _timer = subsystem.metrics.time_db_transaction(); - let ops = overlayed_db.into_write_ops(); backend.write(ops)?; } @@ -969,14 +968,14 @@ async fn handle_actions( backing_group, } => { let span = state.spans.get(&relay_block_hash).unwrap(); - let mut launch_approval_span = - span.child("launch-approval").with_stage(jaeger::Stage::ApprovalChecking); + let mut launch_approval_span = span + .child("launch-approval") + .with_candidate(candidate_hash) + .with_stage(jaeger::Stage::ApprovalChecking); // Don't launch approval work if the node is syncing. if let Mode::Syncing(_) = *mode { continue } - launch_approval_span - .add_string_tag("candidate-hash", format!("{:?}", candidate_hash)); metrics.on_assignment_produced(assignment_tranche); let block_hash = indirect_cert.block_hash; @@ -1751,11 +1750,6 @@ fn check_and_import_assignment( )), }; - check_and_import_assignment_span - .add_uint_tag("needed-approvals", session_info.needed_approvals as u64); - check_and_import_assignment_span - .add_uint_tag("no-show-slots", session_info.no_show_slots as u64); - let (claimed_core_index, assigned_candidate_hash) = match block_entry.candidate(candidate_index as usize) { Some((c, h)) => (*c, *h), @@ -2340,9 +2334,6 @@ async fn launch_approval( backing_group: GroupIndex, span: &jaeger::Span, ) -> SubsystemResult> { - let mut launched_work_span = span - .child("launched-approval-work-future") - .with_stage(jaeger::Stage::ApprovalChecking); let (a_tx, a_rx) = oneshot::channel(); let (code_tx, code_rx) = oneshot::channel(); @@ -2373,9 +2364,6 @@ async fn launch_approval( let candidate_hash = candidate.hash(); let para_id = candidate.descriptor.para_id; - launched_work_span.add_string_tag("candidate-hash", format!("{:?}", &candidate_hash)); - launched_work_span.add_string_tag("para-id", format!("{:?}", ¶_id)); - gum::trace!(target: LOG_TARGET, ?candidate_hash, ?para_id, "Recovering data."); let timer = metrics.time_recover_and_approve(); @@ -2393,16 +2381,23 @@ async fn launch_approval( )) .await; + // Covers both validation code and available data currently + let _request_validation_data_span = span + .child("request-validation-data") + .with_candidate(candidate.hash()) + .with_stage(jaeger::Stage::ApprovalChecking); + + let mut validation_result_span = span + .child("validation-result") + .with_candidate(candidate_hash) + .with_stage(jaeger::Stage::ApprovalChecking); + validation_result_span.add_string_tag("para-id", format!("{:?}", para_id)); let candidate = candidate.clone(); let metrics_guard = StaleGuard(Some(metrics)); let mut sender = ctx.sender().clone(); let background = async move { // Force the move of the timer into the background task. let _timer = timer; - let _span = jaeger::Span::from_encodable((block_hash, candidate_hash), "launch-approval") - .with_relay_parent(block_hash) - .with_candidate(candidate_hash) - .with_stage(jaeger::Stage::ApprovalChecking); let available_data = match a_rx.await { Err(_) => return ApprovalState::failed(validator_index, candidate_hash), @@ -2459,9 +2454,9 @@ async fn launch_approval( return ApprovalState::failed(validator_index, candidate_hash) }, }; + drop(_request_validation_data_span); let (val_tx, val_rx) = oneshot::channel(); - sender .send_message(CandidateValidationMessage::ValidateFromExhaustive( available_data.validation_data, @@ -2499,7 +2494,6 @@ async fn launch_approval( candidate_hash, candidate.clone(), ); - metrics_guard.take().on_approval_invalid(); return ApprovalState::failed(validator_index, candidate_hash) }, @@ -2516,7 +2510,7 @@ async fn launch_approval( }, } }; - + drop(validation_result_span); let (background, remote_handle) = background.remote_handle(); ctx.spawn("approval-checks", Box::pin(background)).map(move |()| remote_handle) } @@ -2533,9 +2527,10 @@ async fn issue_approval( ApprovalVoteRequest { validator_index, block_hash }: ApprovalVoteRequest, ) -> SubsystemResult> { let span = state.spans.get(&block_hash).unwrap(); - let mut issue_approval_span = - span.child("issue-approval").with_stage(jaeger::Stage::ApprovalChecking); - issue_approval_span.add_string_tag("candidate-hash", format!("{:?}", candidate_hash)); + let _issue_approval_span = span + .child("issue-approval") + .with_candidate(candidate_hash) + .with_stage(jaeger::Stage::ApprovalChecking); let block_entry = match db.load_block_entry(&block_hash)? { Some(b) => b, None => { diff --git a/node/jaeger/src/spans.rs b/node/jaeger/src/spans.rs index a6183b5d25ea..7f9743cc8917 100644 --- a/node/jaeger/src/spans.rs +++ b/node/jaeger/src/spans.rs @@ -124,13 +124,6 @@ impl PerLeafSpan { } } -/// Default implementation, can be handy in tests dependent upon a mocked PerLeafSpan. -impl std::default::Default for PerLeafSpan { - fn default() -> Self { - Self::new(Arc::new(Span::Disabled), "default") - } -} - /// Returns a reference to the child span. impl std::ops::Deref for PerLeafSpan { type Target = Span; diff --git a/node/subsystem-util/src/determine_new_blocks.rs b/node/subsystem-util/src/determine_new_blocks.rs index 5322e96dc7b5..5a032c38aa1e 100644 --- a/node/subsystem-util/src/determine_new_blocks.rs +++ b/node/subsystem-util/src/determine_new_blocks.rs @@ -483,35 +483,20 @@ mod tests { known.insert(parent_hash); let test_fut = Box::pin(async move { - let after_finality = determine_new_blocks( - ctx.sender(), - |h| known.is_known(h), - head_hash, - &head, - 17, - ) - .await - .unwrap(); + let after_finality = + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 17) + .await + .unwrap(); - let at_finality = determine_new_blocks( - ctx.sender(), - |h| known.is_known(h), - head_hash, - &head, - 18, - ) - .await - .unwrap(); + let at_finality = + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 18) + .await + .unwrap(); - let before_finality = determine_new_blocks( - ctx.sender(), - |h| known.is_known(h), - head_hash, - &head, - 19, - ) - .await - .unwrap(); + let before_finality = + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 19) + .await + .unwrap(); assert_eq!(after_finality, vec![(head_hash, head.clone())]); @@ -540,15 +525,10 @@ mod tests { .collect::>(); let test_fut = Box::pin(async move { - let ancestry = determine_new_blocks( - ctx.sender(), - |h| known.is_known(h), - head_hash, - &head, - 0, - ) - .await - .unwrap(); + let ancestry = + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 0) + .await + .unwrap(); assert_eq!(ancestry, expected_ancestry); }); @@ -583,15 +563,10 @@ mod tests { .collect::>(); let test_fut = Box::pin(async move { - let ancestry = determine_new_blocks( - ctx.sender(), - |h| known.is_known(h), - head_hash, - &head, - 0, - ) - .await - .unwrap(); + let ancestry = + determine_new_blocks(ctx.sender(), |h| known.is_known(h), head_hash, &head, 0) + .await + .unwrap(); assert_eq!(ancestry, expected_ancestry); }); From 06e448f6603c535702dadf6211f4a4e2955b0932 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Mon, 13 Feb 2023 17:54:43 +0100 Subject: [PATCH 48/82] Remove unnecessary span --- node/core/approval-voting/src/lib.rs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 6e234a934e4f..a9e62704ec8d 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1495,10 +1495,6 @@ async fn handle_approved_ancestor( ); entry_span.add_uint_tag("unapproved-candidates", unapproved.len() as u64); for candidate_hash in unapproved { - let mut candidate_span = entry_span - .child("load-candidate-entry") - .with_stage(jaeger::Stage::ApprovalChecking); - candidate_span.add_string_tag("candidate-hash", format!("{:?}", candidate_hash)); match db.load_candidate_entry(&candidate_hash)? { None => { gum::warn!( From 9eca698024eb616429e03c06c3e4d00d6e8f32f7 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Mon, 13 Feb 2023 17:58:51 +0100 Subject: [PATCH 49/82] Remove another excessively spammy span --- node/core/approval-voting/src/lib.rs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index a9e62704ec8d..0f9b7292dba4 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -2011,10 +2011,6 @@ fn advance_approval_state( mut candidate_entry: CandidateEntry, transition: ApprovalStateTransition, ) -> Vec { - let span = state.spans.get(&block_entry.block_hash()).unwrap(); - let _advance_approval_state_span = - span.child("advance-approval-state").with_stage(jaeger::Stage::ApprovalChecking); - let validator_index = transition.validator_index(); let already_approved_by = validator_index.as_ref().map(|v| candidate_entry.mark_approval(*v)); From c96022fdfcb88a8784b8ee5aa1e73458dc608296 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 14 Feb 2023 10:14:52 +0000 Subject: [PATCH 50/82] Add missing spans from State in import tests --- node/core/approval-voting/src/import.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 58c71a318c20..4edbff55f1d8 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -693,6 +693,7 @@ pub(crate) mod tests { assignment_criteria: Box::new(MockAssignmentCriteria), db, db_config: TEST_CONFIG, + spans: HashMap::new(), } } From a61a21bc7ad6acbbf4e7953809adeb9aa93d1522 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 14 Feb 2023 17:27:44 +0000 Subject: [PATCH 51/82] Use functional approach to get spans --- node/core/approval-voting/src/lib.rs | 104 ++++++++++++++++++--------- 1 file changed, 70 insertions(+), 34 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 0f9b7292dba4..9cdfbd2d04ef 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -924,9 +924,15 @@ async fn handle_actions( while let Some(action) = actions_iter.next() { match action { Action::ScheduleWakeup { block_hash, block_number, candidate_hash, tick } => { - let span = state.spans.get(&block_hash).unwrap(); - let _schedule_wakeup_span = - span.child("schedule-wakeup").with_stage(jaeger::Stage::ApprovalChecking); + let _span = state + .spans + .get(&block_hash) + .map(|span| span.child("schedule-wakeup")) + .unwrap_or(jaeger::Span::new(block_hash, "schedule-wakeup")) + .with_stage(jaeger::Stage::ApprovalChecking) + .with_candidate(candidate_hash) + .with_uint_tag("block-number", block_number as u64); + wakeups.schedule(block_hash, block_number, candidate_hash, tick); }, Action::IssueApproval(candidate_hash, approval_request) => { @@ -967,16 +973,19 @@ async fn handle_actions( candidate, backing_group, } => { - let span = state.spans.get(&relay_block_hash).unwrap(); - let mut launch_approval_span = span - .child("launch-approval") - .with_candidate(candidate_hash) - .with_stage(jaeger::Stage::ApprovalChecking); // Don't launch approval work if the node is syncing. if let Mode::Syncing(_) = *mode { continue } + let mut launch_approval_span = state + .spans + .get(&relay_block_hash) + .map(|span| span.child("launch-approval")) + .unwrap_or(jaeger::Span::new(relay_block_hash, "launch-approval")) + .with_candidate(candidate_hash) + .with_stage(jaeger::Stage::ApprovalChecking); + metrics.on_assignment_produced(assignment_tranche); let block_hash = indirect_cert.block_hash; launch_approval_span.add_string_tag("block-hash", format!("{:?}", block_hash)); @@ -1025,9 +1034,12 @@ async fn handle_actions( } }, Action::NoteApprovedInChainSelection(block_hash) => { - let span = state.spans.get(&block_hash).unwrap(); - let _note_approved_span = span - .child("note-approved-in-chain-selection") + let _span = state + .spans + .get(&block_hash) + .map(|span| span.child("note-approved-in-chain-selection")) + .unwrap_or(jaeger::Span::new(block_hash, "note-approved-in-chain-selection")) + .with_string_tag("block-hash", format!("{:?}", block_hash)) .with_stage(jaeger::Stage::ApprovalChecking); ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; }, @@ -1059,10 +1071,13 @@ fn distribution_messages_for_activation( messages.push(ApprovalDistributionMessage::NewBlocks(Vec::new())); // dummy value. for block_hash in all_blocks { - let span = state.spans.get(&block_hash).unwrap(); - let mut distribution_message_span = span - .child("distribution-messages-for-activation") - .with_stage(jaeger::Stage::ApprovalChecking); + let mut distribution_message_span = state + .spans + .get(&block_hash) + .map(|span| span.child("distribution-messages-for-activation")) + .unwrap_or(jaeger::Span::new(block_hash, "distribution-messages-for-activation")) + .with_stage(jaeger::Stage::ApprovalChecking) + .with_string_tag("block-hash", format!("{:?}", block_hash)); let block_entry = match db.load_block_entry(&block_hash)? { Some(b) => b, None => { @@ -1228,6 +1243,7 @@ async fn handle_from_overseer( .map_err(|e| SubsystemError::with_origin("db", e))?; wakeups.prune_finalized_wakeups(block_number); + // Logic for pruning the spans of the approval voting subsystem state.spans.remove(&block_hash); Vec::new() }, @@ -1248,10 +1264,13 @@ async fn handle_from_overseer( })? .0, ApprovalVotingMessage::ApprovedAncestor(target, lower_bound, res) => { - let span = state.spans.get(&target).unwrap(); - let mut approved_ancestor_span = - span.child("approved-ancestor").with_stage(jaeger::Stage::ApprovalChecking); - approved_ancestor_span.add_string_tag("target", format!("{:?}", target)); + let mut approved_ancestor_span = state + .spans + .get(&target) + .map(|span| span.child("approved-ancestor")) + .unwrap_or(jaeger::Span::new(target, "approved-ancestor")) + .with_stage(jaeger::Stage::ApprovalChecking) + .with_string_tag("target", format!("{:?}", target)); match handle_approved_ancestor( ctx, db, @@ -1717,12 +1736,16 @@ fn check_and_import_assignment( candidate_index: CandidateIndex, ) -> SubsystemResult<(AssignmentCheckResult, Vec)> { let tick_now = state.clock.tick_now(); - let span = state.spans.get(&assignment.block_hash).unwrap(); - let mut check_and_import_assignment_span = span - .child("check-and-import-assignment") + + let mut check_and_import_assignment_span = state + .spans + .get(&assignment.block_hash) + .map(|span| span.child("check-and-import-assignment")) + .unwrap_or(jaeger::Span::new(assignment.block_hash, "check-and-import-assignment")) + .with_string_tag("block-hash", format!("{:?}", assignment.block_hash)) + .with_stage(jaeger::Stage::ApprovalChecking) + .with_uint_tag("candidate-index", candidate_index as u64) .with_stage(jaeger::Stage::ApprovalChecking); - check_and_import_assignment_span - .add_string_tag("block-hash", format!("{:?}", assignment.block_hash)); let block_entry = match db.load_block_entry(&assignment.block_hash)? { Some(b) => b, @@ -1874,10 +1897,15 @@ fn check_and_import_approval( }}; } - let span = state.spans.get(&approval.block_hash).unwrap(); - let mut check_and_import_approval_span = span.child("check-and-import-approval"); - check_and_import_approval_span - .add_string_tag("block-hash", format!("{:?}", approval.block_hash)); + let _span = state + .spans + .get(&approval.block_hash) + .map(|span| span.child("check-and-import-approval")) + .unwrap_or(jaeger::Span::new(approval.block_hash, "check-and-import-approval-span")) + .with_uint_tag("candidate-index", approval.candidate_index as u64) + .with_string_tag("block-hash", format!("{:?}", approval.block_hash)) + .with_stage(jaeger::Stage::ApprovalChecking); + let block_entry = match db.load_block_entry(&approval.block_hash)? { Some(b) => b, None => { @@ -2179,9 +2207,14 @@ fn process_wakeup( _expected_tick: Tick, metrics: &Metrics, ) -> SubsystemResult> { - let span = state.spans.get(&relay_block).unwrap(); - let _process_wakeup_span = - span.child("process-wakeup").with_stage(jaeger::Stage::ApprovalChecking); + let _span = state + .spans + .get(&relay_block) + .map(|span| span.child("process-wakeup")) + .unwrap_or(jaeger::Span::new(relay_block, "process-wakeup")) + .with_candidate(candidate_hash) + .with_stage(jaeger::Stage::ApprovalChecking); + let block_entry = db.load_block_entry(&relay_block)?; let candidate_entry = db.load_candidate_entry(&candidate_hash)?; @@ -2518,11 +2551,14 @@ async fn issue_approval( candidate_hash: CandidateHash, ApprovalVoteRequest { validator_index, block_hash }: ApprovalVoteRequest, ) -> SubsystemResult> { - let span = state.spans.get(&block_hash).unwrap(); - let _issue_approval_span = span - .child("issue-approval") + let _issue_approval_span = state + .spans + .get(&block_hash) + .map(|span| span.child("issue-approval")) + .unwrap_or(jaeger::Span::new(block_hash, "issue-approval")) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); + let block_entry = match db.load_block_entry(&block_hash)? { Some(b) => b, None => { From ae4e614df12b7ea183dcc7b6b46317fab0c323db Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 15 Feb 2023 18:09:33 +0000 Subject: [PATCH 52/82] - Add functional approach for the approval-voting span - Add doc on block_numbers given labelling ambiguity - Add span pruning logic - Use .add_para_id on validation_result_span --- node/core/approval-voting/src/import.rs | 34 ++++++++++--------------- node/core/approval-voting/src/lib.rs | 20 ++++++++++----- 2 files changed, 27 insertions(+), 27 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 4edbff55f1d8..53e7fb937acb 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -329,12 +329,15 @@ pub(crate) async fn handle_new_head( finalized_number: &Option, ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; - let handle_new_head_span = match state.spans.get(&head) { - Some(s) => s.child("handle-new-head"), - None => jaeger::Span::Disabled, - }; + let mut handle_new_head_span = state + .spans + .get(&head) + .map(|span| span.child("handle-new-head")) + .unwrap_or(jaeger::Span::new(head, "handle-new-head")) + .with_stage(jaeger::Stage::ApprovalChecking); + let header = { - let mut get_header_span = handle_new_head_span.child("get-block-header"); + let _get_header_span = handle_new_head_span.child("get-block-header"); let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; match h_rx.await? { @@ -345,31 +348,23 @@ pub(crate) async fn handle_new_head( e, ); // May be a better way of handling errors here. - get_header_span - .add_string_tag("header", format!("Error from Chain API subsystem: {:?}", e)); return Ok(Vec::new()) }, Ok(None) => { gum::warn!(target: LOG_TARGET, "Missing header for new head {}", head); // May be a better way of handling warnings here. - get_header_span - .add_string_tag("header", format!("Missing header for new head {}", head)); return Ok(Vec::new()) }, - Ok(Some(h)) => { - get_header_span.add_string_tag("parent-hash", format!("{:?}", h.parent_hash)); - get_header_span.add_string_tag("number", format!("{:?}", h.number)); - get_header_span.add_string_tag("state_root", format!("{:?}", h.state_root)); - get_header_span - .add_string_tag("extrinsics_root", format!("{:?}", h.extrinsics_root)); - h - }, + Ok(Some(h)) => h, } }; + handle_new_head_span.add_string_tag("block-number", format!("{:?}", &header.number)); + // Update session info based on most recent head. - let mut cache_session_span = handle_new_head_span.child("cache-session-info"); - cache_session_span.add_string_tag("head", format!("{:?}", head)); + let _cache_session_span = handle_new_head_span + .child("cache-session-info") + .with_string_tag("head", format!("{:?}", head)); match state.cache_session_info_for_head(ctx, head).await { Err(e) => { gum::debug!( @@ -634,7 +629,6 @@ pub(crate) async fn handle_new_head( ); ctx.send_unbounded_message(ApprovalDistributionMessage::NewBlocks(approval_meta)); - Ok(imported_candidates) } diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 9cdfbd2d04ef..1f6fa8c8dfca 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -431,6 +431,7 @@ struct Wakeups { // Tick -> [(Relay Block, Candidate Hash)] wakeups: BTreeMap>, reverse_wakeups: HashMap<(Hash, CandidateHash), Tick>, + /// A mapping from block numbers to hashes. block_numbers: BTreeMap>, } @@ -1243,8 +1244,12 @@ async fn handle_from_overseer( .map_err(|e| SubsystemError::with_origin("db", e))?; wakeups.prune_finalized_wakeups(block_number); - // Logic for pruning the spans of the approval voting subsystem - state.spans.remove(&block_hash); + + // We let prune_finalized_wakeups decide whether we prune the span for a finalized block. + for hash_set in wakeups.block_numbers.values().cloned() { + state.spans.retain(|hash, _| hash_set.contains(hash)); + } + Vec::new() }, FromOrchestra::Signal(OverseerSignal::Conclude) => { @@ -2407,16 +2412,17 @@ async fn launch_approval( .await; // Covers both validation code and available data currently - let _request_validation_data_span = span + let request_validation_data_span = span .child("request-validation-data") .with_candidate(candidate.hash()) .with_stage(jaeger::Stage::ApprovalChecking); - let mut validation_result_span = span + let validation_result_span = span .child("validation-result") .with_candidate(candidate_hash) - .with_stage(jaeger::Stage::ApprovalChecking); - validation_result_span.add_string_tag("para-id", format!("{:?}", para_id)); + .with_stage(jaeger::Stage::ApprovalChecking) + .add_para_id(para_id); + let candidate = candidate.clone(); let metrics_guard = StaleGuard(Some(metrics)); let mut sender = ctx.sender().clone(); @@ -2479,7 +2485,7 @@ async fn launch_approval( return ApprovalState::failed(validator_index, candidate_hash) }, }; - drop(_request_validation_data_span); + drop(request_validation_data_span); let (val_tx, val_rx) = oneshot::channel(); sender From 7383ea216c4242ca08e297cf5b91acc49728fb9e Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 16 Feb 2023 10:07:36 +0000 Subject: [PATCH 53/82] Replace for hash_set in hash_set_iter with map closure --- node/core/approval-voting/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 1f6fa8c8dfca..5f7b02f8fb0b 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1246,9 +1246,9 @@ async fn handle_from_overseer( wakeups.prune_finalized_wakeups(block_number); // We let prune_finalized_wakeups decide whether we prune the span for a finalized block. - for hash_set in wakeups.block_numbers.values().cloned() { + wakeups.block_numbers.values().map(| hash_set | { state.spans.retain(|hash, _| hash_set.contains(hash)); - } + }); Vec::new() }, From a92d891d93c3a3625718ee972ae6e43850e4a5d5 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 16 Feb 2023 10:09:48 +0000 Subject: [PATCH 54/82] cargo +nightly fmt --all --- node/core/approval-voting/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 5f7b02f8fb0b..eda0f93d3689 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1246,7 +1246,7 @@ async fn handle_from_overseer( wakeups.prune_finalized_wakeups(block_number); // We let prune_finalized_wakeups decide whether we prune the span for a finalized block. - wakeups.block_numbers.values().map(| hash_set | { + wakeups.block_numbers.values().map(|hash_set| { state.spans.retain(|hash, _| hash_set.contains(hash)); }); From bb03a5bfb446a800b46abc2897f7c55e99d3c253 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 16 Feb 2023 10:45:55 +0000 Subject: [PATCH 55/82] Change from unconsumed `map` to `.for_each` --- node/core/approval-voting/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index eda0f93d3689..f369835c82ea 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1246,8 +1246,8 @@ async fn handle_from_overseer( wakeups.prune_finalized_wakeups(block_number); // We let prune_finalized_wakeups decide whether we prune the span for a finalized block. - wakeups.block_numbers.values().map(|hash_set| { - state.spans.retain(|hash, _| hash_set.contains(hash)); + wakeups.block_numbers.values().for_each(|hash_set| { + state.spans.retain(|hash, _| hash_set.contains(hash)) }); Vec::new() From 43a47e953f9de0a6f59a9601b97a7bb9159fdf19 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 16 Feb 2023 10:51:36 +0000 Subject: [PATCH 56/82] cargo +nightly fmt --all --- node/core/approval-voting/src/lib.rs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index f369835c82ea..becd30de5a50 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1246,9 +1246,10 @@ async fn handle_from_overseer( wakeups.prune_finalized_wakeups(block_number); // We let prune_finalized_wakeups decide whether we prune the span for a finalized block. - wakeups.block_numbers.values().for_each(|hash_set| { - state.spans.retain(|hash, _| hash_set.contains(hash)) - }); + wakeups + .block_numbers + .values() + .for_each(|hash_set| state.spans.retain(|hash, _| hash_set.contains(hash))); Vec::new() }, From a6d618fb85486f2db66394cfdd473a1d0a9c43d2 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 16 Feb 2023 11:42:28 +0000 Subject: [PATCH 57/82] Refactor add_para_id to validation_result_span --- node/core/approval-voting/src/lib.rs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index becd30de5a50..f8cfbc55a1a9 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -2418,11 +2418,12 @@ async fn launch_approval( .with_candidate(candidate.hash()) .with_stage(jaeger::Stage::ApprovalChecking); - let validation_result_span = span + let mut validation_result_span = span .child("validation-result") .with_candidate(candidate_hash) - .with_stage(jaeger::Stage::ApprovalChecking) - .add_para_id(para_id); + .with_stage(jaeger::Stage::ApprovalChecking); + + validation_result_span.add_string_tag("para-id", format!("{:?}", para_id)); let candidate = candidate.clone(); let metrics_guard = StaleGuard(Some(metrics)); From 4613d8bf2f7e2c35fafee810bba477f3cabefb3f Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 16 Feb 2023 11:43:19 +0000 Subject: [PATCH 58/82] cargo +nightly fmt --all --- node/core/approval-voting/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index f8cfbc55a1a9..0395505222e2 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -2422,7 +2422,7 @@ async fn launch_approval( .child("validation-result") .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); - + validation_result_span.add_string_tag("para-id", format!("{:?}", para_id)); let candidate = candidate.clone(); From 424838f4a98683530ab28a12459e79872ca1e981 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 16 Feb 2023 11:49:09 +0000 Subject: [PATCH 59/82] Remove duplicate tag --- node/core/approval-voting/src/lib.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 0395505222e2..3cbdbe6a156e 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1749,7 +1749,6 @@ fn check_and_import_assignment( .map(|span| span.child("check-and-import-assignment")) .unwrap_or(jaeger::Span::new(assignment.block_hash, "check-and-import-assignment")) .with_string_tag("block-hash", format!("{:?}", assignment.block_hash)) - .with_stage(jaeger::Stage::ApprovalChecking) .with_uint_tag("candidate-index", candidate_index as u64) .with_stage(jaeger::Stage::ApprovalChecking); From 13fbc824659e3b2bb4b03b114796e60474c67423 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 16 Feb 2023 12:43:54 +0000 Subject: [PATCH 60/82] Add missing tag to handle-approved-ancestor span --- node/core/approval-voting/src/lib.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 3cbdbe6a156e..36a160160425 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1412,7 +1412,9 @@ async fn handle_approved_ancestor( ) -> SubsystemResult> { const MAX_TRACING_WINDOW: usize = 200; const ABNORMAL_DEPTH_THRESHOLD: usize = 5; - let mut span = span.child("handle-approved-ancestor"); + let mut span = span + .child("handle-approved-ancestor") + .with_stage(jaeger::Stage::ApprovalChecking); use bitvec::{order::Lsb0, vec::BitVec}; let mut all_approved_max = None; From b1285496dcd67f5853182da3e17878448ec23ab7 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Mon, 20 Feb 2023 08:10:57 +0000 Subject: [PATCH 61/82] Refactor span pruning to only invoke retain once --- node/core/approval-voting/src/lib.rs | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 36a160160425..54e01926d094 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1246,10 +1246,8 @@ async fn handle_from_overseer( wakeups.prune_finalized_wakeups(block_number); // We let prune_finalized_wakeups decide whether we prune the span for a finalized block. - wakeups - .block_numbers - .values() - .for_each(|hash_set| state.spans.retain(|hash, _| hash_set.contains(hash))); + let hash_set = wakeups.block_numbers.values().flatten().collect::>(); + state.spans.retain(|hash, _| hash_set.contains(hash)); Vec::new() }, From 9bffea446408e9040ab7abd9c8f819e6e2f4743e Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Mon, 20 Feb 2023 10:40:03 +0000 Subject: [PATCH 62/82] Typo in span name --- node/core/approval-voting/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 54e01926d094..9cd66cf70e9f 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1906,7 +1906,7 @@ fn check_and_import_approval( .spans .get(&approval.block_hash) .map(|span| span.child("check-and-import-approval")) - .unwrap_or(jaeger::Span::new(approval.block_hash, "check-and-import-approval-span")) + .unwrap_or(jaeger::Span::new(approval.block_hash, "check-and-import-approval")) .with_uint_tag("candidate-index", approval.candidate_index as u64) .with_string_tag("block-hash", format!("{:?}", approval.block_hash)) .with_stage(jaeger::Stage::ApprovalChecking); From bda1fd7b70ff0a804a09ad79a0a3626972848d76 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 21 Feb 2023 16:38:36 +0000 Subject: [PATCH 63/82] - Replace unwrap_or with unwrap_or_else due to lazy evaluation of trace-identifier in polkadot_node_jaeger - Remove some redundant spans --- node/core/approval-voting/src/import.rs | 34 ++++--------------------- node/core/approval-voting/src/lib.rs | 18 ++++++------- 2 files changed, 14 insertions(+), 38 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 53e7fb937acb..56613d73fcac 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -329,15 +329,15 @@ pub(crate) async fn handle_new_head( finalized_number: &Option, ) -> SubsystemResult> { const MAX_HEADS_LOOK_BACK: BlockNumber = MAX_FINALITY_LAG; - let mut handle_new_head_span = state + let _handle_new_head_span = state .spans .get(&head) .map(|span| span.child("handle-new-head")) - .unwrap_or(jaeger::Span::new(head, "handle-new-head")) + .unwrap_or_else(|| jaeger::Span::new(head, "handle-new-head")) + .with_string_tag("head", format!("{:?}", head)) .with_stage(jaeger::Stage::ApprovalChecking); let header = { - let _get_header_span = handle_new_head_span.child("get-block-header"); let (h_tx, h_rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::BlockHeader(head, h_tx)).await; match h_rx.await? { @@ -359,12 +359,7 @@ pub(crate) async fn handle_new_head( } }; - handle_new_head_span.add_string_tag("block-number", format!("{:?}", &header.number)); - // Update session info based on most recent head. - let _cache_session_span = handle_new_head_span - .child("cache-session-info") - .with_string_tag("head", format!("{:?}", head)); match state.cache_session_info_for_head(ctx, head).await { Err(e) => { gum::debug!( @@ -409,15 +404,8 @@ pub(crate) async fn handle_new_head( // `determine_new_blocks` gives us a vec in backwards order. we want to move forwards. let imported_blocks_and_info = { - let mut imported_blocks_and_info_span = - handle_new_head_span.child("imported-blocks-and-info"); - imported_blocks_and_info_span.add_uint_tag("new-blocks-count", new_blocks.len() as u64); let mut imported_blocks_and_info = Vec::with_capacity(new_blocks.len()); for (block_hash, block_header) in new_blocks.into_iter().rev() { - let mut new_block_span = imported_blocks_and_info_span.child("new-block"); - new_block_span.add_string_tag("block-hash", format!("{:?}", block_hash)); - new_block_span.add_uint_tag("block-number", block_header.number as u64); - let env = ImportedBlockInfoEnv { session_window: &state.session_window, assignment_criteria: &*state.assignment_criteria, @@ -429,24 +417,14 @@ pub(crate) async fn handle_new_head( imported_blocks_and_info.push((block_hash, block_header, i)); }, Err(error) => { - new_block_span - .add_string_tag("imported-block-info-error", format!("{:?}", error)); // It's possible that we've lost a race with finality. let (tx, rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::FinalizedBlockHash(block_header.number, tx)) .await; let lost_to_finality = match rx.await { - Ok(Ok(Some(h))) if h != block_hash => { - new_block_span - .add_string_tag("lost-to-finality", format!("{:?}", true)); - true - }, - _ => { - new_block_span - .add_string_tag("lost-to-finality", format!("{:?}", false)); - false - }, + Ok(Ok(Some(h))) if h != block_hash => true, + _ => false, }; if !lost_to_finality { @@ -473,7 +451,6 @@ pub(crate) async fn handle_new_head( imported_blocks = imported_blocks_and_info.len(), "Inserting imported blocks into database" ); - let mut db_insertion_span = handle_new_head_span.child("block-db-insertion"); for (block_hash, block_header, imported_block_info) in imported_blocks_and_info { let ImportedBlockInfo { @@ -538,7 +515,6 @@ pub(crate) async fn handle_new_head( result } }; - db_insertion_span.add_uint_tag("approved-bitfields", approved_bitfield.count_ones() as u64); // If all bits are already set, then send an approve message. if approved_bitfield.count_ones() == approved_bitfield.len() { ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 9cd66cf70e9f..c0ff8dcc07fc 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -929,7 +929,7 @@ async fn handle_actions( .spans .get(&block_hash) .map(|span| span.child("schedule-wakeup")) - .unwrap_or(jaeger::Span::new(block_hash, "schedule-wakeup")) + .unwrap_or_else(|| jaeger::Span::new(block_hash, "schedule-wakeup")) .with_stage(jaeger::Stage::ApprovalChecking) .with_candidate(candidate_hash) .with_uint_tag("block-number", block_number as u64); @@ -983,7 +983,7 @@ async fn handle_actions( .spans .get(&relay_block_hash) .map(|span| span.child("launch-approval")) - .unwrap_or(jaeger::Span::new(relay_block_hash, "launch-approval")) + .unwrap_or_else(|| jaeger::Span::new(relay_block_hash, "launch-approval")) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); @@ -1039,7 +1039,7 @@ async fn handle_actions( .spans .get(&block_hash) .map(|span| span.child("note-approved-in-chain-selection")) - .unwrap_or(jaeger::Span::new(block_hash, "note-approved-in-chain-selection")) + .unwrap_or_else(|| jaeger::Span::new(block_hash, "note-approved-in-chain-selection")) .with_string_tag("block-hash", format!("{:?}", block_hash)) .with_stage(jaeger::Stage::ApprovalChecking); ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; @@ -1076,7 +1076,7 @@ fn distribution_messages_for_activation( .spans .get(&block_hash) .map(|span| span.child("distribution-messages-for-activation")) - .unwrap_or(jaeger::Span::new(block_hash, "distribution-messages-for-activation")) + .unwrap_or_else(|| jaeger::Span::new(block_hash, "distribution-messages-for-activation")) .with_stage(jaeger::Stage::ApprovalChecking) .with_string_tag("block-hash", format!("{:?}", block_hash)); let block_entry = match db.load_block_entry(&block_hash)? { @@ -1272,7 +1272,7 @@ async fn handle_from_overseer( .spans .get(&target) .map(|span| span.child("approved-ancestor")) - .unwrap_or(jaeger::Span::new(target, "approved-ancestor")) + .unwrap_or_else(|| jaeger::Span::new(target, "approved-ancestor")) .with_stage(jaeger::Stage::ApprovalChecking) .with_string_tag("target", format!("{:?}", target)); match handle_approved_ancestor( @@ -1747,7 +1747,7 @@ fn check_and_import_assignment( .spans .get(&assignment.block_hash) .map(|span| span.child("check-and-import-assignment")) - .unwrap_or(jaeger::Span::new(assignment.block_hash, "check-and-import-assignment")) + .unwrap_or_else(|| jaeger::Span::new(assignment.block_hash, "check-and-import-assignment")) .with_string_tag("block-hash", format!("{:?}", assignment.block_hash)) .with_uint_tag("candidate-index", candidate_index as u64) .with_stage(jaeger::Stage::ApprovalChecking); @@ -1906,7 +1906,7 @@ fn check_and_import_approval( .spans .get(&approval.block_hash) .map(|span| span.child("check-and-import-approval")) - .unwrap_or(jaeger::Span::new(approval.block_hash, "check-and-import-approval")) + .unwrap_or_else(|| jaeger::Span::new(approval.block_hash, "check-and-import-approval")) .with_uint_tag("candidate-index", approval.candidate_index as u64) .with_string_tag("block-hash", format!("{:?}", approval.block_hash)) .with_stage(jaeger::Stage::ApprovalChecking); @@ -2216,7 +2216,7 @@ fn process_wakeup( .spans .get(&relay_block) .map(|span| span.child("process-wakeup")) - .unwrap_or(jaeger::Span::new(relay_block, "process-wakeup")) + .unwrap_or_else(|| jaeger::Span::new(relay_block, "process-wakeup")) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); @@ -2562,7 +2562,7 @@ async fn issue_approval( .spans .get(&block_hash) .map(|span| span.child("issue-approval")) - .unwrap_or(jaeger::Span::new(block_hash, "issue-approval")) + .unwrap_or_else(|| jaeger::Span::new(block_hash, "issue-approval")) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); From 2ad97954f996a423f27d6457ffdc7904f8a75fe5 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 22 Feb 2023 15:53:12 +0000 Subject: [PATCH 64/82] Add approval-distribution spans --- Cargo.lock | 1 + node/jaeger/src/spans.rs | 23 ++++++++ node/network/approval-distribution/Cargo.toml | 1 + node/network/approval-distribution/src/lib.rs | 53 +++++++++++++++++-- 4 files changed, 73 insertions(+), 5 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 7d8c37e9728c..45eeb11151a9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6431,6 +6431,7 @@ dependencies = [ "env_logger 0.9.0", "futures", "log", + "polkadot-node-jaeger", "polkadot-node-metrics", "polkadot-node-network-protocol", "polkadot-node-primitives", diff --git a/node/jaeger/src/spans.rs b/node/jaeger/src/spans.rs index 7f9743cc8917..c4aa3f4b9cc1 100644 --- a/node/jaeger/src/spans.rs +++ b/node/jaeger/src/spans.rs @@ -156,6 +156,7 @@ pub enum Stage { AvailabilityRecovery = 6, BitfieldDistribution = 7, ApprovalChecking = 8, + ApprovalDistribution = 9, // 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] @@ -290,6 +291,28 @@ impl Span { } } + /// Derive a child span with a traceID string tag set to the decimal representation of the CandidateHash. + pub fn child_with_trace_id(&self, name: &'static str, trace_id: CandidateHash) -> Self { + let mut span = match self { + Self::Enabled(inner) => Self::Enabled(inner.child(name)), + Self::Disabled => Self::Disabled, + }; + span.add_string_tag("traceID", hash_to_trace_identifier(trace_id.0).to_string()); + span + } + + /// Derive a child span with a start time set to the current system time using mick_jaeger::StartTime::now(). + /// This is useful for spans that are created after the parent span has started. + pub fn child_with_start_time(&self, name: &'static str) -> Self { + match self { + Self::Enabled(inner) => { + let start_time = mick_jaeger::StartTime::now(); + Self::Enabled(inner.child(name).with_start_time_override(start_time)) + }, + Self::Disabled => Self::Disabled, + } + } + #[inline(always)] pub fn with_string_tag(mut self, tag: &'static str, val: V) -> Self { self.add_string_tag::(tag, val); diff --git a/node/network/approval-distribution/Cargo.toml b/node/network/approval-distribution/Cargo.toml index 6df854072aa6..87e7d8456188 100644 --- a/node/network/approval-distribution/Cargo.toml +++ b/node/network/approval-distribution/Cargo.toml @@ -10,6 +10,7 @@ polkadot-node-network-protocol = { path = "../protocol" } polkadot-node-primitives = { path = "../../primitives" } polkadot-node-subsystem = { path = "../../subsystem" } polkadot-primitives = { path = "../../../primitives" } +polkadot-node-jaeger = { path = "../../jaeger" } rand = "0.8" futures = "0.3.21" diff --git a/node/network/approval-distribution/src/lib.rs b/node/network/approval-distribution/src/lib.rs index 3c6ed8661e0e..d9348a979bf0 100644 --- a/node/network/approval-distribution/src/lib.rs +++ b/node/network/approval-distribution/src/lib.rs @@ -20,6 +20,7 @@ #![warn(missing_docs)] +use polkadot_node_jaeger as jaeger; use futures::{channel::oneshot, FutureExt as _}; use polkadot_node_network_protocol::{ self as net_protocol, @@ -35,7 +36,7 @@ use polkadot_node_subsystem::{ ApprovalCheckResult, ApprovalDistributionMessage, ApprovalVotingMessage, AssignmentCheckResult, NetworkBridgeEvent, NetworkBridgeTxMessage, }, - overseer, ActiveLeavesUpdate, FromOrchestra, OverseerSignal, SpawnedSubsystem, SubsystemError, + overseer, FromOrchestra, OverseerSignal, SpawnedSubsystem, SubsystemError, }; use polkadot_primitives::{ BlockNumber, CandidateIndex, Hash, SessionIndex, ValidatorIndex, ValidatorSignature, @@ -180,6 +181,9 @@ struct State { /// Config for aggression. aggression_config: AggressionConfig, + + /// HashMap from active leaves to spans + spans: HashMap, } #[derive(Debug, Clone, Copy, PartialEq, Eq)] @@ -390,9 +394,18 @@ impl State { ) { let mut new_hashes = HashSet::new(); for meta in &metas { + let mut span = self + .spans + .get(&meta.hash) + .map(|span| span.child_with_start_time(&"handle-new-blocks")) + .unwrap_or_else(|| jaeger::Span::new(meta.hash, &"handle-new-blocks")) + .with_relay_parent(meta.hash) + .with_stage(jaeger::Stage::ApprovalDistribution); + match self.blocks.entry(meta.hash) { hash_map::Entry::Vacant(entry) => { let candidates_count = meta.candidates.len(); + span.add_uint_tag("candidates-count", candidates_count as u64); let mut candidates = Vec::with_capacity(candidates_count); candidates.resize_with(candidates_count, Default::default); @@ -688,6 +701,8 @@ impl State { old_blocks.values().flatten().for_each(|relay_block| { self.recent_outdated_blocks.note_outdated(*relay_block); if let Some(block_entry) = self.blocks.remove(relay_block) { + // We should remove the span associated with the relay block to avoid memory leaks. + self.spans.remove(&relay_block); self.topologies.dec_session_refs(block_entry.session); } }); @@ -1230,6 +1245,14 @@ impl State { ) -> HashMap { let mut all_sigs = HashMap::new(); for (hash, index) in indices { + let _span = self + .spans + .get(&hash) + .map(|span| span.child("get-approval-signatures")) + .unwrap_or_else(|| jaeger::Span::new(&hash, "get-approval-signatures")) + .with_relay_parent(hash) + .with_stage(jaeger::Stage::ApprovalDistribution); + let block_entry = match self.blocks.get(&hash) { None => { gum::debug!( @@ -1650,13 +1673,17 @@ impl ApprovalDistribution { match message { FromOrchestra::Communication { msg } => Self::handle_incoming(&mut ctx, state, msg, &self.metrics, rng).await, - FromOrchestra::Signal(OverseerSignal::ActiveLeaves(ActiveLeavesUpdate { - .. - })) => { + FromOrchestra::Signal(OverseerSignal::ActiveLeaves(update)) => { gum::trace!(target: LOG_TARGET, "active leaves signal (ignored)"); // the relay chain blocks relevant to the approval subsystems // are those that are available, but not finalized yet - // actived and deactivated heads hence are irrelevant to this subsystem + // actived and deactivated heads hence are irrelevant to this subsystem, other than + // for tracing purposes. + if let Some(activated) = update.activated { + let head = activated.hash; + let approval_distribution_span = jaeger::PerLeafSpan::new(activated.span, "approval-distribution"); + state.spans.insert(head, approval_distribution_span); + } }, FromOrchestra::Signal(OverseerSignal::BlockFinalized(_hash, number)) => { gum::trace!(target: LOG_TARGET, number = %number, "finalized signal"); @@ -1682,6 +1709,14 @@ impl ApprovalDistribution { state.handle_new_blocks(ctx, metrics, metas, rng).await; }, ApprovalDistributionMessage::DistributeAssignment(cert, candidate_index) => { + let _span = state + .spans + .get(&cert.block_hash) + .map(|span| span.child("distribute-assignment")) + .unwrap_or_else(|| jaeger::Span::new(&cert.block_hash, "distribute-assignment")) + .with_relay_parent(cert.block_hash) + .with_stage(jaeger::Stage::ApprovalDistribution); + gum::debug!( target: LOG_TARGET, "Distributing our assignment on candidate (block={}, index={})", @@ -1701,6 +1736,14 @@ impl ApprovalDistribution { .await; }, ApprovalDistributionMessage::DistributeApproval(vote) => { + let _span = state + .spans + .get(&vote.block_hash) + .map(|span| span.child("distribute-approval")) + .unwrap_or_else(|| jaeger::Span::new(&vote.block_hash, "distribute-approval")) + .with_relay_parent(vote.block_hash) + .with_stage(jaeger::Stage::ApprovalDistribution); + gum::debug!( target: LOG_TARGET, "Distributing our approval vote on candidate (block={}, index={})", From ae046693e8a56d4f552b21e41528e706fb09483e Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 22 Feb 2023 15:54:30 +0000 Subject: [PATCH 65/82] - Add unwrap_or_else on note-approved-in-chain-selection - Use child_with_trace_id to add traceID string tag on span (note this does not change the traceID, but just adds a tag) --- node/core/approval-voting/src/lib.rs | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index c0ff8dcc07fc..539beb4cf1a9 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1039,7 +1039,9 @@ async fn handle_actions( .spans .get(&block_hash) .map(|span| span.child("note-approved-in-chain-selection")) - .unwrap_or_else(|| jaeger::Span::new(block_hash, "note-approved-in-chain-selection")) + .unwrap_or_else(|| { + jaeger::Span::new(block_hash, "note-approved-in-chain-selection") + }) .with_string_tag("block-hash", format!("{:?}", block_hash)) .with_stage(jaeger::Stage::ApprovalChecking); ctx.send_message(ChainSelectionMessage::Approved(block_hash)).await; @@ -1076,7 +1078,9 @@ fn distribution_messages_for_activation( .spans .get(&block_hash) .map(|span| span.child("distribution-messages-for-activation")) - .unwrap_or_else(|| jaeger::Span::new(block_hash, "distribution-messages-for-activation")) + .unwrap_or_else(|| { + jaeger::Span::new(block_hash, "distribution-messages-for-activation") + }) .with_stage(jaeger::Stage::ApprovalChecking) .with_string_tag("block-hash", format!("{:?}", block_hash)); let block_entry = match db.load_block_entry(&block_hash)? { @@ -2215,8 +2219,9 @@ fn process_wakeup( let _span = state .spans .get(&relay_block) - .map(|span| span.child("process-wakeup")) - .unwrap_or_else(|| jaeger::Span::new(relay_block, "process-wakeup")) + .map(|span| span.child_with_trace_id("process-wakeup", candidate_hash)) + .unwrap_or_else(|| jaeger::Span::new(candidate_hash, "process-wakeup")) + .with_relay_parent(relay_block) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); From 58676a32094a3d92de1bc42f02ba45aba78fa3ff Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 22 Feb 2023 16:03:34 +0000 Subject: [PATCH 66/82] cargo +nightly fmt --all --- node/network/approval-distribution/src/lib.rs | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/node/network/approval-distribution/src/lib.rs b/node/network/approval-distribution/src/lib.rs index d9348a979bf0..e3af13b5cdf7 100644 --- a/node/network/approval-distribution/src/lib.rs +++ b/node/network/approval-distribution/src/lib.rs @@ -20,8 +20,8 @@ #![warn(missing_docs)] -use polkadot_node_jaeger as jaeger; use futures::{channel::oneshot, FutureExt as _}; +use polkadot_node_jaeger as jaeger; use polkadot_node_network_protocol::{ self as net_protocol, grid_topology::{RandomRouting, RequiredRouting, SessionGridTopologies, SessionGridTopology}, @@ -395,12 +395,12 @@ impl State { let mut new_hashes = HashSet::new(); for meta in &metas { let mut span = self - .spans - .get(&meta.hash) - .map(|span| span.child_with_start_time(&"handle-new-blocks")) - .unwrap_or_else(|| jaeger::Span::new(meta.hash, &"handle-new-blocks")) - .with_relay_parent(meta.hash) - .with_stage(jaeger::Stage::ApprovalDistribution); + .spans + .get(&meta.hash) + .map(|span| span.child_with_start_time(&"handle-new-blocks")) + .unwrap_or_else(|| jaeger::Span::new(meta.hash, &"handle-new-blocks")) + .with_relay_parent(meta.hash) + .with_stage(jaeger::Stage::ApprovalDistribution); match self.blocks.entry(meta.hash) { hash_map::Entry::Vacant(entry) => { @@ -1252,7 +1252,7 @@ impl State { .unwrap_or_else(|| jaeger::Span::new(&hash, "get-approval-signatures")) .with_relay_parent(hash) .with_stage(jaeger::Stage::ApprovalDistribution); - + let block_entry = match self.blocks.get(&hash) { None => { gum::debug!( @@ -1681,7 +1681,8 @@ impl ApprovalDistribution { // for tracing purposes. if let Some(activated) = update.activated { let head = activated.hash; - let approval_distribution_span = jaeger::PerLeafSpan::new(activated.span, "approval-distribution"); + let approval_distribution_span = + jaeger::PerLeafSpan::new(activated.span, "approval-distribution"); state.spans.insert(head, approval_distribution_span); } }, From cbb38c641af44a21509e4dbc1780750ad6eae571 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 23 Feb 2023 15:12:05 +0000 Subject: [PATCH 67/82] - Add traceID tags were necessary in approval-voting and availability-distribution - Always use block-hash tag in stead of relay-parent tag in approval-distribution --- node/core/approval-voting/src/lib.rs | 32 ++++++++++------- node/network/approval-distribution/src/lib.rs | 10 +++--- .../availability-distribution/src/lib.rs | 27 ++++++++++++-- .../src/pov_requester/mod.rs | 19 +++++++--- .../src/requester/fetch_task/mod.rs | 29 ++++++++------- .../src/requester/mod.rs | 36 +++++++++++++++++-- .../src/responder.rs | 8 +++-- 7 files changed, 118 insertions(+), 43 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 539beb4cf1a9..8cbaf98b8717 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -928,11 +928,12 @@ async fn handle_actions( let _span = state .spans .get(&block_hash) - .map(|span| span.child("schedule-wakeup")) + .map(|span| span.child_with_trace_id("schedule-wakeup", candidate_hash)) .unwrap_or_else(|| jaeger::Span::new(block_hash, "schedule-wakeup")) - .with_stage(jaeger::Stage::ApprovalChecking) + .with_string_tag("leaf", format!("{:?}", block_hash)) + .with_uint_tag("block-number", block_number as u64) .with_candidate(candidate_hash) - .with_uint_tag("block-number", block_number as u64); + .with_stage(jaeger::Stage::ApprovalChecking); wakeups.schedule(block_hash, block_number, candidate_hash, tick); }, @@ -1278,7 +1279,7 @@ async fn handle_from_overseer( .map(|span| span.child("approved-ancestor")) .unwrap_or_else(|| jaeger::Span::new(target, "approved-ancestor")) .with_stage(jaeger::Stage::ApprovalChecking) - .with_string_tag("target", format!("{:?}", target)); + .with_string_tag("leaf", format!("{:?}", target)); match handle_approved_ancestor( ctx, db, @@ -1433,7 +1434,7 @@ async fn handle_approved_ancestor( } }; - span.add_uint_tag("target-number", target_number as u64); + span.add_uint_tag("leaf-number", target_number as u64); span.add_uint_tag("lower-bound", lower_bound as u64); if target_number <= lower_bound { return Ok(None) @@ -1645,8 +1646,8 @@ async fn handle_approved_ancestor( }); match all_approved_max { Some(HighestApprovedAncestorBlock { ref hash, ref number, .. }) => { - span.add_uint_tag("approved-number", *number as u64); - span.add_string_fmt_debug_tag("approved-hash", hash); + span.add_uint_tag("highest-approved-number", *number as u64); + span.add_string_fmt_debug_tag("highest-approved-hash", hash); }, None => { span.add_string_tag("reached-lower-bound", "true"); @@ -1752,7 +1753,7 @@ fn check_and_import_assignment( .get(&assignment.block_hash) .map(|span| span.child("check-and-import-assignment")) .unwrap_or_else(|| jaeger::Span::new(assignment.block_hash, "check-and-import-assignment")) - .with_string_tag("block-hash", format!("{:?}", assignment.block_hash)) + .with_relay_parent(assignment.block_hash) .with_uint_tag("candidate-index", candidate_index as u64) .with_stage(jaeger::Stage::ApprovalChecking); @@ -1791,7 +1792,11 @@ fn check_and_import_assignment( }; check_and_import_assignment_span - .add_string_tag("assigned-candidate-hash", format!("{:?}", assigned_candidate_hash)); + .add_string_tag("candidate-hash", format!("{:?}", assigned_candidate_hash)); + check_and_import_assignment_span.add_string_tag( + "traceID", + format!("{:?}", jaeger::hash_to_trace_identifier(assigned_candidate_hash.0)), + ); let mut candidate_entry = match db.load_candidate_entry(&assigned_candidate_hash)? { Some(c) => c, @@ -1912,7 +1917,7 @@ fn check_and_import_approval( .map(|span| span.child("check-and-import-approval")) .unwrap_or_else(|| jaeger::Span::new(approval.block_hash, "check-and-import-approval")) .with_uint_tag("candidate-index", approval.candidate_index as u64) - .with_string_tag("block-hash", format!("{:?}", approval.block_hash)) + .with_relay_parent(approval.block_hash) .with_stage(jaeger::Stage::ApprovalChecking); let block_entry = match db.load_block_entry(&approval.block_hash)? { @@ -2563,12 +2568,14 @@ async fn issue_approval( candidate_hash: CandidateHash, ApprovalVoteRequest { validator_index, block_hash }: ApprovalVoteRequest, ) -> SubsystemResult> { - let _issue_approval_span = state + let mut issue_approval_span = state .spans .get(&block_hash) - .map(|span| span.child("issue-approval")) + .map(|span| span.child_with_trace_id("issue-approval", candidate_hash)) .unwrap_or_else(|| jaeger::Span::new(block_hash, "issue-approval")) + .with_string_tag("leaf", format!("{:?}", block_hash)) .with_candidate(candidate_hash) + .with_validator_index(validator_index) .with_stage(jaeger::Stage::ApprovalChecking); let block_entry = match db.load_block_entry(&block_hash)? { @@ -2595,6 +2602,7 @@ async fn issue_approval( }, Some(idx) => idx, }; + issue_approval_span.add_int_tag("candidate_index", candidate_index as i64); let session_info = match state.session_info(block_entry.session()) { Some(s) => s, diff --git a/node/network/approval-distribution/src/lib.rs b/node/network/approval-distribution/src/lib.rs index e3af13b5cdf7..421274e82628 100644 --- a/node/network/approval-distribution/src/lib.rs +++ b/node/network/approval-distribution/src/lib.rs @@ -397,9 +397,9 @@ impl State { let mut span = self .spans .get(&meta.hash) - .map(|span| span.child_with_start_time(&"handle-new-blocks")) + .map(|span| span.child(&"handle-new-blocks")) .unwrap_or_else(|| jaeger::Span::new(meta.hash, &"handle-new-blocks")) - .with_relay_parent(meta.hash) + .with_string_tag("block-hash", format!("{:?}", meta.hash)) .with_stage(jaeger::Stage::ApprovalDistribution); match self.blocks.entry(meta.hash) { @@ -1250,7 +1250,7 @@ impl State { .get(&hash) .map(|span| span.child("get-approval-signatures")) .unwrap_or_else(|| jaeger::Span::new(&hash, "get-approval-signatures")) - .with_relay_parent(hash) + .with_string_tag("block-hash", format!("{:?}", hash)) .with_stage(jaeger::Stage::ApprovalDistribution); let block_entry = match self.blocks.get(&hash) { @@ -1715,7 +1715,7 @@ impl ApprovalDistribution { .get(&cert.block_hash) .map(|span| span.child("distribute-assignment")) .unwrap_or_else(|| jaeger::Span::new(&cert.block_hash, "distribute-assignment")) - .with_relay_parent(cert.block_hash) + .with_string_tag("block-hash", format!("{:?}", cert.block_hash)) .with_stage(jaeger::Stage::ApprovalDistribution); gum::debug!( @@ -1742,7 +1742,7 @@ impl ApprovalDistribution { .get(&vote.block_hash) .map(|span| span.child("distribute-approval")) .unwrap_or_else(|| jaeger::Span::new(&vote.block_hash, "distribute-approval")) - .with_relay_parent(vote.block_hash) + .with_string_tag("block-hash", format!("{:?}", vote.block_hash)) .with_stage(jaeger::Stage::ApprovalDistribution); gum::debug!( diff --git a/node/network/availability-distribution/src/lib.rs b/node/network/availability-distribution/src/lib.rs index 7dceb5f80e6c..e46783de312e 100644 --- a/node/network/availability-distribution/src/lib.rs +++ b/node/network/availability-distribution/src/lib.rs @@ -20,9 +20,11 @@ use sp_keystore::SyncCryptoStorePtr; use polkadot_node_network_protocol::request_response::{v1, IncomingRequestReceiver}; use polkadot_node_subsystem::{ - messages::AvailabilityDistributionMessage, overseer, FromOrchestra, OverseerSignal, + jaeger, messages::AvailabilityDistributionMessage, overseer, FromOrchestra, OverseerSignal, SpawnedSubsystem, SubsystemError, }; +use polkadot_primitives::Hash; +use std::collections::HashMap; /// Error and [`Result`] type for this subsystem. mod error; @@ -95,6 +97,7 @@ impl AvailabilityDistributionSubsystem { /// Start processing work as passed on from the Overseer. async fn run(self, mut ctx: Context) -> std::result::Result<(), FatalError> { let Self { mut runtime, recvs, metrics } = self; + let mut spans: HashMap = HashMap::new(); let IncomingRequestReceivers { pov_req_receiver, chunk_req_receiver } = recvs; let mut requester = Requester::new(metrics.clone()).fuse(); @@ -135,15 +138,24 @@ impl AvailabilityDistributionSubsystem { }; match message { FromOrchestra::Signal(OverseerSignal::ActiveLeaves(update)) => { + let cloned_leaf = match update.activated.clone() { + Some(activated) => activated, + None => continue, + }; + let span = + jaeger::PerLeafSpan::new(cloned_leaf.span, "availability-distribution"); + spans.insert(cloned_leaf.hash, span); log_error( requester .get_mut() - .update_fetching_heads(&mut ctx, &mut runtime, update) + .update_fetching_heads(&mut ctx, &mut runtime, update, &spans) .await, "Error in Requester::update_fetching_heads", )?; }, - FromOrchestra::Signal(OverseerSignal::BlockFinalized(..)) => {}, + FromOrchestra::Signal(OverseerSignal::BlockFinalized(hash, _)) => { + spans.remove(&hash); + }, FromOrchestra::Signal(OverseerSignal::Conclude) => return Ok(()), FromOrchestra::Communication { msg: @@ -156,6 +168,14 @@ impl AvailabilityDistributionSubsystem { tx, }, } => { + let span = spans + .get(&relay_parent) + .map(|span| span.child_with_trace_id("fetch-pov", candidate_hash)) + .unwrap_or_else(|| jaeger::Span::new(&relay_parent, "fetch-pov")) + .with_candidate(candidate_hash) + .with_relay_parent(relay_parent) + .with_stage(jaeger::Stage::AvailabilityDistribution); + log_error( pov_requester::fetch_pov( &mut ctx, @@ -167,6 +187,7 @@ impl AvailabilityDistributionSubsystem { pov_hash, tx, metrics.clone(), + &span, ) .await, "pov_requester::fetch_pov", diff --git a/node/network/availability-distribution/src/pov_requester/mod.rs b/node/network/availability-distribution/src/pov_requester/mod.rs index 2d9f53e63f5f..2a595be43ab6 100644 --- a/node/network/availability-distribution/src/pov_requester/mod.rs +++ b/node/network/availability-distribution/src/pov_requester/mod.rs @@ -52,7 +52,17 @@ pub async fn fetch_pov( pov_hash: Hash, tx: oneshot::Sender, metrics: Metrics, + span: &jaeger::Span, ) -> Result<()> { + let span = span + .child_with_trace_id("fetch-pov", candidate_hash) + .with_validator_index(from_validator) + .with_candidate(candidate_hash) + .with_para_id(para_id) + .with_relay_parent(parent) + .with_string_tag("pov-hash", format!("{:?}", pov_hash)) + .with_stage(jaeger::Stage::AvailabilityDistribution); + let info = &runtime.get_session_info(ctx.sender(), parent).await?.session_info; let authority_id = info .discovery_keys @@ -71,10 +81,6 @@ pub async fn fetch_pov( )) .await; - let span = jaeger::Span::new(candidate_hash, "fetch-pov") - .with_validator_index(from_validator) - .with_relay_parent(parent) - .with_para_id(para_id); ctx.spawn( "pov-fetcher", fetch_pov_job(para_id, pov_hash, authority_id, pending_response.boxed(), span, tx, metrics) @@ -103,10 +109,13 @@ async fn fetch_pov_job( async fn do_fetch_pov( pov_hash: Hash, pending_response: BoxFuture<'static, std::result::Result>, - _span: jaeger::Span, + span: jaeger::Span, tx: oneshot::Sender, metrics: Metrics, ) -> Result<()> { + let _span = span + .child_with_start_time("do-fetch-pov") + .with_stage(jaeger::Stage::AvailabilityDistribution); let response = pending_response.await.map_err(Error::FetchPoV); let pov = match response { Ok(PoVFetchingResponse::PoV(pov)) => pov, diff --git a/node/network/availability-distribution/src/requester/fetch_task/mod.rs b/node/network/availability-distribution/src/requester/fetch_task/mod.rs index 09e12aece47f..432003ae1b4f 100644 --- a/node/network/availability-distribution/src/requester/fetch_task/mod.rs +++ b/node/network/availability-distribution/src/requester/fetch_task/mod.rs @@ -140,7 +140,17 @@ impl FetchTaskConfig { sender: mpsc::Sender, metrics: Metrics, session_info: &SessionInfo, + span: jaeger::Span, ) -> Self { + let span = span + .child_with_trace_id("fetch-task-config", core.candidate_hash) + .with_string_tag("leaf", format!("{:?}", leaf)) + .with_validator_index(session_info.our_index) + .with_uint_tag("group-index", core.group_responsible.0 as u64) + .with_relay_parent(core.candidate_descriptor.relay_parent) + .with_string_tag("pov-hash", format!("{:?}", core.candidate_descriptor.pov_hash)) + .with_stage(jaeger::Stage::AvailabilityDistribution); + let live_in = vec![leaf].into_iter().collect(); // Don't run tasks for our backing group: @@ -148,9 +158,6 @@ impl FetchTaskConfig { return FetchTaskConfig { live_in, prepared_running: None } } - let span = jaeger::Span::new(core.candidate_hash, "availability-distribution") - .with_stage(jaeger::Stage::AvailabilityDistribution); - let prepared_running = RunningTask { session_index: session_info.session_index, group_index: core.group_responsible, @@ -251,20 +258,18 @@ impl RunningTask { let mut bad_validators = Vec::new(); let mut succeeded = false; let mut count: u32 = 0; - let mut _span = self - .span - .child("fetch-task") - .with_chunk_index(self.request.index.0) - .with_relay_parent(self.relay_parent); + let mut span = self.span.child("run-fetch-chunk-task").with_relay_parent(self.relay_parent); // Try validators in reverse order: while let Some(validator) = self.group.pop() { - let _try_span = _span.child("try"); // Report retries: if count > 0 { self.metrics.on_retry(); } count += 1; - + let _chunk_fetch_span = span + .child("fetch-chunk-request") + .with_chunk_index(self.request.index.0) + .with_stage(jaeger::Stage::AvailabilityDistribution); // Send request: let resp = match self.do_request(&validator).await { Ok(resp) => resp, @@ -308,10 +313,10 @@ impl RunningTask { // Ok, let's store it and be happy: self.store_chunk(chunk).await; succeeded = true; - _span.add_string_tag("success", "true"); + span.add_string_tag("success", "true"); break } - _span.add_int_tag("tries", count as _); + span.add_int_tag("tries", count as _); if succeeded { self.metrics.on_fetch(SUCCEEDED); self.conclude(bad_validators).await; diff --git a/node/network/availability-distribution/src/requester/mod.rs b/node/network/availability-distribution/src/requester/mod.rs index 088937b6e995..2b6628b975b2 100644 --- a/node/network/availability-distribution/src/requester/mod.rs +++ b/node/network/availability-distribution/src/requester/mod.rs @@ -33,6 +33,7 @@ use futures::{ }; use polkadot_node_subsystem::{ + jaeger, messages::{ChainApiMessage, RuntimeApiMessage}, overseer, ActivatedLeaf, ActiveLeavesUpdate, LeafStatus, }; @@ -100,14 +101,22 @@ impl Requester { ctx: &mut Context, runtime: &mut RuntimeInfo, update: ActiveLeavesUpdate, + spans: &HashMap, ) -> Result<()> { gum::trace!(target: LOG_TARGET, ?update, "Update fetching heads"); let ActiveLeavesUpdate { activated, deactivated } = update; // Stale leaves happen after a reversion - we don't want to re-run availability there. if let Some(leaf) = activated.filter(|leaf| leaf.status == LeafStatus::Fresh) { + let span = spans + .get(&leaf.hash) + .map(|span| span.child("update-fetching-heads")) + .unwrap_or_else(|| jaeger::Span::new(&leaf.hash, "update-fetching-heads")) + .with_string_tag("leaf", format!("{:?}", leaf.hash)) + .with_stage(jaeger::Stage::AvailabilityDistribution); + // Order important! We need to handle activated, prior to deactivated, otherwise we might // cancel still needed jobs. - self.start_requesting_chunks(ctx, runtime, leaf).await?; + self.start_requesting_chunks(ctx, runtime, leaf, &span).await?; } self.stop_requesting_chunks(deactivated.into_iter()); @@ -123,7 +132,13 @@ impl Requester { ctx: &mut Context, runtime: &mut RuntimeInfo, new_head: ActivatedLeaf, + span: &jaeger::Span, ) -> Result<()> { + let mut span = span + .child("request-chunks") + .with_string_tag("leaf", format!("{:?}", new_head.hash)) + .with_stage(jaeger::Stage::AvailabilityDistribution); + let sender = &mut ctx.sender().clone(); let ActivatedLeaf { hash: leaf, .. } = new_head; let (leaf_session_index, ancestors_in_session) = get_block_ancestors_in_same_session( @@ -133,8 +148,15 @@ impl Requester { Self::LEAF_ANCESTRY_LEN_WITHIN_SESSION, ) .await?; + span.add_uint_tag("ancestors-in-session", ancestors_in_session.len() as u64); + // Also spawn or bump tasks for candidates in ancestry in the same session. for hash in std::iter::once(leaf).chain(ancestors_in_session) { + let span = span + .child("get-occupied-cores") + .with_string_tag("leaf", format!("{:?}", hash.clone())) + .with_stage(jaeger::Stage::AvailabilityDistribution); + let cores = get_occupied_cores(sender, hash).await?; gum::trace!( target: LOG_TARGET, @@ -148,7 +170,7 @@ impl Requester { // The next time the subsystem receives leaf update, some of spawned task will be bumped // to be live in fresh relay parent, while some might get dropped due to the current leaf // being deactivated. - self.add_cores(ctx, runtime, leaf, leaf_session_index, cores).await?; + self.add_cores(ctx, runtime, leaf, leaf_session_index, cores, span).await?; } Ok(()) @@ -178,15 +200,23 @@ impl Requester { leaf: Hash, leaf_session_index: SessionIndex, cores: impl IntoIterator, + span: jaeger::Span, ) -> Result<()> { for core in cores { + let mut span = span + .child_with_trace_id("check-fetch-candidate", core.candidate_hash) + .with_string_tag("leaf", format!("{:?}", leaf)) + .with_candidate(core.candidate_hash) + .with_stage(jaeger::Stage::AvailabilityDistribution); match self.fetches.entry(core.candidate_hash) { Entry::Occupied(mut e) => // Just book keeping - we are already requesting that chunk: { + span.add_string_tag("alread-requested-chunk", "true"); e.get_mut().add_leaf(leaf); }, Entry::Vacant(e) => { + span.add_string_tag("already-requested-chunk", "false"); let tx = self.tx.clone(); let metrics = self.metrics.clone(); @@ -201,7 +231,7 @@ impl Requester { // be fetchable by the state trie. leaf, leaf_session_index, - |info| FetchTaskConfig::new(leaf, &core, tx, metrics, info), + |info| FetchTaskConfig::new(leaf, &core, tx, metrics, info, span), ) .await .map_err(|err| { diff --git a/node/network/availability-distribution/src/responder.rs b/node/network/availability-distribution/src/responder.rs index daf0c3175bf3..fa7884f49348 100644 --- a/node/network/availability-distribution/src/responder.rs +++ b/node/network/availability-distribution/src/responder.rs @@ -156,7 +156,7 @@ pub async fn answer_pov_request( where Sender: SubsystemSender, { - let _span = jaeger::Span::new(req.payload.candidate_hash, "answer-pov-request"); + let mut span = jaeger::Span::new(req.payload.candidate_hash, "answer-pov-request"); let av_data = query_available_data(sender, req.payload.candidate_hash).await?; @@ -184,9 +184,11 @@ pub async fn answer_chunk_request( where Sender: SubsystemSender, { - let span = jaeger::Span::new(req.payload.candidate_hash, "answer-chunk-request"); + let mut span = jaeger::Span::new(req.payload.candidate_hash, "answer-chunk-request"); - let _child_span = span.child("answer-chunk-request").with_chunk_index(req.payload.index.0); + let _child_span = span + .child_with_trace_id("answer-chunk-request", req.payload.candidate_hash) + .with_chunk_index(req.payload.index.0); let chunk = query_chunk(sender, req.payload.candidate_hash, req.payload.index).await?; From 495739c4413a392d9b24659c6d1a37fc959cc852 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 23 Feb 2023 15:35:18 +0000 Subject: [PATCH 68/82] Remove schedule-wakeup span as it will duplicate spans on existing wakeups (which should be a no-op) --- node/core/approval-voting/src/lib.rs | 10 ---------- 1 file changed, 10 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 8cbaf98b8717..f08389fd390c 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -925,16 +925,6 @@ async fn handle_actions( while let Some(action) = actions_iter.next() { match action { Action::ScheduleWakeup { block_hash, block_number, candidate_hash, tick } => { - let _span = state - .spans - .get(&block_hash) - .map(|span| span.child_with_trace_id("schedule-wakeup", candidate_hash)) - .unwrap_or_else(|| jaeger::Span::new(block_hash, "schedule-wakeup")) - .with_string_tag("leaf", format!("{:?}", block_hash)) - .with_uint_tag("block-number", block_number as u64) - .with_candidate(candidate_hash) - .with_stage(jaeger::Stage::ApprovalChecking); - wakeups.schedule(block_hash, block_number, candidate_hash, tick); }, Action::IssueApproval(candidate_hash, approval_request) => { From 9af3b09ddbebce194ba85fa24f758e486201ae7e Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 23 Feb 2023 15:39:02 +0000 Subject: [PATCH 69/82] Remove a couple of warnings related to mutability --- node/network/availability-distribution/src/responder.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/network/availability-distribution/src/responder.rs b/node/network/availability-distribution/src/responder.rs index fa7884f49348..db8b454c94e5 100644 --- a/node/network/availability-distribution/src/responder.rs +++ b/node/network/availability-distribution/src/responder.rs @@ -156,7 +156,7 @@ pub async fn answer_pov_request( where Sender: SubsystemSender, { - let mut span = jaeger::Span::new(req.payload.candidate_hash, "answer-pov-request"); + let _span = jaeger::Span::new(req.payload.candidate_hash, "answer-pov-request"); let av_data = query_available_data(sender, req.payload.candidate_hash).await?; @@ -184,7 +184,7 @@ pub async fn answer_chunk_request( where Sender: SubsystemSender, { - let mut span = jaeger::Span::new(req.payload.candidate_hash, "answer-chunk-request"); + let span = jaeger::Span::new(req.payload.candidate_hash, "answer-chunk-request"); let _child_span = span .child_with_trace_id("answer-chunk-request", req.payload.candidate_hash) From e7706c0acddf9633eece919b3d39959d65372507 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Thu, 23 Feb 2023 16:19:36 +0000 Subject: [PATCH 70/82] Fix failing tests in availability distribution --- .../src/pov_requester/mod.rs | 1 + .../src/requester/tests.rs | 18 ++++++++++-------- 2 files changed, 11 insertions(+), 8 deletions(-) diff --git a/node/network/availability-distribution/src/pov_requester/mod.rs b/node/network/availability-distribution/src/pov_requester/mod.rs index 2a595be43ab6..310fc8a067f0 100644 --- a/node/network/availability-distribution/src/pov_requester/mod.rs +++ b/node/network/availability-distribution/src/pov_requester/mod.rs @@ -191,6 +191,7 @@ mod tests { pov_hash, tx, Metrics::new_dummy(), + &jaeger::Span::Disabled, ) .await .expect("Should succeed"); diff --git a/node/network/availability-distribution/src/requester/tests.rs b/node/network/availability-distribution/src/requester/tests.rs index 59db97176a76..abb81d28131f 100644 --- a/node/network/availability-distribution/src/requester/tests.rs +++ b/node/network/availability-distribution/src/requester/tests.rs @@ -14,6 +14,8 @@ // You should have received a copy of the GNU General Public License // along with Polkadot. If not, see . +use std::collections::HashMap; + use std::{future::Future, sync::Arc}; use futures::FutureExt; @@ -196,7 +198,7 @@ fn check_ancestry_lookup_in_same_session() { test_harness(test_state.clone(), |mut ctx| async move { let chain = &test_state.relay_chain; - + let spans: HashMap = HashMap::new(); let block_number = 1; let update = ActiveLeavesUpdate { activated: Some(ActivatedLeaf { @@ -209,7 +211,7 @@ fn check_ancestry_lookup_in_same_session() { }; requester - .update_fetching_heads(&mut ctx, &mut runtime, update) + .update_fetching_heads(&mut ctx, &mut runtime, update, &spans) .await .expect("Leaf processing failed"); let fetch_tasks = &requester.fetches; @@ -229,7 +231,7 @@ fn check_ancestry_lookup_in_same_session() { }; requester - .update_fetching_heads(&mut ctx, &mut runtime, update) + .update_fetching_heads(&mut ctx, &mut runtime, update, &spans) .await .expect("Leaf processing failed"); let fetch_tasks = &requester.fetches; @@ -255,7 +257,7 @@ fn check_ancestry_lookup_in_same_session() { deactivated: vec![chain[1], chain[2]].into(), }; requester - .update_fetching_heads(&mut ctx, &mut runtime, update) + .update_fetching_heads(&mut ctx, &mut runtime, update, &spans) .await .expect("Leaf processing failed"); let fetch_tasks = &requester.fetches; @@ -283,7 +285,7 @@ fn check_ancestry_lookup_in_different_sessions() { test_harness(test_state.clone(), |mut ctx| async move { let chain = &test_state.relay_chain; - + let spans: HashMap = HashMap::new(); let block_number = 3; let update = ActiveLeavesUpdate { activated: Some(ActivatedLeaf { @@ -296,7 +298,7 @@ fn check_ancestry_lookup_in_different_sessions() { }; requester - .update_fetching_heads(&mut ctx, &mut runtime, update) + .update_fetching_heads(&mut ctx, &mut runtime, update, &spans) .await .expect("Leaf processing failed"); let fetch_tasks = &requester.fetches; @@ -314,7 +316,7 @@ fn check_ancestry_lookup_in_different_sessions() { }; requester - .update_fetching_heads(&mut ctx, &mut runtime, update) + .update_fetching_heads(&mut ctx, &mut runtime, update, &spans) .await .expect("Leaf processing failed"); let fetch_tasks = &requester.fetches; @@ -332,7 +334,7 @@ fn check_ancestry_lookup_in_different_sessions() { }; requester - .update_fetching_heads(&mut ctx, &mut runtime, update) + .update_fetching_heads(&mut ctx, &mut runtime, update, &spans) .await .expect("Leaf processing failed"); let fetch_tasks = &requester.fetches; From 35ac7bdec52dd7ab4c10a27cd363e63a0fb7ae07 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 24 Feb 2023 09:55:17 +0000 Subject: [PATCH 71/82] Add traceID tag to launch-approval and validation-result --- node/core/approval-voting/src/lib.rs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index f08389fd390c..cc07eb23baaf 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -973,8 +973,8 @@ async fn handle_actions( let mut launch_approval_span = state .spans .get(&relay_block_hash) - .map(|span| span.child("launch-approval")) - .unwrap_or_else(|| jaeger::Span::new(relay_block_hash, "launch-approval")) + .map(|span| span.child_with_trace_id("launch-approval", candidate_hash)) + .unwrap_or_else(|| jaeger::Span::new(candidate_hash, "launch-approval")) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); @@ -2413,12 +2413,12 @@ async fn launch_approval( // Covers both validation code and available data currently let request_validation_data_span = span - .child("request-validation-data") + .child_with_trace_id("request-validation-data", candidate.hash()) .with_candidate(candidate.hash()) .with_stage(jaeger::Stage::ApprovalChecking); let mut validation_result_span = span - .child("validation-result") + .child_with_trace_id("validation-result", candidate.hash()) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); From 20ca68aec4f8c55d4b59cc32da57d76b872f7345 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 24 Feb 2023 10:20:41 +0000 Subject: [PATCH 72/82] Reshuffle the validation and validation result spans to where more appropriate and add block-hash tag --- node/core/approval-voting/src/lib.rs | 31 ++++++++++++++-------------- 1 file changed, 15 insertions(+), 16 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index cc07eb23baaf..91e754c55332 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -2396,6 +2396,12 @@ async fn launch_approval( let para_id = candidate.descriptor.para_id; gum::trace!(target: LOG_TARGET, ?candidate_hash, ?para_id, "Recovering data."); + let request_validation_data_span = span + .child_with_trace_id("request-validation-data", candidate_hash) + .with_candidate(candidate_hash) + .with_string_tag("block-hash", format!("{:?}", block_hash)) + .with_stage(jaeger::Stage::ApprovalChecking); + let timer = metrics.time_recover_and_approve(); ctx.send_message(AvailabilityRecoveryMessage::RecoverAvailableData( candidate.clone(), @@ -2405,25 +2411,18 @@ async fn launch_approval( )) .await; + let request_validation_result_span = span + .child_with_trace_id("request-validation-result", candidate_hash) + .with_candidate(candidate_hash) + .with_string_tag("block-hash", format!("{:?}", block_hash)) + .with_stage(jaeger::Stage::ApprovalChecking); + ctx.send_message(RuntimeApiMessage::Request( block_hash, RuntimeApiRequest::ValidationCodeByHash(candidate.descriptor.validation_code_hash, code_tx), )) .await; - // Covers both validation code and available data currently - let request_validation_data_span = span - .child_with_trace_id("request-validation-data", candidate.hash()) - .with_candidate(candidate.hash()) - .with_stage(jaeger::Stage::ApprovalChecking); - - let mut validation_result_span = span - .child_with_trace_id("validation-result", candidate.hash()) - .with_candidate(candidate_hash) - .with_stage(jaeger::Stage::ApprovalChecking); - - validation_result_span.add_string_tag("para-id", format!("{:?}", para_id)); - let candidate = candidate.clone(); let metrics_guard = StaleGuard(Some(metrics)); let mut sender = ctx.sender().clone(); @@ -2467,6 +2466,7 @@ async fn launch_approval( return ApprovalState::failed(validator_index, candidate_hash) }, }; + drop(request_validation_data_span); let validation_code = match code_rx.await { Err(_) => return ApprovalState::failed(validator_index, candidate_hash), @@ -2486,7 +2486,6 @@ async fn launch_approval( return ApprovalState::failed(validator_index, candidate_hash) }, }; - drop(request_validation_data_span); let (val_tx, val_rx) = oneshot::channel(); sender @@ -2542,7 +2541,7 @@ async fn launch_approval( }, } }; - drop(validation_result_span); + drop(request_validation_result_span); let (background, remote_handle) = background.remote_handle(); ctx.spawn("approval-checks", Box::pin(background)).map(move |()| remote_handle) } @@ -2563,7 +2562,7 @@ async fn issue_approval( .get(&block_hash) .map(|span| span.child_with_trace_id("issue-approval", candidate_hash)) .unwrap_or_else(|| jaeger::Span::new(block_hash, "issue-approval")) - .with_string_tag("leaf", format!("{:?}", block_hash)) + .with_string_tag("block-hash", format!("{:?}", block_hash)) .with_candidate(candidate_hash) .with_validator_index(validator_index) .with_stage(jaeger::Stage::ApprovalChecking); From aa601b943b53cc1af8e914428ede7933a0b088a9 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 24 Feb 2023 11:25:12 +0000 Subject: [PATCH 73/82] - Add tranche and should-trigger tag to process-wakeup span - Add candidate-hash and traceID to check-and-import-approval span --- node/core/approval-voting/src/lib.rs | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 91e754c55332..06cea95f21a9 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -21,6 +21,7 @@ //! of others. It uses this information to determine when candidates and blocks have //! been sufficiently approved to finalize. +use jaeger::hash_to_trace_identifier; use polkadot_node_jaeger as jaeger; use polkadot_node_primitives::{ approval::{ @@ -1901,7 +1902,7 @@ fn check_and_import_approval( }}; } - let _span = state + let mut span = state .spans .get(&approval.block_hash) .map(|span| span.child("check-and-import-approval")) @@ -1935,6 +1936,9 @@ fn check_and_import_approval( )), }; + span.add_string_tag("candidate-hash", format!("{:?}", approved_candidate_hash)); + span.add_string_tag("traceID", format!("{:?}", hash_to_trace_identifier(approved_candidate_hash.0))); + let pubkey = match session_info.validators.get(approval.validator) { Some(k) => k, None => respond_early!(ApprovalCheckResult::Bad( @@ -2211,7 +2215,7 @@ fn process_wakeup( _expected_tick: Tick, metrics: &Metrics, ) -> SubsystemResult> { - let _span = state + let mut span = state .spans .get(&relay_block) .map(|span| span.child_with_trace_id("process-wakeup", candidate_hash)) @@ -2248,9 +2252,8 @@ fn process_wakeup( state.slot_duration_millis, Slot::from(u64::from(session_info.no_show_slots)), ); - let tranche_now = state.clock.tranche_now(state.slot_duration_millis, block_entry.slot()); - + span.add_uint_tag("tranche", tranche_now as u64); gum::trace!( target: LOG_TARGET, tranche = tranche_now, @@ -2283,6 +2286,9 @@ fn process_wakeup( (should_trigger, approval_entry.backing_group()) }; + + span.add_string_tag("should-trigger", format!("{:?}", should_trigger)); + let mut actions = Vec::new(); let candidate_receipt = candidate_entry.candidate_receipt().clone(); From 75ade4f70a522e5b814f7e705ff9b6f92ccb9527 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 24 Feb 2023 11:41:14 +0000 Subject: [PATCH 74/82] cargo fmt --- node/core/approval-voting/src/lib.rs | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 06cea95f21a9..3f705c92dec5 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1937,7 +1937,10 @@ fn check_and_import_approval( }; span.add_string_tag("candidate-hash", format!("{:?}", approved_candidate_hash)); - span.add_string_tag("traceID", format!("{:?}", hash_to_trace_identifier(approved_candidate_hash.0))); + span.add_string_tag( + "traceID", + format!("{:?}", hash_to_trace_identifier(approved_candidate_hash.0)), + ); let pubkey = match session_info.validators.get(approval.validator) { Some(k) => k, @@ -2286,7 +2289,7 @@ fn process_wakeup( (should_trigger, approval_entry.backing_group()) }; - + span.add_string_tag("should-trigger", format!("{:?}", should_trigger)); let mut actions = Vec::new(); From 209e1c993bf2103776ee60d661b226adf4688e78 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 28 Feb 2023 15:47:05 +0000 Subject: [PATCH 75/82] - Adjustments after PR comments --- node/core/approval-voting/src/import.rs | 4 +-- node/core/approval-voting/src/lib.rs | 26 ++++++++++--------- node/jaeger/src/spans.rs | 25 ++++-------------- node/network/approval-distribution/src/lib.rs | 4 +-- .../availability-distribution/src/lib.rs | 3 ++- .../src/pov_requester/mod.rs | 14 ++++------ .../src/requester/fetch_task/mod.rs | 14 ++++++++-- .../src/requester/mod.rs | 3 ++- .../src/responder.rs | 3 ++- 9 files changed, 45 insertions(+), 51 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 56613d73fcac..8e8ad818fe49 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -413,9 +413,7 @@ pub(crate) async fn handle_new_head( }; match imported_block_info(ctx, env, block_hash, &block_header).await { - Ok(i) => { - imported_blocks_and_info.push((block_hash, block_header, i)); - }, + Ok(i) => imported_blocks_and_info.push((block_hash, block_header, i)), Err(error) => { // It's possible that we've lost a race with finality. let (tx, rx) = oneshot::channel(); diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 3f705c92dec5..574f346b4ea2 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -432,7 +432,6 @@ struct Wakeups { // Tick -> [(Relay Block, Candidate Hash)] wakeups: BTreeMap>, reverse_wakeups: HashMap<(Hash, CandidateHash), Tick>, - /// A mapping from block numbers to hashes. block_numbers: BTreeMap>, } @@ -802,14 +801,13 @@ where loop { let mut overlayed_db = OverlayedBackend::new(&backend); let actions = futures::select! { - (tick, woken_block, woken_candidate) = wakeups.next(&*state.clock).fuse() => { + (_tick, woken_block, woken_candidate) = wakeups.next(&*state.clock).fuse() => { subsystem.metrics.on_wakeup(); process_wakeup( &mut state, &mut overlayed_db, woken_block, woken_candidate, - tick, &subsystem.metrics, )? } @@ -974,8 +972,9 @@ async fn handle_actions( let mut launch_approval_span = state .spans .get(&relay_block_hash) - .map(|span| span.child_with_trace_id("launch-approval", candidate_hash)) + .map(|span| span.child("launch-approval")) .unwrap_or_else(|| jaeger::Span::new(candidate_hash, "launch-approval")) + .with_trace_id(candidate_hash) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); @@ -1241,7 +1240,7 @@ async fn handle_from_overseer( wakeups.prune_finalized_wakeups(block_number); - // We let prune_finalized_wakeups decide whether we prune the span for a finalized block. + // `prune_finalized_wakeups` prunes all finalized block hashes. We prune spans accordingly. let hash_set = wakeups.block_numbers.values().flatten().collect::>(); state.spans.retain(|hash, _| hash_set.contains(hash)); @@ -2215,14 +2214,14 @@ fn process_wakeup( db: &mut OverlayedBackend<'_, impl Backend>, relay_block: Hash, candidate_hash: CandidateHash, - _expected_tick: Tick, metrics: &Metrics, ) -> SubsystemResult> { let mut span = state .spans .get(&relay_block) - .map(|span| span.child_with_trace_id("process-wakeup", candidate_hash)) + .map(|span| span.child("process-wakeup")) .unwrap_or_else(|| jaeger::Span::new(candidate_hash, "process-wakeup")) + .with_trace_id(candidate_hash) .with_relay_parent(relay_block) .with_candidate(candidate_hash) .with_stage(jaeger::Stage::ApprovalChecking); @@ -2290,7 +2289,7 @@ fn process_wakeup( (should_trigger, approval_entry.backing_group()) }; - span.add_string_tag("should-trigger", format!("{:?}", should_trigger)); + gum::trace!(target: LOG_TARGET, "Wakeup processed. Should trigger: {}", should_trigger); let mut actions = Vec::new(); let candidate_receipt = candidate_entry.candidate_receipt().clone(); @@ -2406,7 +2405,8 @@ async fn launch_approval( gum::trace!(target: LOG_TARGET, ?candidate_hash, ?para_id, "Recovering data."); let request_validation_data_span = span - .child_with_trace_id("request-validation-data", candidate_hash) + .child("request-validation-data") + .with_trace_id(candidate_hash) .with_candidate(candidate_hash) .with_string_tag("block-hash", format!("{:?}", block_hash)) .with_stage(jaeger::Stage::ApprovalChecking); @@ -2421,7 +2421,8 @@ async fn launch_approval( .await; let request_validation_result_span = span - .child_with_trace_id("request-validation-result", candidate_hash) + .child("request-validation-result") + .with_trace_id(candidate_hash) .with_candidate(candidate_hash) .with_string_tag("block-hash", format!("{:?}", block_hash)) .with_stage(jaeger::Stage::ApprovalChecking); @@ -2546,11 +2547,11 @@ async fn launch_approval( "Failed to validate candidate due to internal error", ); metrics_guard.take().on_approval_error(); + drop(request_validation_result_span); return ApprovalState::failed(validator_index, candidate_hash) }, } }; - drop(request_validation_result_span); let (background, remote_handle) = background.remote_handle(); ctx.spawn("approval-checks", Box::pin(background)).map(move |()| remote_handle) } @@ -2569,8 +2570,9 @@ async fn issue_approval( let mut issue_approval_span = state .spans .get(&block_hash) - .map(|span| span.child_with_trace_id("issue-approval", candidate_hash)) + .map(|span| span.child("issue-approval")) .unwrap_or_else(|| jaeger::Span::new(block_hash, "issue-approval")) + .with_trace_id(candidate_hash) .with_string_tag("block-hash", format!("{:?}", block_hash)) .with_candidate(candidate_hash) .with_validator_index(validator_index) diff --git a/node/jaeger/src/spans.rs b/node/jaeger/src/spans.rs index c4aa3f4b9cc1..f43ff736f4e5 100644 --- a/node/jaeger/src/spans.rs +++ b/node/jaeger/src/spans.rs @@ -291,26 +291,11 @@ impl Span { } } - /// Derive a child span with a traceID string tag set to the decimal representation of the CandidateHash. - pub fn child_with_trace_id(&self, name: &'static str, trace_id: CandidateHash) -> Self { - let mut span = match self { - Self::Enabled(inner) => Self::Enabled(inner.child(name)), - Self::Disabled => Self::Disabled, - }; - span.add_string_tag("traceID", hash_to_trace_identifier(trace_id.0).to_string()); - span - } - - /// Derive a child span with a start time set to the current system time using mick_jaeger::StartTime::now(). - /// This is useful for spans that are created after the parent span has started. - pub fn child_with_start_time(&self, name: &'static str) -> Self { - match self { - Self::Enabled(inner) => { - let start_time = mick_jaeger::StartTime::now(); - Self::Enabled(inner.child(name).with_start_time_override(start_time)) - }, - Self::Disabled => Self::Disabled, - } + /// Attach a 'traceID' tag set to the decimal representation of the candidate hash. + #[inline(always)] + pub fn with_trace_id(mut self, candidate_hash: CandidateHash) -> Self { + self.add_string_tag("traceID", hash_to_trace_identifier(candidate_hash.0)); + self } #[inline(always)] diff --git a/node/network/approval-distribution/src/lib.rs b/node/network/approval-distribution/src/lib.rs index 421274e82628..4b12b3408482 100644 --- a/node/network/approval-distribution/src/lib.rs +++ b/node/network/approval-distribution/src/lib.rs @@ -1713,7 +1713,7 @@ impl ApprovalDistribution { let _span = state .spans .get(&cert.block_hash) - .map(|span| span.child("distribute-assignment")) + .map(|span| span.child("import-and-distribute-assignment")) .unwrap_or_else(|| jaeger::Span::new(&cert.block_hash, "distribute-assignment")) .with_string_tag("block-hash", format!("{:?}", cert.block_hash)) .with_stage(jaeger::Stage::ApprovalDistribution); @@ -1740,7 +1740,7 @@ impl ApprovalDistribution { let _span = state .spans .get(&vote.block_hash) - .map(|span| span.child("distribute-approval")) + .map(|span| span.child("import-and-distribute-approval")) .unwrap_or_else(|| jaeger::Span::new(&vote.block_hash, "distribute-approval")) .with_string_tag("block-hash", format!("{:?}", vote.block_hash)) .with_stage(jaeger::Stage::ApprovalDistribution); diff --git a/node/network/availability-distribution/src/lib.rs b/node/network/availability-distribution/src/lib.rs index e46783de312e..83ab7547f099 100644 --- a/node/network/availability-distribution/src/lib.rs +++ b/node/network/availability-distribution/src/lib.rs @@ -170,8 +170,9 @@ impl AvailabilityDistributionSubsystem { } => { let span = spans .get(&relay_parent) - .map(|span| span.child_with_trace_id("fetch-pov", candidate_hash)) + .map(|span| span.child("fetch-pov")) .unwrap_or_else(|| jaeger::Span::new(&relay_parent, "fetch-pov")) + .with_trace_id(candidate_hash) .with_candidate(candidate_hash) .with_relay_parent(relay_parent) .with_stage(jaeger::Stage::AvailabilityDistribution); diff --git a/node/network/availability-distribution/src/pov_requester/mod.rs b/node/network/availability-distribution/src/pov_requester/mod.rs index 310fc8a067f0..ebe33f3b9423 100644 --- a/node/network/availability-distribution/src/pov_requester/mod.rs +++ b/node/network/availability-distribution/src/pov_requester/mod.rs @@ -54,8 +54,9 @@ pub async fn fetch_pov( metrics: Metrics, span: &jaeger::Span, ) -> Result<()> { - let span = span - .child_with_trace_id("fetch-pov", candidate_hash) + let _span = span + .child("fetch-pov") + .with_trace_id(candidate_hash) .with_validator_index(from_validator) .with_candidate(candidate_hash) .with_para_id(para_id) @@ -83,7 +84,7 @@ pub async fn fetch_pov( ctx.spawn( "pov-fetcher", - fetch_pov_job(para_id, pov_hash, authority_id, pending_response.boxed(), span, tx, metrics) + fetch_pov_job(para_id, pov_hash, authority_id, pending_response.boxed(), tx, metrics) .boxed(), ) .map_err(|e| FatalError::SpawnTask(e))?; @@ -96,11 +97,10 @@ async fn fetch_pov_job( pov_hash: Hash, authority_id: AuthorityDiscoveryId, pending_response: BoxFuture<'static, std::result::Result>, - span: jaeger::Span, tx: oneshot::Sender, metrics: Metrics, ) { - if let Err(err) = do_fetch_pov(pov_hash, pending_response, span, tx, metrics).await { + if let Err(err) = do_fetch_pov(pov_hash, pending_response, tx, metrics).await { gum::warn!(target: LOG_TARGET, ?err, ?para_id, ?pov_hash, ?authority_id, "fetch_pov_job"); } } @@ -109,13 +109,9 @@ async fn fetch_pov_job( async fn do_fetch_pov( pov_hash: Hash, pending_response: BoxFuture<'static, std::result::Result>, - span: jaeger::Span, tx: oneshot::Sender, metrics: Metrics, ) -> Result<()> { - let _span = span - .child_with_start_time("do-fetch-pov") - .with_stage(jaeger::Stage::AvailabilityDistribution); let response = pending_response.await.map_err(Error::FetchPoV); let pov = match response { Ok(PoVFetchingResponse::PoV(pov)) => pov, diff --git a/node/network/availability-distribution/src/requester/fetch_task/mod.rs b/node/network/availability-distribution/src/requester/fetch_task/mod.rs index 432003ae1b4f..a867246551b1 100644 --- a/node/network/availability-distribution/src/requester/fetch_task/mod.rs +++ b/node/network/availability-distribution/src/requester/fetch_task/mod.rs @@ -143,7 +143,8 @@ impl FetchTaskConfig { span: jaeger::Span, ) -> Self { let span = span - .child_with_trace_id("fetch-task-config", core.candidate_hash) + .child("fetch-task-config") + .with_trace_id(core.candidate_hash) .with_string_tag("leaf", format!("{:?}", leaf)) .with_validator_index(session_info.our_index) .with_uint_tag("group-index", core.group_responsible.0 as u64) @@ -286,6 +287,11 @@ impl RunningTask { continue }, }; + drop(_chunk_fetch_span); + let _chunk_recombine_span = span + .child("recombine-chunk") + .with_chunk_index(self.request.index.0) + .with_stage(jaeger::Stage::AvailabilityDistribution); let chunk = match resp { ChunkFetchingResponse::Chunk(resp) => resp.recombine_into_chunk(&self.request), ChunkFetchingResponse::NoSuchChunk => { @@ -303,6 +309,11 @@ impl RunningTask { continue }, }; + drop(_chunk_recombine_span); + let _chunk_validate_and_store_span = span + .child("validate-and-store-chunk") + .with_chunk_index(self.request.index.0) + .with_stage(jaeger::Stage::AvailabilityDistribution); // Data genuine? if !self.validate_chunk(&validator, &chunk) { @@ -313,7 +324,6 @@ impl RunningTask { // Ok, let's store it and be happy: self.store_chunk(chunk).await; succeeded = true; - span.add_string_tag("success", "true"); break } span.add_int_tag("tries", count as _); diff --git a/node/network/availability-distribution/src/requester/mod.rs b/node/network/availability-distribution/src/requester/mod.rs index 2b6628b975b2..485e5487a197 100644 --- a/node/network/availability-distribution/src/requester/mod.rs +++ b/node/network/availability-distribution/src/requester/mod.rs @@ -204,7 +204,8 @@ impl Requester { ) -> Result<()> { for core in cores { let mut span = span - .child_with_trace_id("check-fetch-candidate", core.candidate_hash) + .child("check-fetch-candidate") + .with_trace_id(core.candidate_hash) .with_string_tag("leaf", format!("{:?}", leaf)) .with_candidate(core.candidate_hash) .with_stage(jaeger::Stage::AvailabilityDistribution); diff --git a/node/network/availability-distribution/src/responder.rs b/node/network/availability-distribution/src/responder.rs index db8b454c94e5..d8e5a9c1a659 100644 --- a/node/network/availability-distribution/src/responder.rs +++ b/node/network/availability-distribution/src/responder.rs @@ -187,7 +187,8 @@ where let span = jaeger::Span::new(req.payload.candidate_hash, "answer-chunk-request"); let _child_span = span - .child_with_trace_id("answer-chunk-request", req.payload.candidate_hash) + .child("answer-chunk-request") + .with_trace_id(req.payload.candidate_hash) .with_chunk_index(req.payload.index.0); let chunk = query_chunk(sender, req.payload.candidate_hash, req.payload.index).await?; From 8bb2773c2a86731a31126fbf5c0db1201c9a6cf0 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Tue, 28 Feb 2023 16:18:59 +0000 Subject: [PATCH 76/82] Move span pruning after other pruning logic --- node/network/approval-distribution/src/lib.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/node/network/approval-distribution/src/lib.rs b/node/network/approval-distribution/src/lib.rs index 4b12b3408482..f0df22b559e6 100644 --- a/node/network/approval-distribution/src/lib.rs +++ b/node/network/approval-distribution/src/lib.rs @@ -701,10 +701,9 @@ impl State { old_blocks.values().flatten().for_each(|relay_block| { self.recent_outdated_blocks.note_outdated(*relay_block); if let Some(block_entry) = self.blocks.remove(relay_block) { - // We should remove the span associated with the relay block to avoid memory leaks. - self.spans.remove(&relay_block); self.topologies.dec_session_refs(block_entry.session); } + self.spans.remove(&relay_block); }); // If a block was finalized, this means we may need to move our aggression From 3614167080155ec7a662504d494cd5da73bd4a7d Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Wed, 1 Mar 2023 13:24:58 +0000 Subject: [PATCH 77/82] Remove DerefMut - no longer needed --- node/jaeger/src/spans.rs | 7 ------- 1 file changed, 7 deletions(-) diff --git a/node/jaeger/src/spans.rs b/node/jaeger/src/spans.rs index f43ff736f4e5..b67ca0f9f260 100644 --- a/node/jaeger/src/spans.rs +++ b/node/jaeger/src/spans.rs @@ -133,13 +133,6 @@ impl std::ops::Deref for PerLeafSpan { } } -/// Returns a mutable reference to the child span. -impl std::ops::DerefMut for PerLeafSpan { - fn deref_mut(&mut self) -> &mut Self::Target { - &mut self.span - } -} - /// A helper to annotate the stage with a numerical value /// to ease the life of the tooling team creating viable /// statistical metrics for which stage of the inclusion From 4ec2c2d86142c5024dc77aab0ceed44777676c1d Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 10 Mar 2023 11:58:32 +0000 Subject: [PATCH 78/82] Relabel request-chunk spans --- node/network/availability-distribution/src/requester/mod.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/network/availability-distribution/src/requester/mod.rs b/node/network/availability-distribution/src/requester/mod.rs index 485e5487a197..a4483e11a796 100644 --- a/node/network/availability-distribution/src/requester/mod.rs +++ b/node/network/availability-distribution/src/requester/mod.rs @@ -135,7 +135,7 @@ impl Requester { span: &jaeger::Span, ) -> Result<()> { let mut span = span - .child("request-chunks") + .child("request-chunks-new-head") .with_string_tag("leaf", format!("{:?}", new_head.hash)) .with_stage(jaeger::Stage::AvailabilityDistribution); @@ -153,7 +153,7 @@ impl Requester { // Also spawn or bump tasks for candidates in ancestry in the same session. for hash in std::iter::once(leaf).chain(ancestors_in_session) { let span = span - .child("get-occupied-cores") + .child("request-chunks-ancestor") .with_string_tag("leaf", format!("{:?}", hash.clone())) .with_stage(jaeger::Stage::AvailabilityDistribution); From 2b49b795459413f85683ef65632029be688ece81 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 10 Mar 2023 15:31:53 +0000 Subject: [PATCH 79/82] - Fix typo in span label - Add docs for drops --- .../availability-distribution/src/requester/fetch_task/mod.rs | 2 ++ node/network/availability-distribution/src/requester/mod.rs | 2 +- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/node/network/availability-distribution/src/requester/fetch_task/mod.rs b/node/network/availability-distribution/src/requester/fetch_task/mod.rs index a867246551b1..adc2c32e30bd 100644 --- a/node/network/availability-distribution/src/requester/fetch_task/mod.rs +++ b/node/network/availability-distribution/src/requester/fetch_task/mod.rs @@ -287,6 +287,7 @@ impl RunningTask { continue }, }; + // We drop the span here, so that the span is not active while we recombine the chunk. drop(_chunk_fetch_span); let _chunk_recombine_span = span .child("recombine-chunk") @@ -309,6 +310,7 @@ impl RunningTask { continue }, }; + // We drop the span so that the span is not active whilst we validate and store the chunk. drop(_chunk_recombine_span); let _chunk_validate_and_store_span = span .child("validate-and-store-chunk") diff --git a/node/network/availability-distribution/src/requester/mod.rs b/node/network/availability-distribution/src/requester/mod.rs index a4483e11a796..58a04dbcbf76 100644 --- a/node/network/availability-distribution/src/requester/mod.rs +++ b/node/network/availability-distribution/src/requester/mod.rs @@ -213,7 +213,7 @@ impl Requester { Entry::Occupied(mut e) => // Just book keeping - we are already requesting that chunk: { - span.add_string_tag("alread-requested-chunk", "true"); + span.add_string_tag("already-requested-chunk", "true"); e.get_mut().add_leaf(leaf); }, Entry::Vacant(e) => { From cc9f7c94eef03de3d98441b37761a6c1b939462b Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 10 Mar 2023 16:27:38 +0000 Subject: [PATCH 80/82] Add new approval-voting span pruning logic --- node/core/approval-voting/src/lib.rs | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index f60e06fa0954..d70f585d240f 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -21,7 +21,7 @@ //! of others. It uses this information to determine when candidates and blocks have //! been sufficiently approved to finalize. -use jaeger::hash_to_trace_identifier; +use jaeger::{PerLeafSpan, hash_to_trace_identifier}; use polkadot_node_jaeger as jaeger; use polkadot_node_primitives::{ approval::{ @@ -479,7 +479,7 @@ impl Wakeups { self.wakeups.entry(tick).or_default().push((block_hash, candidate_hash)); } - fn prune_finalized_wakeups(&mut self, finalized_number: BlockNumber) { + fn prune_finalized_wakeups(&mut self, finalized_number: BlockNumber, spans: &mut HashMap) { let after = self.block_numbers.split_off(&(finalized_number + 1)); let pruned_blocks: HashSet<_> = std::mem::replace(&mut self.block_numbers, after) .into_iter() @@ -497,12 +497,16 @@ impl Wakeups { for (tick, pruned) in pruned_wakeups { if let BTMEntry::Occupied(mut entry) = self.wakeups.entry(tick) { - entry.get_mut().retain(|wakeup| !pruned.contains(wakeup)); + entry.get_mut().retain(|wakeup| pruned.contains(wakeup)); if entry.get().is_empty() { let _ = entry.remove(); } } } + + // Remove all spans that are associated with pruned blocks. + spans.retain(|h, _| !pruned_blocks.contains(h)); + } // Get the wakeup for a particular block/candidate combo, if any. @@ -1238,11 +1242,12 @@ async fn handle_from_overseer( crate::ops::canonicalize(db, block_number, block_hash) .map_err(|e| SubsystemError::with_origin("db", e))?; - wakeups.prune_finalized_wakeups(block_number); - // `prune_finalized_wakeups` prunes all finalized block hashes. We prune spans accordingly. - let hash_set = wakeups.block_numbers.values().flatten().collect::>(); - state.spans.retain(|hash, _| hash_set.contains(hash)); + wakeups.prune_finalized_wakeups(block_number, &mut state.spans); + + // // `prune_finalized_wakeups` prunes all finalized block hashes. We prune spans accordingly. + // let hash_set = wakeups.block_numbers.values().flatten().collect::>(); + // state.spans.retain(|hash, _| hash_set.contains(hash)); Vec::new() }, From 75421613b93e26219524d3dd6e838c71d3141c87 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 10 Mar 2023 16:28:52 +0000 Subject: [PATCH 81/82] Undo removal of ! --- node/core/approval-voting/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index d70f585d240f..731666ab8a51 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -497,7 +497,7 @@ impl Wakeups { for (tick, pruned) in pruned_wakeups { if let BTMEntry::Occupied(mut entry) = self.wakeups.entry(tick) { - entry.get_mut().retain(|wakeup| pruned.contains(wakeup)); + entry.get_mut().retain(|wakeup| !pruned.contains(wakeup)); if entry.get().is_empty() { let _ = entry.remove(); } From 405e8c88d722317502821bdefffa282d2f163514 Mon Sep 17 00:00:00 2001 From: Mattia Bradascio <28816406+bredamatt@users.noreply.github.com> Date: Fri, 10 Mar 2023 16:30:39 +0000 Subject: [PATCH 82/82] cargo fmt --- node/core/approval-voting/src/lib.rs | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 731666ab8a51..a26ea4e59dab 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -21,7 +21,7 @@ //! of others. It uses this information to determine when candidates and blocks have //! been sufficiently approved to finalize. -use jaeger::{PerLeafSpan, hash_to_trace_identifier}; +use jaeger::{hash_to_trace_identifier, PerLeafSpan}; use polkadot_node_jaeger as jaeger; use polkadot_node_primitives::{ approval::{ @@ -479,7 +479,11 @@ impl Wakeups { self.wakeups.entry(tick).or_default().push((block_hash, candidate_hash)); } - fn prune_finalized_wakeups(&mut self, finalized_number: BlockNumber, spans: &mut HashMap) { + fn prune_finalized_wakeups( + &mut self, + finalized_number: BlockNumber, + spans: &mut HashMap, + ) { let after = self.block_numbers.split_off(&(finalized_number + 1)); let pruned_blocks: HashSet<_> = std::mem::replace(&mut self.block_numbers, after) .into_iter() @@ -506,7 +510,6 @@ impl Wakeups { // Remove all spans that are associated with pruned blocks. spans.retain(|h, _| !pruned_blocks.contains(h)); - } // Get the wakeup for a particular block/candidate combo, if any.