diff --git a/polkadot/node/collation-generation/src/lib.rs b/polkadot/node/collation-generation/src/lib.rs index 6d37a157dd..ad28b66f07 100644 --- a/polkadot/node/collation-generation/src/lib.rs +++ b/polkadot/node/collation-generation/src/lib.rs @@ -189,7 +189,11 @@ async fn handle_new_activations( // follow the procedure from the guide: // https://w3f.github.io/parachain-implementers-guide/node/collators/collation-generation.html + let _overall_timer = metrics.time_new_activations(); + for relay_parent in activated.iter().copied() { + let _relay_parent_timer = metrics.time_new_activations_relay_parent(); + // double-future magic happens here: the first layer of requests takes a mutable borrow of the context, and // returns a receiver. The second layer of requests actually polls those receivers to completion. let (availability_cores, validators) = join!( @@ -201,6 +205,8 @@ async fn handle_new_activations( let n_validators = validators??.len(); for core in availability_cores { + let _availability_core_timer = metrics.time_new_activations_availability_core(); + let (scheduled_core, assumption) = match core { CoreState::Scheduled(scheduled_core) => { (scheduled_core, OccupiedCoreAssumption::Free) @@ -335,6 +341,9 @@ fn erasure_root( #[derive(Clone)] struct MetricsInner { collations_generated_total: prometheus::Counter, + new_activations_overall: prometheus::Histogram, + new_activations_per_relay_parent: prometheus::Histogram, + new_activations_per_availability_core: prometheus::Histogram, } /// CollationGenerationSubsystem metrics. @@ -347,6 +356,21 @@ impl Metrics { metrics.collations_generated_total.inc(); } } + + /// Provide a timer for new activations which updates on drop. + fn time_new_activations(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.new_activations_overall.start_timer()) + } + + /// Provide a timer per relay parents which updates on drop. + fn time_new_activations_relay_parent(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.new_activations_per_relay_parent.start_timer()) + } + + /// Provide a timer per availability core which updates on drop. + fn time_new_activations_availability_core(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.new_activations_per_availability_core.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -359,6 +383,33 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + new_activations_overall: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_collation_generation_new_activations", + "Time spent within fn handle_new_activations", + ) + )?, + registry, + )?, + new_activations_per_relay_parent: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_collation_generation_per_relay_parent", + "Time spent handling a particular relay parent within fn handle_new_activations" + ) + )?, + registry, + )?, + new_activations_per_availability_core: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_collation_generation_per_availability_core", + "Time spent handling a particular availability core for a relay parent in fn handle_new_activations", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/core/av-store/src/lib.rs b/polkadot/node/core/av-store/src/lib.rs index 8fe0e6c5e9..8c20e351f9 100644 --- a/polkadot/node/core/av-store/src/lib.rs +++ b/polkadot/node/core/av-store/src/lib.rs @@ -313,6 +313,8 @@ impl AvailabilityStoreSubsystem { // Perform pruning of PoVs #[tracing::instrument(level = "trace", skip(self), fields(subsystem = LOG_TARGET))] fn prune_povs(&self) -> Result<(), Error> { + let _timer = self.metrics.time_prune_povs(); + let mut tx = DBTransaction::new(); let mut pov_pruning = pov_pruning(&self.inner).unwrap_or_default(); let now = PruningDelay::now()?; @@ -338,6 +340,8 @@ impl AvailabilityStoreSubsystem { // Perform pruning of chunks. #[tracing::instrument(level = "trace", skip(self), fields(subsystem = LOG_TARGET))] fn prune_chunks(&self) -> Result<(), Error> { + let _timer = self.metrics.time_prune_chunks(); + let mut tx = DBTransaction::new(); let mut chunk_pruning = chunk_pruning(&self.inner).unwrap_or_default(); let now = PruningDelay::now()?; @@ -522,7 +526,7 @@ where ActiveLeavesUpdate { activated, .. }) ) => { for activated in activated.into_iter() { - process_block_activated(ctx, &subsystem.inner, activated).await?; + process_block_activated(ctx, &subsystem.inner, activated, &subsystem.metrics).await?; } } FromOverseer::Signal(OverseerSignal::BlockFinalized(hash)) => { @@ -561,6 +565,8 @@ async fn process_block_finalized( where Context: SubsystemContext { + let _timer = subsystem.metrics.time_process_block_finalized(); + let block_number = get_block_number(ctx, hash).await?; if let Some(mut pov_pruning) = pov_pruning(db) { @@ -606,15 +612,18 @@ where Ok(()) } -#[tracing::instrument(level = "trace", skip(ctx, db), fields(subsystem = LOG_TARGET))] +#[tracing::instrument(level = "trace", skip(ctx, db, metrics), fields(subsystem = LOG_TARGET))] async fn process_block_activated( ctx: &mut Context, db: &Arc, hash: Hash, + metrics: &Metrics, ) -> Result<(), Error> where Context: SubsystemContext { + let _timer = metrics.time_block_activated(); + let events = match request_candidate_events(ctx, hash).await { Ok(events) => events, Err(err) => { @@ -697,6 +706,8 @@ where { use AvailabilityStoreMessage::*; + let _timer = subsystem.metrics.time_process_message(); + match msg { QueryAvailableData(hash, tx) => { tx.send(available_data(&subsystem.inner, &hash).map(|d| d.data)) @@ -860,6 +871,8 @@ fn store_available_data( n_validators: u32, available_data: AvailableData, ) -> Result<(), Error> { + let _timer = subsystem.metrics.time_store_available_data(); + let mut tx = DBTransaction::new(); let block_number = available_data.validation_data.block_number; @@ -927,6 +940,8 @@ fn store_chunk( chunk: ErasureChunk, block_number: BlockNumber, ) -> Result<(), Error> { + let _timer = subsystem.metrics.time_store_chunk(); + let mut tx = DBTransaction::new(); let dbkey = erasure_chunk_key(candidate_hash, chunk.index); @@ -977,6 +992,8 @@ fn get_chunk( candidate_hash: &CandidateHash, index: u32, ) -> Result, Error> { + let _timer = subsystem.metrics.time_get_chunk(); + if let Some(chunk) = query_inner( &subsystem.inner, columns::DATA, @@ -1059,6 +1076,14 @@ fn get_chunks(data: &AvailableData, n_validators: usize, metrics: &Metrics) -> R #[derive(Clone)] struct MetricsInner { received_availability_chunks_total: prometheus::Counter, + prune_povs: prometheus::Histogram, + prune_chunks: prometheus::Histogram, + process_block_finalized: prometheus::Histogram, + block_activated: prometheus::Histogram, + process_message: prometheus::Histogram, + store_available_data: prometheus::Histogram, + store_chunk: prometheus::Histogram, + get_chunk: prometheus::Histogram, } /// Availability metrics. @@ -1074,6 +1099,46 @@ impl Metrics { metrics.received_availability_chunks_total.inc_by(by); } } + + /// Provide a timer for `prune_povs` which observes on drop. + fn time_prune_povs(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.prune_povs.start_timer()) + } + + /// Provide a timer for `prune_chunks` which observes on drop. + fn time_prune_chunks(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.prune_chunks.start_timer()) + } + + /// Provide a timer for `process_block_finalized` which observes on drop. + fn time_process_block_finalized(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.process_block_finalized.start_timer()) + } + + /// Provide a timer for `block_activated` which observes on drop. + fn time_block_activated(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.block_activated.start_timer()) + } + + /// Provide a timer for `process_message` which observes on drop. + fn time_process_message(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.process_message.start_timer()) + } + + /// Provide a timer for `store_available_data` which observes on drop. + fn time_store_available_data(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.store_available_data.start_timer()) + } + + /// Provide a timer for `store_chunk` which observes on drop. + fn time_store_chunk(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.store_chunk.start_timer()) + } + + /// Provide a timer for `get_chunk` which observes on drop. + fn time_get_chunk(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.get_chunk.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -1086,6 +1151,78 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + prune_povs: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_av_store_prune_povs", + "Time spent within `av_store::prune_povs`", + ) + )?, + registry, + )?, + prune_chunks: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_av_store_prune_chunks", + "Time spent within `av_store::prune_chunks`", + ) + )?, + registry, + )?, + process_block_finalized: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_av_store_process_block_finalized", + "Time spent within `av_store::block_finalized`", + ) + )?, + registry, + )?, + block_activated: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_av_store_block_activated", + "Time spent within `av_store::block_activated`", + ) + )?, + registry, + )?, + process_message: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_av_store_process_message", + "Time spent within `av_store::process_message`", + ) + )?, + registry, + )?, + store_available_data: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_av_store_store_available_data", + "Time spent within `av_store::store_available_data`", + ) + )?, + registry, + )?, + store_chunk: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_av_store_store_chunk", + "Time spent within `av_store::store_chunk`", + ) + )?, + registry, + )?, + get_chunk: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_av_store_get_chunk", + "Time spent within `av_store::get_chunk`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/core/backing/src/lib.rs b/polkadot/node/core/backing/src/lib.rs index 7c7b248a74..def1d0dd56 100644 --- a/polkadot/node/core/backing/src/lib.rs +++ b/polkadot/node/core/backing/src/lib.rs @@ -481,8 +481,11 @@ impl CandidateBackingJob { #[tracing::instrument(level = "trace", skip(self), fields(subsystem = LOG_TARGET))] async fn process_msg(&mut self, msg: CandidateBackingMessage) -> Result<(), Error> { + match msg { CandidateBackingMessage::Second(_, candidate, pov) => { + let _timer = self.metrics.time_process_second(); + // Sanity check that candidate is from our assignment. if candidate.descriptor().para_id != self.assignment { return Ok(()); @@ -509,6 +512,8 @@ impl CandidateBackingJob { } } CandidateBackingMessage::Statement(_, statement) => { + let _timer = self.metrics.time_process_statement(); + self.check_statement_signature(&statement)?; match self.maybe_validate_and_import(statement).await { Err(Error::ValidationFailed(_)) => return Ok(()), @@ -517,6 +522,8 @@ impl CandidateBackingJob { } } CandidateBackingMessage::GetBackedCandidates(_, tx) => { + let _timer = self.metrics.time_get_backed_candidates(); + let backed = self.get_backed(); tx.send(backed).map_err(|data| Error::Send(data))?; @@ -898,7 +905,10 @@ impl util::JobTrait for CandidateBackingJob { #[derive(Clone)] struct MetricsInner { signed_statements_total: prometheus::Counter, - candidates_seconded_total: prometheus::Counter + candidates_seconded_total: prometheus::Counter, + process_second: prometheus::Histogram, + process_statement: prometheus::Histogram, + get_backed_candidates: prometheus::Histogram, } /// Candidate backing metrics. @@ -917,6 +927,21 @@ impl Metrics { metrics.candidates_seconded_total.inc(); } } + + /// Provide a timer for handling `CandidateBackingMessage:Second` which observes on drop. + fn time_process_second(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.process_second.start_timer()) + } + + /// Provide a timer for handling `CandidateBackingMessage::Statement` which observes on drop. + fn time_process_statement(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.process_statement.start_timer()) + } + + /// Provide a timer for handling `CandidateBackingMessage::GetBackedCandidates` which observes on drop. + fn time_get_backed_candidates(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.get_backed_candidates.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -924,18 +949,45 @@ impl metrics::Metrics for Metrics { let metrics = MetricsInner { signed_statements_total: prometheus::register( prometheus::Counter::new( - "parachain_signed_statements_total", + "parachain_candidate_backing_signed_statements_total", "Number of statements signed.", )?, registry, )?, candidates_seconded_total: prometheus::register( prometheus::Counter::new( - "parachain_candidates_seconded_total", + "parachain_candidate_backing_candidates_seconded_total", "Number of candidates seconded.", )?, registry, )?, + process_second: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_candidate_backing_process_second", + "Time spent within `candidate_backing::process_second`", + ) + )?, + registry, + )?, + process_statement: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_candidate_backing_process_statement", + "Time spent within `candidate_backing::process_statement`", + ) + )?, + registry, + )?, + get_backed_candidates: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_candidate_backing_get_backed_candidates", + "Time spent within `candidate_backing::get_backed_candidates`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/core/bitfield-signing/src/lib.rs b/polkadot/node/core/bitfield-signing/src/lib.rs index a0d3f938ae..6bbd4f48ea 100644 --- a/polkadot/node/core/bitfield-signing/src/lib.rs +++ b/polkadot/node/core/bitfield-signing/src/lib.rs @@ -230,6 +230,7 @@ async fn construct_availability_bitfield( #[derive(Clone)] struct MetricsInner { bitfields_signed_total: prometheus::Counter, + run: prometheus::Histogram, } /// Bitfield signing metrics. @@ -242,6 +243,11 @@ impl Metrics { metrics.bitfields_signed_total.inc(); } } + + /// Provide a timer for `prune_povs` which observes on drop. + fn time_run(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.run.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -254,6 +260,15 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + run: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_bitfield_signing_run", + "Time spent within `bitfield_signing::run`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } @@ -277,6 +292,7 @@ impl JobTrait for BitfieldSigningJob { _receiver: mpsc::Receiver, mut sender: mpsc::Sender, ) -> Pin> + Send>> { + let metrics = metrics.clone(); async move { let wait_until = Instant::now() + JOB_DELAY; @@ -291,6 +307,10 @@ impl JobTrait for BitfieldSigningJob { // wait a bit before doing anything else Delay::new_at(wait_until).await?; + // this timer does not appear at the head of the function because we don't want to include + // JOB_DELAY each time. + let _timer = metrics.time_run(); + let bitfield = match construct_availability_bitfield(relay_parent, validator.index(), &mut sender).await { diff --git a/polkadot/node/core/candidate-selection/src/lib.rs b/polkadot/node/core/candidate-selection/src/lib.rs index b4654d121b..64697a69a5 100644 --- a/polkadot/node/core/candidate-selection/src/lib.rs +++ b/polkadot/node/core/candidate-selection/src/lib.rs @@ -204,6 +204,8 @@ impl CandidateSelectionJob { para_id: ParaId, collator_id: CollatorId, ) { + let _timer = self.metrics.time_handle_collation(); + if self.seconded_candidate.is_none() { let (candidate_receipt, pov) = match get_collation( @@ -240,6 +242,8 @@ impl CandidateSelectionJob { #[tracing::instrument(level = "trace", skip(self), fields(subsystem = LOG_TARGET))] async fn handle_invalid(&mut self, candidate_receipt: CandidateReceipt) { + let _timer = self.metrics.time_handle_invalid(); + let received_from = match &self.seconded_candidate { Some(peer) => peer, None => { @@ -336,6 +340,8 @@ async fn forward_invalidity_note( struct MetricsInner { seconds: prometheus::CounterVec, invalid_selections: prometheus::CounterVec, + handle_collation: prometheus::Histogram, + handle_invalid: prometheus::Histogram, } /// Candidate selection metrics. @@ -356,6 +362,16 @@ impl Metrics { metrics.invalid_selections.with_label_values(&[label]).inc(); } } + + /// Provide a timer for `handle_collation` which observes on drop. + fn time_handle_collation(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_collation.start_timer()) + } + + /// Provide a timer for `handle_invalid` which observes on drop. + fn time_handle_invalid(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_invalid.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -381,6 +397,24 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + handle_collation: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_candidate_selection_handle_collation", + "Time spent within `candidate_selection::handle_collation`", + ) + )?, + registry, + )?, + handle_invalid: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_candidate_selection:handle_invalid", + "Time spent within `candidate_selection::handle_invalid`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/core/candidate-validation/src/lib.rs b/polkadot/node/core/candidate-validation/src/lib.rs index b2382f59e3..011b156ffd 100644 --- a/polkadot/node/core/candidate-validation/src/lib.rs +++ b/polkadot/node/core/candidate-validation/src/lib.rs @@ -103,12 +103,15 @@ async fn run( pov, response_sender, ) => { + let _timer = metrics.time_validate_from_chain_state(); + let res = spawn_validate_from_chain_state( &mut ctx, isolation_strategy.clone(), descriptor, pov, spawn.clone(), + &metrics, ).await; match res { @@ -126,6 +129,8 @@ async fn run( pov, response_sender, ) => { + let _timer = metrics.time_validate_from_exhaustive(); + let res = spawn_validate_exhaustive( &mut ctx, isolation_strategy.clone(), @@ -134,6 +139,7 @@ async fn run( descriptor, pov, spawn.clone(), + &metrics, ).await; match res { @@ -260,13 +266,14 @@ async fn find_assumed_validation_data( Ok(AssumptionCheckOutcome::DoesNotMatch) } -#[tracing::instrument(level = "trace", skip(ctx, pov, spawn), fields(subsystem = LOG_TARGET))] +#[tracing::instrument(level = "trace", skip(ctx, pov, spawn, metrics), fields(subsystem = LOG_TARGET))] async fn spawn_validate_from_chain_state( ctx: &mut impl SubsystemContext, isolation_strategy: IsolationStrategy, descriptor: CandidateDescriptor, pov: Arc, spawn: impl SpawnNamed + 'static, + metrics: &Metrics, ) -> SubsystemResult> { let (validation_data, validation_code) = match find_assumed_validation_data(ctx, &descriptor).await? { @@ -292,6 +299,7 @@ async fn spawn_validate_from_chain_state( descriptor.clone(), pov, spawn, + metrics, ) .await; @@ -320,7 +328,7 @@ async fn spawn_validate_from_chain_state( validation_result } -#[tracing::instrument(level = "trace", skip(ctx, validation_code, pov, spawn), fields(subsystem = LOG_TARGET))] +#[tracing::instrument(level = "trace", skip(ctx, validation_code, pov, spawn, metrics), fields(subsystem = LOG_TARGET))] async fn spawn_validate_exhaustive( ctx: &mut impl SubsystemContext, isolation_strategy: IsolationStrategy, @@ -329,8 +337,10 @@ async fn spawn_validate_exhaustive( descriptor: CandidateDescriptor, pov: Arc, spawn: impl SpawnNamed + 'static, + metrics: &Metrics, ) -> SubsystemResult> { let (tx, rx) = oneshot::channel(); + let metrics = metrics.clone(); let fut = async move { let res = validate_candidate_exhaustive::( isolation_strategy, @@ -339,6 +349,7 @@ async fn spawn_validate_exhaustive( descriptor, pov, spawn, + &metrics, ); let _ = tx.send(res); @@ -408,7 +419,7 @@ impl ValidationBackend for RealValidationBackend { /// Validates the candidate from exhaustive parameters. /// /// Sends the result of validation on the channel once complete. -#[tracing::instrument(level = "trace", skip(backend_arg, validation_code, pov, spawn), fields(subsystem = LOG_TARGET))] +#[tracing::instrument(level = "trace", skip(backend_arg, validation_code, pov, spawn, metrics), fields(subsystem = LOG_TARGET))] fn validate_candidate_exhaustive( backend_arg: B::Arg, persisted_validation_data: PersistedValidationData, @@ -416,7 +427,10 @@ fn validate_candidate_exhaustive( descriptor: CandidateDescriptor, pov: Arc, spawn: S, + metrics: &Metrics, ) -> Result { + let _timer = metrics.time_validate_candidate_exhaustive(); + if let Err(e) = perform_basic_checks(&descriptor, persisted_validation_data.max_pov_size, &*pov) { return Ok(ValidationResult::Invalid(e)) } @@ -460,6 +474,9 @@ fn validate_candidate_exhaustive( #[derive(Clone)] struct MetricsInner { validation_requests: prometheus::CounterVec, + validate_from_chain_state: prometheus::Histogram, + validate_from_exhaustive: prometheus::Histogram, + validate_candidate_exhaustive: prometheus::Histogram, } /// Candidate validation metrics. @@ -482,6 +499,21 @@ impl Metrics { } } } + + /// Provide a timer for `validate_from_chain_state` which observes on drop. + fn time_validate_from_chain_state(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.validate_from_chain_state.start_timer()) + } + + /// Provide a timer for `validate_from_exhaustive` which observes on drop. + fn time_validate_from_exhaustive(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.validate_from_exhaustive.start_timer()) + } + + /// Provide a timer for `validate_candidate_exhaustive` which observes on drop. + fn time_validate_candidate_exhaustive(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.validate_candidate_exhaustive.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -497,6 +529,33 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + validate_from_chain_state: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_candidate_validation_validate_from_chain_state", + "Time spent within `candidate_validation::validate_from_chain_state`", + ) + )?, + registry, + )?, + validate_from_exhaustive: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_candidate_validation_validate_from_exhaustive", + "Time spent within `candidate_validation::validate_from_exhaustive`", + ) + )?, + registry, + )?, + validate_candidate_exhaustive: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_candidate_validation_validate_candidate_exhaustive", + "Time spent within `candidate_validation::validate_candidate_exhaustive`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } @@ -850,6 +909,7 @@ mod tests { descriptor, Arc::new(pov), TaskExecutor::new(), + &Default::default(), ).unwrap(); assert_matches!(v, ValidationResult::Valid(outputs, used_validation_data) => { @@ -885,6 +945,7 @@ mod tests { descriptor, Arc::new(pov), TaskExecutor::new(), + &Default::default(), ).unwrap(); assert_matches!(v, ValidationResult::Invalid(InvalidCandidate::BadReturn)); @@ -913,6 +974,7 @@ mod tests { descriptor, Arc::new(pov), TaskExecutor::new(), + &Default::default(), ); assert_matches!(v, Ok(ValidationResult::Invalid(InvalidCandidate::Timeout))); diff --git a/polkadot/node/core/chain-api/src/lib.rs b/polkadot/node/core/chain-api/src/lib.rs index 9868ead623..3c7a2a7241 100644 --- a/polkadot/node/core/chain-api/src/lib.rs +++ b/polkadot/node/core/chain-api/src/lib.rs @@ -92,11 +92,13 @@ where FromOverseer::Signal(OverseerSignal::BlockFinalized(_)) => {}, FromOverseer::Communication { msg } => match msg { ChainApiMessage::BlockNumber(hash, response_channel) => { + let _timer = subsystem.metrics.time_block_number(); let result = subsystem.client.number(hash).map_err(|e| e.to_string().into()); subsystem.metrics.on_request(result.is_ok()); let _ = response_channel.send(result); }, ChainApiMessage::BlockHeader(hash, response_channel) => { + let _timer = subsystem.metrics.time_block_header(); let result = subsystem.client .header(BlockId::Hash(hash)) .map_err(|e| e.to_string().into()); @@ -104,19 +106,23 @@ where let _ = response_channel.send(result); }, ChainApiMessage::FinalizedBlockHash(number, response_channel) => { + let _timer = subsystem.metrics.time_finalized_block_hash(); // Note: we don't verify it's finalized let result = subsystem.client.hash(number).map_err(|e| e.to_string().into()); subsystem.metrics.on_request(result.is_ok()); let _ = response_channel.send(result); }, ChainApiMessage::FinalizedBlockNumber(response_channel) => { + let _timer = subsystem.metrics.time_finalized_block_number(); let result = subsystem.client.info().finalized_number; // always succeeds subsystem.metrics.on_request(true); let _ = response_channel.send(Ok(result)); }, ChainApiMessage::Ancestors { hash, k, response_channel } => { + let _timer = subsystem.metrics.time_ancestors(); tracing::span!(tracing::Level::TRACE, "ChainApiMessage::Ancestors", subsystem=LOG_TARGET, hash=%hash, k=k); + let mut hash = hash; let next_parent = core::iter::from_fn(|| { @@ -153,6 +159,11 @@ where #[derive(Clone)] struct MetricsInner { chain_api_requests: prometheus::CounterVec, + block_number: prometheus::Histogram, + block_header: prometheus::Histogram, + finalized_block_hash: prometheus::Histogram, + finalized_block_number: prometheus::Histogram, + ancestors: prometheus::Histogram, } /// Chain API metrics. @@ -169,6 +180,31 @@ impl Metrics { } } } + + /// Provide a timer for `block_number` which observes on drop. + fn time_block_number(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.block_number.start_timer()) + } + + /// Provide a timer for `block_header` which observes on drop. + fn time_block_header(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.block_header.start_timer()) + } + + /// Provide a timer for `finalized_block_hash` which observes on drop. + fn time_finalized_block_hash(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.finalized_block_hash.start_timer()) + } + + /// Provide a timer for `finalized_block_number` which observes on drop. + fn time_finalized_block_number(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.finalized_block_number.start_timer()) + } + + /// Provide a timer for `ancestors` which observes on drop. + fn time_ancestors(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.ancestors.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -184,6 +220,51 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + block_number: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_chain_api_block_number", + "Time spent within `chain_api::block_number`", + ) + )?, + registry, + )?, + block_header: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_chain_api_block_headers", + "Time spent within `chain_api::block_headers`", + ) + )?, + registry, + )?, + finalized_block_hash: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_chain_api_finalized_block_hash", + "Time spent within `chain_api::finalized_block_hash`", + ) + )?, + registry, + )?, + finalized_block_number: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_chain_api_finalized_block_number", + "Time spent within `chain_api::finalized_block_number`", + ) + )?, + registry, + )?, + ancestors: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_chain_api_ancestors", + "Time spent within `chain_api::ancestors`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/core/provisioner/src/lib.rs b/polkadot/node/core/provisioner/src/lib.rs index 18913613c6..1a33c3fdb0 100644 --- a/polkadot/node/core/provisioner/src/lib.rs +++ b/polkadot/node/core/provisioner/src/lib.rs @@ -197,6 +197,8 @@ impl ProvisioningJob { match msg { ToJob::Provisioner(RequestInherentData(_, return_sender)) => { + let _timer = self.metrics.time_request_inherent_data(); + if let Err(err) = send_inherent_data( self.relay_parent, &self.signed_bitfields, @@ -216,6 +218,8 @@ impl ProvisioningJob { self.provisionable_data_channels.push(sender) } ToJob::Provisioner(ProvisionableData(_, data)) => { + let _timer = self.metrics.time_provisionable_data(); + let mut bad_indices = Vec::new(); for (idx, channel) in self.provisionable_data_channels.iter_mut().enumerate() { match channel.send(data.clone()).await { @@ -488,6 +492,8 @@ fn bitfields_indicate_availability( #[derive(Clone)] struct MetricsInner { inherent_data_requests: prometheus::CounterVec, + request_inherent_data: prometheus::Histogram, + provisionable_data: prometheus::Histogram, } /// Provisioner metrics. @@ -503,6 +509,16 @@ impl Metrics { } } } + + /// Provide a timer for `request_inherent_data` which observes on drop. + fn time_request_inherent_data(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.request_inherent_data.start_timer()) + } + + /// Provide a timer for `provisionable_data` which observes on drop. + fn time_provisionable_data(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.provisionable_data.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -518,6 +534,24 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + request_inherent_data: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_provisioner_request_inherent_data", + "Time spent within `provisioner::request_inherent_data`", + ) + )?, + registry, + )?, + provisionable_data: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_provisioner_provisionable_data", + "Time spent within `provisioner::provisionable_data`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/core/runtime-api/src/lib.rs b/polkadot/node/core/runtime-api/src/lib.rs index 255965815a..c957302737 100644 --- a/polkadot/node/core/runtime-api/src/lib.rs +++ b/polkadot/node/core/runtime-api/src/lib.rs @@ -103,6 +103,8 @@ fn make_runtime_api_request( Client: ProvideRuntimeApi, Client::Api: ParachainHost, { + let _timer = metrics.time_make_runtime_api_request(); + macro_rules! query { ($api_name:ident ($($param:expr),*), $sender:expr) => {{ let sender = $sender; @@ -141,6 +143,7 @@ fn make_runtime_api_request( #[derive(Clone)] struct MetricsInner { chain_api_requests: prometheus::CounterVec, + make_runtime_api_request: prometheus::Histogram, } /// Runtime API metrics. @@ -157,6 +160,11 @@ impl Metrics { } } } + + /// Provide a timer for `make_runtime_api_request` which observes on drop. + fn time_make_runtime_api_request(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.make_runtime_api_request.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -172,6 +180,15 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + make_runtime_api_request: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_runtime_api_make_runtime_api_request", + "Time spent within `runtime_api::make_runtime_api_request`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/network/availability-distribution/src/lib.rs b/polkadot/node/network/availability-distribution/src/lib.rs index 9f390e4cab..24d48acc9e 100644 --- a/polkadot/node/network/availability-distribution/src/lib.rs +++ b/polkadot/node/network/availability-distribution/src/lib.rs @@ -385,6 +385,8 @@ async fn handle_our_view_change( where Context: SubsystemContext, { + let _timer = metrics.time_handle_our_view_change(); + let old_view = std::mem::replace(&mut (state.view), view); // needed due to borrow rules @@ -651,6 +653,8 @@ async fn process_incoming_peer_message( where Context: SubsystemContext, { + let _timer = metrics.time_process_incoming_peer_message(); + // obtain the set of candidates we are interested in based on our current view let live_candidates = state.cached_live_candidates_unioned(state.view.0.iter()); @@ -1180,6 +1184,8 @@ where #[derive(Clone)] struct MetricsInner { gossipped_availability_chunks: prometheus::Counter, + handle_our_view_change: prometheus::Histogram, + process_incoming_peer_message: prometheus::Histogram, } /// Availability Distribution metrics. @@ -1192,6 +1198,16 @@ impl Metrics { metrics.gossipped_availability_chunks.inc(); } } + + /// Provide a timer for `handle_our_view_change` which observes on drop. + fn time_handle_our_view_change(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_our_view_change.start_timer()) + } + + /// Provide a timer for `process_incoming_peer_message` which observes on drop. + fn time_process_incoming_peer_message(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.process_incoming_peer_message.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -1206,6 +1222,24 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + handle_our_view_change: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_availability_distribution_handle_our_view_change", + "Time spent within `availability_distribution::handle_our_view_change`", + ) + )?, + registry, + )?, + process_incoming_peer_message: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_availability_distribution_process_incoming_peer_message", + "Time spent within `availability_distribution::process_incoming_peer_message`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/network/bitfield-distribution/src/lib.rs b/polkadot/node/network/bitfield-distribution/src/lib.rs index 7b2348eee6..680c450bd5 100644 --- a/polkadot/node/network/bitfield-distribution/src/lib.rs +++ b/polkadot/node/network/bitfield-distribution/src/lib.rs @@ -183,6 +183,8 @@ impl BitfieldDistribution { } } FromOverseer::Signal(OverseerSignal::ActiveLeaves(ActiveLeavesUpdate { activated, deactivated })) => { + let _timer = self.metrics.time_active_leaves_update(); + for relay_parent in activated { tracing::trace!(target: LOG_TARGET, relay_parent = %relay_parent, "activated"); // query basic system parameters once @@ -257,6 +259,8 @@ async fn handle_bitfield_distribution( where Context: SubsystemContext, { + let _timer = metrics.time_handle_bitfield_distribution(); + // Ignore anything the overseer did not tell this subsystem to work on let mut job_data = state.per_relay_parent.get_mut(&relay_parent); let job_data: &mut _ = if let Some(ref mut job_data) = job_data { @@ -461,6 +465,8 @@ async fn handle_network_msg( where Context: SubsystemContext, { + let _timer = metrics.time_handle_network_msg(); + match bridge_message { NetworkBridgeEvent::PeerConnected(peerid, _role) => { // insert if none already present @@ -659,6 +665,9 @@ where struct MetricsInner { gossipped_own_availability_bitfields: prometheus::Counter, received_availability_bitfields: prometheus::Counter, + active_leaves_update: prometheus::Histogram, + handle_bitfield_distribution: prometheus::Histogram, + handle_network_msg: prometheus::Histogram, } /// Bitfield Distribution metrics. @@ -677,6 +686,21 @@ impl Metrics { metrics.received_availability_bitfields.inc(); } } + + /// Provide a timer for `active_leaves_update` which observes on drop. + fn time_active_leaves_update(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.active_leaves_update.start_timer()) + } + + /// Provide a timer for `handle_bitfield_distribution` which observes on drop. + fn time_handle_bitfield_distribution(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_bitfield_distribution.start_timer()) + } + + /// Provide a timer for `handle_network_msg` which observes on drop. + fn time_handle_network_msg(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_network_msg.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -696,6 +720,33 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + active_leaves_update: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_bitfield_distribution_active_leaves_update", + "Time spent within `bitfield_distribution::active_leaves_update`", + ) + )?, + registry, + )?, + handle_bitfield_distribution: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_bitfield_distribution_handle_bitfield_distribution", + "Time spent within `bitfield_distribution::handle_bitfield_distribution`", + ) + )?, + registry, + )?, + handle_network_msg: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_bitfield_distribution_handle_network_msg", + "Time spent within `bitfield_distribution::handle_network_msg`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/network/collator-protocol/src/collator_side.rs b/polkadot/node/network/collator-protocol/src/collator_side.rs index 9267ab0916..853221e0d7 100644 --- a/polkadot/node/network/collator-protocol/src/collator_side.rs +++ b/polkadot/node/network/collator-protocol/src/collator_side.rs @@ -57,12 +57,24 @@ impl Metrics { metrics.collations_sent.inc(); } } + + /// Provide a timer for handling `ConnectionRequest` which observes on drop. + fn time_handle_connection_request(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_connection_request.start_timer()) + } + + /// Provide a timer for `process_msg` which observes on drop. + fn time_process_msg(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.process_msg.start_timer()) + } } #[derive(Clone)] struct MetricsInner { advertisements_made: prometheus::Counter, collations_sent: prometheus::Counter, + handle_connection_request: prometheus::Histogram, + process_msg: prometheus::Histogram, } impl metrics::Metrics for Metrics { @@ -84,6 +96,24 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + handle_connection_request: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_collator_protocol_collator_handle_connection_request", + "Time spent within `collator_protocol_collator::handle_connection_request`", + ) + )?, + registry, + )?, + process_msg: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_collator_protocol_collator_process_msg", + "Time spent within `collator_protocol_collator::process_msg`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) @@ -377,6 +407,8 @@ where { use CollatorProtocolMessage::*; + let _timer = state.metrics.time_process_msg(); + match msg { CollateOn(id) => { state.collating_on = Some(id); @@ -662,6 +694,8 @@ where loop { if let Some(mut request) = state.last_connection_request.take() { + let _timer = state.metrics.time_handle_connection_request(); + while let Poll::Ready(Some((validator_id, peer_id))) = futures::poll!(request.next()) { if let Err(err) = handle_validator_connected(&mut ctx, &mut state, peer_id, validator_id).await { tracing::warn!( diff --git a/polkadot/node/network/collator-protocol/src/validator_side.rs b/polkadot/node/network/collator-protocol/src/validator_side.rs index f3a5958a67..faeda6d307 100644 --- a/polkadot/node/network/collator-protocol/src/validator_side.rs +++ b/polkadot/node/network/collator-protocol/src/validator_side.rs @@ -63,11 +63,23 @@ impl Metrics { } } } + + /// Provide a timer for `process_msg` which observes on drop. + fn time_process_msg(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.process_msg.start_timer()) + } + + /// Provide a timer for `handle_collation_request_result` which observes on drop. + fn time_handle_collation_request_result(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_collation_request_result.start_timer()) + } } #[derive(Clone)] struct MetricsInner { collation_requests: prometheus::CounterVec, + process_msg: prometheus::Histogram, + handle_collation_request_result: prometheus::Histogram, } impl metrics::Metrics for Metrics { @@ -84,7 +96,25 @@ impl metrics::Metrics for Metrics { &["success"], )?, registry, - )? + )?, + process_msg: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_collator_protocol_validator_process_msg", + "Time spent within `collator_protocol_validator::process_msg`", + ) + )?, + registry, + )?, + handle_collation_request_result: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_collator_protocol_validator_handle_collation_request_result", + "Time spent within `collator_protocol_validator::handle_collation_request_result`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) @@ -628,6 +658,8 @@ where { use CollatorProtocolMessage::*; + let _timer = state.metrics.time_process_msg(); + match msg { CollateOn(id) => { tracing::warn!( @@ -703,6 +735,8 @@ where } while let Poll::Ready(Some(request)) = futures::poll!(state.requests_in_progress.next()) { + let _timer = state.metrics.time_handle_collation_request_result(); + // Request has timed out, we need to penalize the collator and re-send the request // if the chain has not moved on yet. match request { diff --git a/polkadot/node/network/pov-distribution/src/lib.rs b/polkadot/node/network/pov-distribution/src/lib.rs index b1d7a8367c..e0050aeb27 100644 --- a/polkadot/node/network/pov-distribution/src/lib.rs +++ b/polkadot/node/network/pov-distribution/src/lib.rs @@ -125,6 +125,8 @@ async fn handle_signal( match signal { OverseerSignal::Conclude => Ok(true), OverseerSignal::ActiveLeaves(ActiveLeavesUpdate { activated, deactivated }) => { + let _timer = state.metrics.time_handle_signal(); + for relay_parent in activated { let (vals_tx, vals_rx) = oneshot::channel(); ctx.send_message(AllMessages::RuntimeApi(RuntimeApiMessage::Request( @@ -267,6 +269,8 @@ async fn handle_fetch( descriptor: CandidateDescriptor, response_sender: oneshot::Sender>, ) -> SubsystemResult<()> { + let _timer = state.metrics.time_handle_fetch(); + let relay_parent_state = match state.relay_parent_state.get_mut(&relay_parent) { Some(s) => s, None => return Ok(()), @@ -316,6 +320,8 @@ async fn handle_distribute( descriptor: CandidateDescriptor, pov: Arc, ) -> SubsystemResult<()> { + let _timer = state.metrics.time_handle_distribute(); + let relay_parent_state = match state.relay_parent_state.get_mut(&relay_parent) { None => return Ok(()), Some(s) => s, @@ -483,6 +489,8 @@ async fn handle_network_update( ctx: &mut impl SubsystemContext, update: NetworkBridgeEvent, ) -> SubsystemResult<()> { + let _timer = state.metrics.time_handle_network_update(); + match update { NetworkBridgeEvent::PeerConnected(peer, _observed_role) => { state.peer_state.insert(peer, PeerState { awaited: HashMap::new() }); @@ -600,6 +608,10 @@ impl PoVDistribution { #[derive(Clone)] struct MetricsInner { povs_distributed: prometheus::Counter, + handle_signal: prometheus::Histogram, + handle_fetch: prometheus::Histogram, + handle_distribute: prometheus::Histogram, + handle_network_update: prometheus::Histogram, } /// Availability Distribution metrics. @@ -612,6 +624,26 @@ impl Metrics { metrics.povs_distributed.inc(); } } + + /// Provide a timer for `handle_signal` which observes on drop. + fn time_handle_signal(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_signal.start_timer()) + } + + /// Provide a timer for `handle_fetch` which observes on drop. + fn time_handle_fetch(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_fetch.start_timer()) + } + + /// Provide a timer for `handle_distribute` which observes on drop. + fn time_handle_distribute(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_distribute.start_timer()) + } + + /// Provide a timer for `handle_network_update` which observes on drop. + fn time_handle_network_update(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.handle_network_update.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -624,6 +656,42 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + handle_signal: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_pov_distribution_handle_signal", + "Time spent within `pov_distribution::handle_signal`", + ) + )?, + registry, + )?, + handle_fetch: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_pov_distribution_handle_fetch", + "Time spent within `pov_distribution::handle_fetch`", + ) + )?, + registry, + )?, + handle_distribute: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_pov_distribution_handle_distribute", + "Time spent within `pov_distribution::handle_distribute`", + ) + )?, + registry, + )?, + handle_network_update: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_pov_distribution_handle_network_update", + "Time spent within `pov_distribution::handle_network_update`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/network/statement-distribution/src/lib.rs b/polkadot/node/network/statement-distribution/src/lib.rs index 383f34a6fc..b01b60014e 100644 --- a/polkadot/node/network/statement-distribution/src/lib.rs +++ b/polkadot/node/network/statement-distribution/src/lib.rs @@ -895,6 +895,8 @@ impl StatementDistribution { let message = ctx.recv().await?; match message { FromOverseer::Signal(OverseerSignal::ActiveLeaves(ActiveLeavesUpdate { activated, .. })) => { + let _timer = metrics.time_active_leaves_update(); + for relay_parent in activated { let (validators, session_index) = { let (val_tx, val_rx) = oneshot::channel(); @@ -944,6 +946,8 @@ impl StatementDistribution { FromOverseer::Signal(OverseerSignal::Conclude) => break, FromOverseer::Communication { msg } => match msg { StatementDistributionMessage::Share(relay_parent, statement) => { + let _timer = metrics.time_share(); + inform_statement_listeners( &statement, &mut statement_listeners, @@ -957,7 +961,9 @@ impl StatementDistribution { &metrics, ).await?; } - StatementDistributionMessage::NetworkBridgeUpdateV1(event) => + StatementDistributionMessage::NetworkBridgeUpdateV1(event) => { + let _timer = metrics.time_network_bridge_update_v1(); + handle_network_update( &mut peers, &mut active_heads, @@ -965,7 +971,8 @@ impl StatementDistribution { &mut our_view, event, &metrics, - ).await?, + ).await? + } StatementDistributionMessage::RegisterStatementListener(tx) => { statement_listeners.push(tx); } @@ -979,6 +986,9 @@ impl StatementDistribution { #[derive(Clone)] struct MetricsInner { statements_distributed: prometheus::Counter, + active_leaves_update: prometheus::Histogram, + share: prometheus::Histogram, + network_bridge_update_v1: prometheus::Histogram, } /// Statement Distribution metrics. @@ -991,6 +1001,21 @@ impl Metrics { metrics.statements_distributed.inc(); } } + + /// Provide a timer for `active_leaves_update` which observes on drop. + fn time_active_leaves_update(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.active_leaves_update.start_timer()) + } + + /// Provide a timer for `share` which observes on drop. + fn time_share(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.share.start_timer()) + } + + /// Provide a timer for `network_bridge_update_v1` which observes on drop. + fn time_network_bridge_update_v1(&self) -> Option { + self.0.as_ref().map(|metrics| metrics.network_bridge_update_v1.start_timer()) + } } impl metrics::Metrics for Metrics { @@ -1003,6 +1028,33 @@ impl metrics::Metrics for Metrics { )?, registry, )?, + active_leaves_update: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_statement_distribution_active_leaves_update", + "Time spent within `statement_distribution::active_leaves_update`", + ) + )?, + registry, + )?, + share: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_statement_distribution_share", + "Time spent within `statement_distribution::share`", + ) + )?, + registry, + )?, + network_bridge_update_v1: prometheus::register( + prometheus::Histogram::with_opts( + prometheus::HistogramOpts::new( + "parachain_statement_distribution_network_bridge_update_v1", + "Time spent within `statement_distribution::network_bridge_update_v1`", + ) + )?, + registry, + )?, }; Ok(Metrics(Some(metrics))) } diff --git a/polkadot/node/subsystem-util/src/lib.rs b/polkadot/node/subsystem-util/src/lib.rs index 2c7129f35c..5766f25f16 100644 --- a/polkadot/node/subsystem-util/src/lib.rs +++ b/polkadot/node/subsystem-util/src/lib.rs @@ -442,9 +442,10 @@ impl JobHandle { /// This module reexports Prometheus types and defines the [`Metrics`] trait. pub mod metrics { - /// Reexport Prometheus types. + /// Reexport Substrate Prometheus types. pub use substrate_prometheus_endpoint as prometheus; + /// Subsystem- or job-specific Prometheus metrics. /// /// Usually implemented as a wrapper for `Option` diff --git a/polkadot/parachain/test-parachains/adder/collator/Cargo.toml b/polkadot/parachain/test-parachains/adder/collator/Cargo.toml index 864149f707..0a2fefa5a8 100644 --- a/polkadot/parachain/test-parachains/adder/collator/Cargo.toml +++ b/polkadot/parachain/test-parachains/adder/collator/Cargo.toml @@ -26,6 +26,7 @@ polkadot-node-subsystem = { path = "../../../../node/subsystem" } sc-cli = { git = "https://github.com/paritytech/substrate", branch = "master" } sp-core = { git = "https://github.com/paritytech/substrate", branch = "master" } sc-authority-discovery = { git = "https://github.com/paritytech/substrate", branch = "master" } +sc-service = { git = "https://github.com/paritytech/substrate", branch = "master" } [dev-dependencies] polkadot-parachain = { path = "../../.." } diff --git a/polkadot/parachain/test-parachains/adder/collator/README.md b/polkadot/parachain/test-parachains/adder/collator/README.md index 543da44633..e3181a84dd 100644 --- a/polkadot/parachain/test-parachains/adder/collator/README.md +++ b/polkadot/parachain/test-parachains/adder/collator/README.md @@ -13,3 +13,5 @@ cargo run --features=real-overseer --release -p test-parachain-adder-collator -- The last step is to register the parachain using polkadot-js. The parachain id is 100. The genesis state and the validation code are printed at startup by the collator. + +To do this automatically, run `scripts/adder-collator.sh`. diff --git a/polkadot/parachain/test-parachains/adder/collator/src/cli.rs b/polkadot/parachain/test-parachains/adder/collator/src/cli.rs new file mode 100644 index 0000000000..7b59d2acf7 --- /dev/null +++ b/polkadot/parachain/test-parachains/adder/collator/src/cli.rs @@ -0,0 +1,108 @@ +// Copyright 2017-2020 Parity Technologies (UK) Ltd. +// This file is part of Polkadot. + +// Polkadot is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// Polkadot is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. + +// You should have received a copy of the GNU General Public License +// along with Polkadot. If not, see . + +//! Polkadot CLI library. + +use sc_cli::{RuntimeVersion, SubstrateCli}; +use structopt::StructOpt; + +/// Sub-commands supported by the collator. +#[derive(Debug, StructOpt)] +pub enum Subcommand { + /// Export the genesis state of the parachain. + #[structopt(name = "export-genesis-state")] + ExportGenesisState(ExportGenesisStateCommand), + + /// Export the genesis wasm of the parachain. + #[structopt(name = "export-genesis-wasm")] + ExportGenesisWasm(ExportGenesisWasmCommand), +} + +/// Command for exporting the genesis state of the parachain +#[derive(Debug, StructOpt)] +pub struct ExportGenesisStateCommand {} + +/// Command for exporting the genesis wasm file. +#[derive(Debug, StructOpt)] +pub struct ExportGenesisWasmCommand {} + +#[allow(missing_docs)] +#[derive(Debug, StructOpt)] +pub struct RunCmd { + #[allow(missing_docs)] + #[structopt(flatten)] + pub base: sc_cli::RunCmd, +} + +#[allow(missing_docs)] +#[derive(Debug, StructOpt)] +pub struct Cli { + #[structopt(subcommand)] + pub subcommand: Option, + + #[structopt(flatten)] + pub run: RunCmd, +} + +impl SubstrateCli for Cli { + fn impl_name() -> String { + "Parity Polkadot".into() + } + + fn impl_version() -> String { + "0.0.0".into() + } + + fn description() -> String { + env!("CARGO_PKG_DESCRIPTION").into() + } + + fn author() -> String { + env!("CARGO_PKG_AUTHORS").into() + } + + fn support_url() -> String { + "https://github.com/paritytech/polkadot/issues/new".into() + } + + fn copyright_start_year() -> i32 { + 2017 + } + + fn executable_name() -> String { + "polkadot".into() + } + + fn load_spec(&self, id: &str) -> std::result::Result, String> { + let id = if id.is_empty() { "rococo" } else { id }; + Ok(match id { + "rococo-staging" => { + Box::new(polkadot_service::chain_spec::rococo_staging_testnet_config()?) + } + "rococo-local" => { + Box::new(polkadot_service::chain_spec::rococo_local_testnet_config()?) + } + "rococo" => Box::new(polkadot_service::chain_spec::rococo_config()?), + _ => Err("adder collator only supports rococo")?, + }) + } + + fn native_runtime_version( + _spec: &Box, + ) -> &'static RuntimeVersion { + &polkadot_service::rococo_runtime::VERSION + } +} diff --git a/polkadot/parachain/test-parachains/adder/collator/src/lib.rs b/polkadot/parachain/test-parachains/adder/collator/src/lib.rs index d3afbc1483..b31f15e303 100644 --- a/polkadot/parachain/test-parachains/adder/collator/src/lib.rs +++ b/polkadot/parachain/test-parachains/adder/collator/src/lib.rs @@ -16,13 +16,17 @@ //! Collator for the adder test parachain. -use std::{sync::{Arc, Mutex}, collections::HashMap, time::Duration}; -use test_parachain_adder::{hash_state, BlockData, HeadData, execute}; use futures_timer::Delay; -use polkadot_primitives::v1::{PoV, CollatorId, CollatorPair}; use polkadot_node_primitives::{Collation, CollatorFn}; +use polkadot_primitives::v1::{CollatorId, CollatorPair, PoV}; use parity_scale_codec::{Encode, Decode}; use sp_core::Pair; +use std::{ + collections::HashMap, + sync::{Arc, Mutex}, + time::Duration, +}; +use test_parachain_adder::{execute, hash_state, BlockData, HeadData}; /// The amount we add when producing a new block. /// @@ -60,15 +64,19 @@ impl State { self.best_block = parent_head.number; let block = BlockData { - state: *self.head_to_state.get(&parent_head).expect("Getting state using parent head"), + state: *self + .head_to_state + .get(&parent_head) + .expect("Getting state using parent head"), add: ADD, }; - let new_head = execute(parent_head.hash(), parent_head, &block) - .expect("Produces valid block"); + let new_head = + execute(parent_head.hash(), parent_head, &block).expect("Produces valid block"); let new_head_arc = Arc::new(new_head.clone()); - self.head_to_state.insert(new_head_arc.clone(), block.state.wrapping_add(ADD)); + self.head_to_state + .insert(new_head_arc.clone(), block.state.wrapping_add(ADD)); self.number_to_head.insert(new_head.number, new_head_arc); (block, new_head) @@ -92,7 +100,13 @@ impl Collator { /// Get the SCALE encoded genesis head of the adder parachain. pub fn genesis_head(&self) -> Vec { - self.state.lock().unwrap().number_to_head.get(&0).expect("Genesis header exists").encode() + self.state + .lock() + .unwrap() + .number_to_head + .get(&0) + .expect("Genesis header exists") + .encode() } /// Get the validation code of the adder parachain. @@ -113,9 +127,7 @@ impl Collator { /// Create the collation function. /// /// This collation function can be plugged into the overseer to generate collations for the adder parachain. - pub fn create_collation_function( - &self, - ) -> CollatorFn { + pub fn create_collation_function(&self) -> CollatorFn { use futures::FutureExt as _; let state = self.state.clone(); @@ -137,7 +149,9 @@ impl Collator { horizontal_messages: Vec::new(), new_validation_code: None, head_data: head_data.encode().into(), - proof_of_validity: PoV { block_data: block_data.encode().into() }, + proof_of_validity: PoV { + block_data: block_data.encode().into(), + }, processed_downward_messages: 0, hrmp_watermark: validation_data.persisted.block_number, }; @@ -155,7 +169,7 @@ impl Collator { let current_block = self.state.lock().unwrap().best_block; if start_block + blocks <= current_block { - return + return; } } } @@ -167,8 +181,7 @@ mod tests { use futures::executor::block_on; use polkadot_parachain::{primitives::ValidationParams, wasm_executor::IsolationStrategy}; - use polkadot_primitives::v1::{ValidationData, PersistedValidationData}; - use parity_scale_codec::Decode; + use polkadot_primitives::v1::{PersistedValidationData, ValidationData}; #[test] fn collator_works() { @@ -176,7 +189,14 @@ mod tests { let collation_function = collator.create_collation_function(); for i in 0..5 { - let parent_head = collator.state.lock().unwrap().number_to_head.get(&i).unwrap().clone(); + let parent_head = collator + .state + .lock() + .unwrap() + .number_to_head + .get(&i) + .unwrap() + .clone(); let validation_data = ValidationData { persisted: PersistedValidationData { @@ -186,7 +206,8 @@ mod tests { ..Default::default() }; - let collation = block_on(collation_function(Default::default(), &validation_data)).unwrap(); + let collation = + block_on(collation_function(Default::default(), &validation_data)).unwrap(); validate_collation(&collator, (*parent_head).clone(), collation); } } @@ -203,9 +224,19 @@ mod tests { }, &IsolationStrategy::InProcess, sp_core::testing::TaskExecutor::new(), - ).unwrap(); + ) + .unwrap(); let new_head = HeadData::decode(&mut &ret.head_data.0[..]).unwrap(); - assert_eq!(**collator.state.lock().unwrap().number_to_head.get(&(parent_head.number + 1)).unwrap(), new_head); + assert_eq!( + **collator + .state + .lock() + .unwrap() + .number_to_head + .get(&(parent_head.number + 1)) + .unwrap(), + new_head + ); } } diff --git a/polkadot/parachain/test-parachains/adder/collator/src/main.rs b/polkadot/parachain/test-parachains/adder/collator/src/main.rs index 0bc93821a2..6b7029be07 100644 --- a/polkadot/parachain/test-parachains/adder/collator/src/main.rs +++ b/polkadot/parachain/test-parachains/adder/collator/src/main.rs @@ -16,71 +16,88 @@ //! Collator for the adder test parachain. -use sc_cli::{Result, Role, SubstrateCli}; -use polkadot_cli::Cli; -use polkadot_node_subsystem::messages::{CollatorProtocolMessage, CollationGenerationMessage}; use polkadot_node_primitives::CollationGenerationConfig; +use polkadot_node_subsystem::messages::{CollationGenerationMessage, CollatorProtocolMessage}; use polkadot_primitives::v1::Id as ParaId; -use test_parachain_adder_collator::Collator; +use sc_cli::{Result, Role, SubstrateCli}; use sp_core::hexdisplay::HexDisplay; use std::time::Duration; +use test_parachain_adder_collator::Collator; const PARA_ID: ParaId = ParaId::new(100); +mod cli; +use cli::Cli; + fn main() -> Result<()> { let cli = Cli::from_args(); - if cli.subcommand.is_some() { - return Err("Subcommands are not supported".into()) - } + match cli.subcommand { + Some(cli::Subcommand::ExportGenesisState(_params)) => { + let collator = Collator::new(); + println!("0x{:?}", HexDisplay::from(&collator.genesis_head())); - let runner = cli.create_runner(&cli.run.base)?; - - runner.run_node_until_exit(|config| async move { - let role = config.role.clone(); - - match role { - Role::Light => Err("Light client not supported".into()), - _ => { - let collator = Collator::new(); - - let full_node = polkadot_service::build_full( - config, - polkadot_service::IsCollator::Yes(collator.collator_id()), - None, - Some(sc_authority_discovery::WorkerConfig { - query_interval: Duration::from_secs(1), - query_start_delay: Duration::from_secs(0), - ..Default::default() - }), - )?; - let mut overseer_handler = full_node.overseer_handler - .expect("Overseer handler should be initialized for collators"); - - let genesis_head_hex = format!("0x{:?}", HexDisplay::from(&collator.genesis_head())); - let validation_code_hex = format!("0x{:?}", HexDisplay::from(&collator.validation_code())); - - log::info!("Running adder collator for parachain id: {}", PARA_ID); - log::info!("Genesis state: {}", genesis_head_hex); - log::info!("Validation code: {}", validation_code_hex); - - let config = CollationGenerationConfig { - key: collator.collator_key(), - collator: collator.create_collation_function(), - para_id: PARA_ID, - }; - overseer_handler - .send_msg(CollationGenerationMessage::Initialize(config)) - .await - .expect("Registers collator"); - - overseer_handler - .send_msg(CollatorProtocolMessage::CollateOn(PARA_ID)) - .await - .expect("Collates on"); - - Ok(full_node.task_manager) - }, + Ok(()) } - }) + Some(cli::Subcommand::ExportGenesisWasm(_params)) => { + let collator = Collator::new(); + println!("0x{:?}", HexDisplay::from(&collator.validation_code())); + + Ok(()) + } + None => { + let runner = cli.create_runner(&cli.run.base)?; + + runner.run_node_until_exit(|config| async move { + let role = config.role.clone(); + + match role { + Role::Light => Err("Light client not supported".into()), + _ => { + let collator = Collator::new(); + + let full_node = polkadot_service::build_full( + config, + polkadot_service::IsCollator::Yes(collator.collator_id()), + None, + Some(sc_authority_discovery::WorkerConfig { + query_interval: Duration::from_secs(1), + query_start_delay: Duration::from_secs(0), + ..Default::default() + }), + )?; + let mut overseer_handler = full_node + .overseer_handler + .expect("Overseer handler should be initialized for collators"); + + let genesis_head_hex = + format!("0x{:?}", HexDisplay::from(&collator.genesis_head())); + let validation_code_hex = + format!("0x{:?}", HexDisplay::from(&collator.validation_code())); + + log::info!("Running adder collator for parachain id: {}", PARA_ID); + log::info!("Genesis state: {}", genesis_head_hex); + log::info!("Validation code: {}", validation_code_hex); + + let config = CollationGenerationConfig { + key: collator.collator_key(), + collator: collator.create_collation_function(), + para_id: PARA_ID, + }; + overseer_handler + .send_msg(CollationGenerationMessage::Initialize(config)) + .await + .expect("Registers collator"); + + overseer_handler + .send_msg(CollatorProtocolMessage::CollateOn(PARA_ID)) + .await + .expect("Collates on"); + + Ok(full_node.task_manager) + } + } + }) + } + } } diff --git a/polkadot/scripts/adder-collator.sh b/polkadot/scripts/adder-collator.sh new file mode 100755 index 0000000000..ca493eb0a4 --- /dev/null +++ b/polkadot/scripts/adder-collator.sh @@ -0,0 +1,191 @@ +#!/usr/bin/env bash + +# Run a two node local net with adder-collator. + +set -e + +chainspec="rococo-local" + +# disabled until we can actually successfully register the chain with polkadot-js-api +# if ! command -v polkadot-js-api > /dev/null; then +# echo "polkadot-js-api required; try" +# echo " sudo yarn global add @polkadot/api-cli" +# exit 1 +# fi + +PROJECT_ROOT=$(git rev-parse --show-toplevel) +# shellcheck disable=SC1090 +source "$(dirname "$0")"/common.sh + +cd "$PROJECT_ROOT" + +last_modified_rust_file=$( + find . -path ./target -prune -o -type f -name '*.rs' -printf '%T@ %p\n' | + sort -nr | + head -1 | + cut -d' ' -f2- +) + +polkadot="target/release/polkadot" +adder_collator="target/release/adder-collator" + +# ensure the polkadot binary exists and is up to date +if [ ! -x "$polkadot" ] || [ "$polkadot" -ot "$last_modified_rust_file" ]; then + cargo build --release --features real-overseer +fi +# likewise for the adder collator +if [ ! -x "$adder_collator" ] || [ "$adder_collator" -ot "$last_modified_rust_file" ]; then + cargo build --release --features real-overseer -p test-parachain-adder-collator +fi + +genesis="$(mktemp --directory)" +genesis_state="$genesis/state" +validation_code="$genesis/validation_code" + +"$adder_collator" export-genesis-state > "$genesis_state" +"$adder_collator" export-genesis-wasm > "$validation_code" + + +# setup variables +node_offset=0 +declare -a node_pids +declare -a node_pipes + +# create a sed expression which injects the node name and stream type into each line +function make_sed_expr() { + name="$1" + type="$2" + + printf "s/^/%16s %s: /" "$name" "$type" +} + +# turn a string into a flag +function flagify() { + printf -- '--%s' "$(tr '[:upper:]' '[:lower:]' <<< "$1")" +} + +# start a node and label its output +# +# This function takes a single argument, the node name. +# The name must be one of those which can be passed to the polkadot binary, in un-flagged form, +# one of: +# alice, bob, charlie, dave, eve, ferdie, one, two +function run_node() { + name="$1" + # create a named pipe so we can get the node's PID while also sedding its output + local stdout + local stderr + stdout=$(mktemp --dry-run --tmpdir) + stderr=$(mktemp --dry-run --tmpdir) + mkfifo "$stdout" + mkfifo "$stderr" + node_pipes+=("$stdout") + node_pipes+=("$stderr") + + # compute ports from offset + local port=$((30333+node_offset)) + local rpc_port=$((9933+node_offset)) + local ws_port=$((9944+node_offset)) + local prometheus_port=$((9615+node_offset)) + node_offset=$((node_offset+1)) + + # start the node + "$polkadot" \ + --chain "$chainspec" \ + --tmp \ + --port "$port" \ + --rpc-port "$rpc_port" \ + --ws-port "$ws_port" \ + --prometheus-port "$prometheus_port" \ + --rpc-cors all \ + "$(flagify "$name")" \ + > "$stdout" \ + 2> "$stderr" \ + & + local pid=$! + node_pids+=("$pid") + + # send output from the stdout pipe to stdout, prepending the node name + sed -e "$(make_sed_expr "$name" "OUT")" "$stdout" >&1 & + # send output from the stderr pipe to stderr, prepending the node name + sed -e "$(make_sed_expr "$name" "ERR")" "$stderr" >&2 & +} + +# start an adder collator and label its output +# +# This function takes a single argument, the node name. This affects only the tagging. +function run_adder_collator() { + name="$1" + # create a named pipe so we can get the node's PID while also sedding its output + local stdout + local stderr + stdout=$(mktemp --dry-run --tmpdir) + stderr=$(mktemp --dry-run --tmpdir) + mkfifo "$stdout" + mkfifo "$stderr" + node_pipes+=("$stdout") + node_pipes+=("$stderr") + + # compute ports from offset + local port=$((30333+node_offset)) + local rpc_port=$((9933+node_offset)) + local ws_port=$((9944+node_offset)) + local prometheus_port=$((9615+node_offset)) + node_offset=$((node_offset+1)) + + # start the node + "$adder_collator" \ + --chain "$chainspec" \ + --tmp \ + --port "$port" \ + --rpc-port "$rpc_port" \ + --ws-port "$ws_port" \ + --prometheus-port "$prometheus_port" \ + --rpc-cors all \ + > "$stdout" \ + 2> "$stderr" \ + & + local pid=$! + node_pids+=("$pid") + + # send output from the stdout pipe to stdout, prepending the node name + sed -e "$(make_sed_expr "$name" "OUT")" "$stdout" >&1 & + # send output from the stderr pipe to stderr, prepending the node name + sed -e "$(make_sed_expr "$name" "ERR")" "$stderr" >&2 & +} + + +# clean up the nodes when this script exits +function finish { + for node_pid in "${node_pids[@]}"; do + kill -9 "$node_pid" + done + for node_pipe in "${node_pipes[@]}"; do + rm "$node_pipe" + done + rm -rf "$genesis" +} +trap finish EXIT + +# start the nodes +run_node Alice +run_node Bob +run_adder_collator AdderCollator + +# register the adder collator +# doesn't work yet due to https://github.com/polkadot-js/tools/issues/185 +# polkadot-js-api \ +# --ws ws://localhost:9944 \ +# --sudo \ +# --seed "//Alice" \ +# tx.registrar.registerPara \ +# 100 \ +# '{"scheduling":"Always"}' \ +# "@$validation_code" \ +# "@$genesis_state" + +# now wait; this will exit on its own only if both subprocesses exit +# the practical implication, as both subprocesses are supposed to run forever, is that +# this script will also run forever, until killed, at which point the exit trap should kill +# the subprocesses +wait diff --git a/polkadot/scripts/two-node-local-net.sh b/polkadot/scripts/two-node-local-net.sh index 4e3291b015..16db4304f1 100755 --- a/polkadot/scripts/two-node-local-net.sh +++ b/polkadot/scripts/two-node-local-net.sh @@ -27,7 +27,7 @@ polkadot="target/release/polkadot" # ensure the polkadot binary exists and is up to date if [ ! -x "$polkadot" ] || [ "$polkadot" -ot "$last_modified_rust_file" ]; then - cargo build --release + cargo build --release --features real-overseer fi # setup variables