From f16ad07bdda33a145120972c9ccbeed61e0b2bdc Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Tue, 11 Jul 2023 21:07:17 +0200 Subject: [PATCH 1/9] Add counter for unapproved candidates --- node/core/approval-voting/src/lib.rs | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index a6a74da50480..1966377933f0 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -160,6 +160,7 @@ struct MetricsInner { time_db_transaction: prometheus::Histogram, time_recover_and_approve: prometheus::Histogram, candidate_signatures_requests_total: prometheus::Counter, + unapproved_candidates_in_unfinalized_chain: prometheus::Counter, } /// Approval Voting metrics. @@ -246,6 +247,12 @@ impl Metrics { fn time_recover_and_approve(&self) -> Option { self.0.as_ref().map(|metrics| metrics.time_recover_and_approve.start_timer()) } + + fn on_unapproved_candidates_in_unfinalized_chain(&self, count: usize) { + if let Some(metrics) = &self.0 { + metrics.unapproved_candidates_in_unfinalized_chain.inc_by(count as u64); + } + } } impl metrics::Metrics for Metrics { @@ -336,6 +343,13 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + unapproved_candidates_in_unfinalized_chain: prometheus::register( + prometheus::Counter::new( + "polkadot_parachain_approval_unapproved_candidates_in_unfinalized_chain", + "Number of unapproved candidates in unfinalized chain", + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) @@ -1298,6 +1312,7 @@ async fn handle_from_overseer( lower_bound, wakeups, &mut approved_ancestor_span, + &metrics, ) .await { @@ -1423,6 +1438,7 @@ async fn handle_approved_ancestor( lower_bound: BlockNumber, wakeups: &Wakeups, span: &mut jaeger::Span, + metrics: &Metrics, ) -> SubsystemResult> { const MAX_TRACING_WINDOW: usize = 200; const ABNORMAL_DEPTH_THRESHOLD: usize = 5; @@ -1534,6 +1550,7 @@ async fn handle_approved_ancestor( unapproved.len(), entry.candidates().len(), ); + metrics.on_unapproved_candidates_in_unfinalized_chain(unapproved.len()); entry_span.add_uint_tag("unapproved-candidates", unapproved.len() as u64); for candidate_hash in unapproved { match db.load_candidate_entry(&candidate_hash)? { From 74d2fd0dd9d3392efcaf977e4f77ada6478fcf0a Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Thu, 20 Jul 2023 18:53:18 +0200 Subject: [PATCH 2/9] Update metrics --- node/core/approval-voting/src/lib.rs | 29 +++++++++++++++++++++------- 1 file changed, 22 insertions(+), 7 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 1966377933f0..a91a166ef874 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -160,7 +160,7 @@ struct MetricsInner { time_db_transaction: prometheus::Histogram, time_recover_and_approve: prometheus::Histogram, candidate_signatures_requests_total: prometheus::Counter, - unapproved_candidates_in_unfinalized_chain: prometheus::Counter, + unapproved_candidates_in_unfinalized_chain: prometheus::GaugeVec, } /// Approval Voting metrics. @@ -248,9 +248,12 @@ impl Metrics { self.0.as_ref().map(|metrics| metrics.time_recover_and_approve.start_timer()) } - fn on_unapproved_candidates_in_unfinalized_chain(&self, count: usize) { + fn on_unapproved_candidates_in_unfinalized_chain(&self, count: usize, depth: usize) { if let Some(metrics) = &self.0 { - metrics.unapproved_candidates_in_unfinalized_chain.inc_by(count as u64); + metrics + .unapproved_candidates_in_unfinalized_chain + .with_label_values(&[&count.to_string(), &depth.to_string()]) + .set(count as u64); } } } @@ -344,9 +347,12 @@ impl metrics::Metrics for Metrics { registry, )?, unapproved_candidates_in_unfinalized_chain: prometheus::register( - prometheus::Counter::new( - "polkadot_parachain_approval_unapproved_candidates_in_unfinalized_chain", - "Number of unapproved candidates in unfinalized chain", + prometheus::GaugeVec::new( + prometheus::Opts::new( + "polkadot_parachain_approval_unapproved_candidates_in_unfinalized_chain", + "Number of unapproved candidates in unfinalized chain", + ), + &["count", "depth"] )?, registry, )?, @@ -1442,6 +1448,7 @@ async fn handle_approved_ancestor( ) -> SubsystemResult> { const MAX_TRACING_WINDOW: usize = 200; const ABNORMAL_DEPTH_THRESHOLD: usize = 5; + const LOGGING_DEPTH_THRESHOLD: usize = 10; let mut span = span .child("handle-approved-ancestor") .with_stage(jaeger::Stage::ApprovalChecking); @@ -1550,7 +1557,15 @@ async fn handle_approved_ancestor( unapproved.len(), entry.candidates().len(), ); - metrics.on_unapproved_candidates_in_unfinalized_chain(unapproved.len()); + if bits.len() > LOGGING_DEPTH_THRESHOLD { + gum::trace!( + target: LOG_TARGET, + "Unapproved blocks on depth {}: {:?}", + bits.len(), + unapproved + ) + } + metrics.on_unapproved_candidates_in_unfinalized_chain(unapproved.len(), bits.len()); entry_span.add_uint_tag("unapproved-candidates", unapproved.len() as u64); for candidate_hash in unapproved { match db.load_candidate_entry(&candidate_hash)? { From 09fbc9d6c61c96e43c01857acc4648fdd2cb0481 Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Tue, 25 Jul 2023 14:07:26 +0200 Subject: [PATCH 3/9] Split metrics --- node/core/approval-voting/src/lib.rs | 35 +++++++++++++++++----------- 1 file changed, 22 insertions(+), 13 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index a91a166ef874..dd0898802018 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -160,7 +160,8 @@ struct MetricsInner { time_db_transaction: prometheus::Histogram, time_recover_and_approve: prometheus::Histogram, candidate_signatures_requests_total: prometheus::Counter, - unapproved_candidates_in_unfinalized_chain: prometheus::GaugeVec, + unapproved_candidates_in_unfinalized_chain: prometheus::Gauge, + unfinalized_chain_depth: prometheus::Gauge, } /// Approval Voting metrics. @@ -248,12 +249,15 @@ impl Metrics { self.0.as_ref().map(|metrics| metrics.time_recover_and_approve.start_timer()) } - fn on_unapproved_candidates_in_unfinalized_chain(&self, count: usize, depth: usize) { + fn on_unapproved_candidates_in_unfinalized_chain(&self, count: usize) { if let Some(metrics) = &self.0 { - metrics - .unapproved_candidates_in_unfinalized_chain - .with_label_values(&[&count.to_string(), &depth.to_string()]) - .set(count as u64); + metrics.unapproved_candidates_in_unfinalized_chain.set(count as u64); + } + } + + fn on_unfinalized_chain_depth(&self, depth: usize) { + if let Some(metrics) = &self.0 { + metrics.unfinalized_chain_depth.set(depth as u64); } } } @@ -347,12 +351,16 @@ impl metrics::Metrics for Metrics { registry, )?, unapproved_candidates_in_unfinalized_chain: prometheus::register( - prometheus::GaugeVec::new( - prometheus::Opts::new( - "polkadot_parachain_approval_unapproved_candidates_in_unfinalized_chain", - "Number of unapproved candidates in unfinalized chain", - ), - &["count", "depth"] + prometheus::Gauge::new( + "polkadot_parachain_approval_unapproved_candidates_in_unfinalized_chain", + "Number of unapproved candidates in unfinalized chain", + )?, + registry, + )?, + unfinalized_chain_depth: prometheus::register( + prometheus::Gauge::new( + "polkadot_parachain_approval_unfinalized_chain_depth", + "Number of unapproved candidates in unfinalized chain", )?, registry, )?, @@ -1565,7 +1573,8 @@ async fn handle_approved_ancestor( unapproved ) } - metrics.on_unapproved_candidates_in_unfinalized_chain(unapproved.len(), bits.len()); + metrics.on_unapproved_candidates_in_unfinalized_chain(unapproved.len()); + metrics.on_unfinalized_chain_depth(bits.len()); entry_span.add_uint_tag("unapproved-candidates", unapproved.len() as u64); for candidate_hash in unapproved { match db.load_candidate_entry(&candidate_hash)? { From 2b722979cc6711db0c5ed6699920c3dd29313dbb Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Tue, 25 Jul 2023 15:07:24 +0200 Subject: [PATCH 4/9] Remove depth metric --- node/core/approval-voting/src/lib.rs | 15 --------------- 1 file changed, 15 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index dd0898802018..ab2c07fc6a96 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -161,7 +161,6 @@ struct MetricsInner { time_recover_and_approve: prometheus::Histogram, candidate_signatures_requests_total: prometheus::Counter, unapproved_candidates_in_unfinalized_chain: prometheus::Gauge, - unfinalized_chain_depth: prometheus::Gauge, } /// Approval Voting metrics. @@ -254,12 +253,6 @@ impl Metrics { metrics.unapproved_candidates_in_unfinalized_chain.set(count as u64); } } - - fn on_unfinalized_chain_depth(&self, depth: usize) { - if let Some(metrics) = &self.0 { - metrics.unfinalized_chain_depth.set(depth as u64); - } - } } impl metrics::Metrics for Metrics { @@ -357,13 +350,6 @@ impl metrics::Metrics for Metrics { )?, registry, )?, - unfinalized_chain_depth: prometheus::register( - prometheus::Gauge::new( - "polkadot_parachain_approval_unfinalized_chain_depth", - "Number of unapproved candidates in unfinalized chain", - )?, - registry, - )?, }; Ok(Metrics(Some(metrics))) @@ -1574,7 +1560,6 @@ async fn handle_approved_ancestor( ) } metrics.on_unapproved_candidates_in_unfinalized_chain(unapproved.len()); - metrics.on_unfinalized_chain_depth(bits.len()); entry_span.add_uint_tag("unapproved-candidates", unapproved.len() as u64); for candidate_hash in unapproved { match db.load_candidate_entry(&candidate_hash)? { From beb8ada658a66d5c8b8fd2869de3c59b4e3fb330 Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Wed, 26 Jul 2023 16:25:28 +0200 Subject: [PATCH 5/9] Print only the oldest unapproved candidates --- 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 ab2c07fc6a96..9e1918abcecd 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1492,6 +1492,8 @@ async fn handle_approved_ancestor( let mut block_descriptions = Vec::new(); let mut bits: BitVec = Default::default(); + // Could be `len() - 1` but we add the target at the beginning of the following for-loop + let oldest_ancestor_idx = ancestry.len(); 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); @@ -1551,7 +1553,7 @@ async fn handle_approved_ancestor( unapproved.len(), entry.candidates().len(), ); - if bits.len() > LOGGING_DEPTH_THRESHOLD { + if i == oldest_ancestor_idx && bits.len() > LOGGING_DEPTH_THRESHOLD { gum::trace!( target: LOG_TARGET, "Unapproved blocks on depth {}: {:?}", From eb2705205a528ed37e60083d8bd06d87546e081a Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Wed, 2 Aug 2023 14:36:23 +0200 Subject: [PATCH 6/9] Update logging condition --- node/core/approval-voting/src/lib.rs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/node/core/approval-voting/src/lib.rs b/node/core/approval-voting/src/lib.rs index 9e1918abcecd..ccbe05d92c50 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1492,8 +1492,6 @@ async fn handle_approved_ancestor( let mut block_descriptions = Vec::new(); let mut bits: BitVec = Default::default(); - // Could be `len() - 1` but we add the target at the beginning of the following for-loop - let oldest_ancestor_idx = ancestry.len(); 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); @@ -1553,7 +1551,7 @@ async fn handle_approved_ancestor( unapproved.len(), entry.candidates().len(), ); - if i == oldest_ancestor_idx && bits.len() > LOGGING_DEPTH_THRESHOLD { + if bits.len() > LOGGING_DEPTH_THRESHOLD && i >= bits.len() - LOGGING_DEPTH_THRESHOLD { gum::trace!( target: LOG_TARGET, "Unapproved blocks on depth {}: {:?}", From 384647bc316d72874c060437be125fe1d84e1bfe Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Tue, 8 Aug 2023 18:30:42 +0200 Subject: [PATCH 7/9] Fix logging condition --- 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 ccbe05d92c50..0ebca9c56e89 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1551,7 +1551,9 @@ async fn handle_approved_ancestor( unapproved.len(), entry.candidates().len(), ); - if bits.len() > LOGGING_DEPTH_THRESHOLD && i >= bits.len() - LOGGING_DEPTH_THRESHOLD { + if ancestry.len() >= LOGGING_DEPTH_THRESHOLD && + i > ancestry.len() - LOGGING_DEPTH_THRESHOLD + { gum::trace!( target: LOG_TARGET, "Unapproved blocks on depth {}: {:?}", From 6315e111a7b2e317b99356eb1b01db2bbf0c3379 Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Tue, 8 Aug 2023 18:35:23 +0200 Subject: [PATCH 8/9] Update logging --- 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 0ebca9c56e89..86e0c0b73a2a 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1488,6 +1488,7 @@ async fn handle_approved_ancestor( } else { Vec::new() }; + let ancestry_len = ancestry.len(); let mut block_descriptions = Vec::new(); @@ -1551,12 +1552,12 @@ async fn handle_approved_ancestor( unapproved.len(), entry.candidates().len(), ); - if ancestry.len() >= LOGGING_DEPTH_THRESHOLD && - i > ancestry.len() - LOGGING_DEPTH_THRESHOLD + if ancestry_len >= LOGGING_DEPTH_THRESHOLD && i > ancestry_len - LOGGING_DEPTH_THRESHOLD { gum::trace!( target: LOG_TARGET, - "Unapproved blocks on depth {}: {:?}", + "Unapproved blocks for block {} on depth {}: {:?}", + block_hash, bits.len(), unapproved ) From 1d0fd8fcc248588937b4b57856dfe9c8e1d3dc2f Mon Sep 17 00:00:00 2001 From: Andrei Eres Date: Tue, 8 Aug 2023 20:21:57 +0200 Subject: [PATCH 9/9] Update node/core/approval-voting/src/lib.rs Co-authored-by: Andrei Sandu <54316454+sandreim@users.noreply.github.com> --- 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 86e0c0b73a2a..05b92f459529 100644 --- a/node/core/approval-voting/src/lib.rs +++ b/node/core/approval-voting/src/lib.rs @@ -1556,8 +1556,8 @@ async fn handle_approved_ancestor( { gum::trace!( target: LOG_TARGET, - "Unapproved blocks for block {} on depth {}: {:?}", - block_hash, + ?block_hash, + "Unapproved candidates at depth {}: {:?}", bits.len(), unapproved )