Merge pull request #2227 from subspace/downgrade-domain-logs

Downgrade annoying domain logs and add slow log for domain block derivation

crates/pallet-domains/src/lib.rs

@@ -1331,6 +1331,7 @@ mod pallet {
                             BundleError::Receipt(BlockTreeError::InFutureReceipt)
                             | BundleError::Receipt(BlockTreeError::StaleReceipt)
                             | BundleError::Receipt(BlockTreeError::NewBranchReceipt)
+                            | BundleError::Receipt(BlockTreeError::UnavailableConsensusBlockHash)
                             | BundleError::Receipt(BlockTreeError::BuiltOnUnknownConsensusBlock) => {
                                 log::debug!(
                                     target: "runtime::domains",

domains/client/domain-operator/src/bundle_processor.rs

@@ -19,7 +19,22 @@ use sp_keystore::KeystorePtr;
 use sp_messenger::MessengerApi;
 use sp_runtime::traits::{Block as BlockT, Zero};
 use sp_runtime::{Digest, DigestItem};
+use sp_weights::constants::WEIGHT_REF_TIME_PER_MILLIS;
 use std::sync::Arc;
+use std::time::Instant;
+
+// The slow log threshold for consensus block preprocessing
+const SLOW_PREPROCESS_MILLIS: u64 = 500;
+
+// The slow log threshold for domain block execution: `reference_duration_ms * 1.2 + 200ms`,
+// where `reference_duration_ms * 0.2` as buffer of the slow extrinsic execution (i.e. slower
+// machine than the reference machine) and 200ms as buffer of the rest of the processing.
+fn slow_domain_block_execution_threshold(reference_duration_ms: u64) -> u64 {
+    reference_duration_ms + (reference_duration_ms / 5) + 200
+}
+
+// The slow log threshold for post domain block execution
+const SLOW_POST_DOMAIN_BLOCK_EXECUTION_MILLIS: u64 = 250;
 
 type DomainReceiptsChecker<Block, CBlock, Client, CClient, Backend, E> =
     ReceiptsChecker<Block, Client, CBlock, CClient, Backend, E>;
@@ -247,6 +262,7 @@ where
     ) -> sp_blockchain::Result<Option<(Block::Hash, NumberFor<Block>)>> {
         let (consensus_block_hash, consensus_block_number) = consensus_block_info;
         let (parent_hash, parent_number) = parent_info;
+        let start = Instant::now();
 
         tracing::debug!(
             "Building a new domain block from consensus block #{consensus_block_number},{consensus_block_hash} \
@@ -258,10 +274,19 @@ where
             .runtime_api()
             .head_receipt_number(consensus_block_hash, self.domain_id)?;
 
-        let Some(preprocess_result) = self
+        let maybe_preprocess_result = self
             .domain_block_preprocessor
-            .preprocess_consensus_block(consensus_block_hash, parent_hash)?
-        else {
+            .preprocess_consensus_block(consensus_block_hash, parent_hash)?;
+
+        let preprocess_took = start.elapsed().as_millis();
+        if preprocess_took >= SLOW_PREPROCESS_MILLIS.into() {
+            tracing::warn!(
+                ?consensus_block_info,
+                "Slow consensus block preprocessing, took {preprocess_took}ms"
+            );
+        }
+
+        let Some(preprocess_result) = maybe_preprocess_result else {
             tracing::debug!(
                 "Skip building new domain block, no bundles and runtime upgrade for this domain \
                     in consensus block #{consensus_block_number:?},{consensus_block_hash}"
@@ -300,6 +325,36 @@ where
             domain_block_result.header_number,
         );
 
+        let block_execution_took = start.elapsed().as_millis().saturating_sub(preprocess_took);
+        let domain_core_api_version = self
+            .client
+            .runtime_api()
+            .api_version::<dyn DomainCoreApi<Block>>(domain_block_result.header_hash)?
+            // safe to return default version as 1 since there will always be version 1.
+            .unwrap_or(1);
+        let reference_block_execution_duration_ms = if domain_core_api_version >= 2 {
+            self.client
+                .runtime_api()
+                .block_weight(domain_block_result.header_hash)?
+                .ref_time()
+                / WEIGHT_REF_TIME_PER_MILLIS
+        } else {
+            // TODO: this is used to keep compatible with the gemini-3g network, remove this
+            // before the next network
+            // 2000ms is the maximum compute time set in the max domain block weight
+            2000
+        };
+        if block_execution_took
+            >= slow_domain_block_execution_threshold(reference_block_execution_duration_ms).into()
+        {
+            tracing::warn!(
+                ?consensus_block_info,
+                ?built_block_info,
+                ?reference_block_execution_duration_ms,
+                "Slow domain block execution, took {block_execution_took}ms"
+            );
+        }
+
         self.domain_block_processor.on_consensus_block_processed(
             consensus_block_hash,
             Some(domain_block_result),
@@ -326,6 +381,18 @@ where
                 .await?;
         }
 
+        let post_block_execution_took = start
+            .elapsed()
+            .as_millis()
+            .saturating_sub(preprocess_took + block_execution_took);
+        if post_block_execution_took >= SLOW_POST_DOMAIN_BLOCK_EXECUTION_MILLIS.into() {
+            tracing::warn!(
+                ?consensus_block_info,
+                ?built_block_info,
+                "Slow post domain block execution, took {post_block_execution_took}ms"
+            );
+        }
+
         Ok(Some(built_block_info))
     }
 }

domains/client/domain-operator/src/domain_block_processor.rs

@@ -62,6 +62,7 @@ where
     pub(crate) domain_confirmation_depth: NumberFor<Block>,
     pub(crate) block_import: SharedBlockImport<Block>,
     pub(crate) import_notification_sinks: DomainImportNotificationSinks<Block, CBlock>,
+    pub(crate) consensus_network_sync_oracle: Arc<dyn SyncOracle + Send + Sync>,
 }
 
 impl<Block, CBlock, Client, CClient, Backend> Clone
@@ -80,6 +81,7 @@ where
             domain_confirmation_depth: self.domain_confirmation_depth,
             block_import: self.block_import.clone(),
             import_notification_sinks: self.import_notification_sinks.clone(),
+            consensus_network_sync_oracle: self.consensus_network_sync_oracle.clone(),
         }
     }
 }
@@ -436,7 +438,14 @@ where
         let header_number = *header.number();
 
         let block_import_params = {
-            let mut import_block = BlockImportParams::new(BlockOrigin::Own, header);
+            let block_origin = if self.consensus_network_sync_oracle.is_major_syncing() {
+                // The domain block is derived from the consensus block, if the consensus chain is
+                // in major sync then we should also consider the domain block is `NetworkInitialSync`
+                BlockOrigin::NetworkInitialSync
+            } else {
+                BlockOrigin::Own
+            };
+            let mut import_block = BlockImportParams::new(block_origin, header);
             import_block.body = Some(body);
             import_block.state_action =
                 StateAction::ApplyChanges(StorageChanges::Changes(storage_changes));

domains/client/domain-operator/src/operator.rs

@@ -150,6 +150,7 @@ where
             domain_confirmation_depth: params.domain_confirmation_depth,
             block_import: params.block_import,
             import_notification_sinks: Default::default(),
+            consensus_network_sync_oracle: params.consensus_network_sync_oracle.clone(),
         };
 
         let receipts_checker = ReceiptsChecker {

domains/client/domain-operator/src/tests.rs

@@ -296,6 +296,7 @@ async fn test_processing_empty_consensus_block() {
         domain_confirmation_depth: 256u32,
         block_import: SharedBlockImport::new(alice.client.clone()),
         import_notification_sinks: Default::default(),
+        consensus_network_sync_oracle: ferdie.sync_service.clone(),
     };
 
     let domain_genesis_hash = alice.client.info().best_hash;

domains/client/relayer/src/worker.rs

@@ -158,14 +158,14 @@ where
     while let Some(block) = chain_block_import.next().await {
         // if the client is in major sync, wait until sync is complete
         if sync_oracle.is_major_syncing() {
-            tracing::info!(target: LOG_TARGET, "Client is in major sync. Skipping...");
+            tracing::debug!(target: LOG_TARGET, "Client is in major sync. Skipping...");
             continue;
         }
 
         let relay_block_until = match block.header.number().checked_sub(&relay_confirmation_depth) {
             None => {
                 // not enough confirmed blocks.
-                tracing::info!(
+                tracing::debug!(
                     target: LOG_TARGET,
                     "Not enough confirmed blocks for domain: {:?}. Skipping...",
                     chain_id
@@ -183,7 +183,7 @@ where
                 .collect();
 
         for (number, hash) in blocks_to_process {
-            tracing::info!(
+            tracing::debug!(
                 target: LOG_TARGET,
                 "Checking messages to be submitted from chain: {chain_id:?} at block: ({number:?}, {hash:?})",
             );
@@ -193,23 +193,23 @@ where
             // mark this block processed and continue to next one.
             if !can_relay_message_from_block(chain_id, number)? {
                 Relayer::store_relayed_block(&client, chain_id, number, hash)?;
-                tracing::info!(
+                tracing::debug!(
                     target: LOG_TARGET,
                     "Chain({chain_id:?}) messages in the Block ({number:?}, {hash:?}) cannot be relayed. Skipping...",
                 );
             } else {
                 match message_processor(&client, hash) {
                     Ok(_) => {
                         Relayer::store_relayed_block(&client, chain_id, number, hash)?;
-                        tracing::info!(
+                        tracing::debug!(
                             target: LOG_TARGET,
                             "Messages from {chain_id:?} at block({number:?}, {hash:?}) are processed."
                         )
                     }
                     Err(err) => {
                         match err {
                             Error::DomainNonConfirmedOnConsensusChain => {
-                                tracing::info!(
+                                tracing::debug!(
                                     target: LOG_TARGET,
                                     "Waiting for Domain[{chain_id:?}] block({number:?}, {hash:?}) to be confirmed on Consensus chain."
                                 )

domains/pallets/executive/src/lib.rs

@@ -435,7 +435,7 @@ where
             COnRuntimeUpgrade,
         >::apply_extrinsic(uxt);
         // TODO: Critical!!! https://github.com/paritytech/substrate/pull/10922#issuecomment-1068997467
-        log::info!(
+        log::debug!(
             target: "domain::runtime::executive",
             "[apply_extrinsic] after: {:?}",
             {

domains/primitives/runtime/src/lib.rs

@@ -222,5 +222,9 @@ sp_api::decl_runtime_apis! {
 
         /// Return the block digest
         fn block_digest() -> Digest;
+
+        /// Return the consumed weight of the block
+        #[api_version(2)]
+        fn block_weight() -> Weight;
     }
 }

domains/runtime/evm/src/lib.rs

@@ -843,6 +843,7 @@ impl_runtime_apis! {
         }
     }
 
+    #[api_version(2)]
     impl domain_runtime_primitives::DomainCoreApi<Block> for Runtime {
         fn extract_signer(
             extrinsics: Vec<<Block as BlockT>::Extrinsic>,
@@ -963,6 +964,10 @@ impl_runtime_apis! {
         fn block_digest() -> Digest {
             System::digest()
         }
+
+        fn block_weight() -> Weight {
+            System::block_weight().total()
+        }
     }
 
     impl sp_messenger::MessengerApi<Block, BlockNumber> for Runtime {

domains/test/runtime/evm/src/lib.rs

@@ -833,6 +833,7 @@ impl_runtime_apis! {
         }
     }
 
+    #[api_version(2)]
     impl domain_runtime_primitives::DomainCoreApi<Block> for Runtime {
         fn extract_signer(
             extrinsics: Vec<<Block as BlockT>::Extrinsic>,
@@ -951,6 +952,10 @@ impl_runtime_apis! {
         fn block_digest() -> Digest {
             System::digest()
         }
+
+        fn block_weight() -> Weight {
+            System::block_weight().total()
+        }
     }
 
     impl sp_messenger::MessengerApi<Block, BlockNumber> for Runtime {