feat(drive-abci): debug-only per-block phase timing

packages/rs-drive-abci/src/abci/handler/finalize_block.rs

@@ -18,6 +18,8 @@ where
     C: CoreRPCLike,
 {
     let _timer = crate::metrics::abci_request_duration("finalize_block");
+    #[cfg(debug_assertions)]
+    let mut laps = crate::perf::Laps::new();
 
     let transaction_guard = app.transaction().read().unwrap();
     let transaction =
@@ -45,13 +47,19 @@ where
 
     let block_height = request_finalize_block.height;
 
+    #[cfg(debug_assertions)]
+    laps.lap("fb_setup");
+
     let block_finalization_outcome = app.platform().finalize_block_proposal(
         request_finalize_block,
         block_execution_context,
         transaction,
         platform_version,
     )?;
 
+    #[cfg(debug_assertions)]
+    laps.lap("fb_proposal");
+
     drop(transaction_guard);
 
     //FIXME: tell tenderdash about the problem instead
@@ -69,6 +77,9 @@ where
 
     let result = app.commit_transaction(platform_version);
 
+    #[cfg(debug_assertions)]
+    laps.lap("fb_commit");
+
     // We had a sequence of errors on the mainnet started since block 32326.
     // We got RocksDB's "transaction is busy" error because of a bug (https://github.com/dashpay/platform/pull/2309).
     // Due to another bug in Tenderdash (https://github.com/dashpay/tenderdash/pull/966),
@@ -92,6 +103,9 @@ where
         result.expect("commit transaction");
     }
 
+    #[cfg(debug_assertions)]
+    laps.lap("fb_commit_check");
+
     app.platform()
         .committed_block_height_guard
         .store(block_height, Ordering::Relaxed);
@@ -101,6 +115,16 @@ where
         app.platform().create_grovedb_checkpoint(platform_version)?;
     }
 
+    #[cfg(debug_assertions)]
+    laps.lap_if(
+        block_finalization_outcome.checkpoint_needed,
+        "fb_checkpoint",
+    );
+    #[cfg(debug_assertions)]
+    drop(laps);
+    #[cfg(debug_assertions)]
+    crate::perf::end_block(block_height);
+
     Ok(proto::ResponseFinalizeBlock { retain_height: 0 })
 }
 

packages/rs-drive-abci/src/execution/engine/finalize_block_proposal/v0/mod.rs

@@ -63,6 +63,9 @@ where
         transaction: &Transaction,
         platform_version: &PlatformVersion,
     ) -> Result<block_execution_outcome::v0::BlockFinalizationOutcome, Error> {
+        #[cfg(debug_assertions)]
+        let mut laps = crate::perf::Laps::new();
+
         let mut validation_result = SimpleValidationResult::<AbciError>::new_with_errors(vec![]);
 
         let block_state_info = block_execution_context.block_state_info();
@@ -94,6 +97,9 @@ where
             .try_into()
             .expect("invalid sha256 length");
 
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_msg_hash");
+
         //// Verification that commit is for our current executed block
         // When receiving the finalized block, we need to make sure info matches our current block
 
@@ -136,6 +142,9 @@ where
             return Ok(validation_result.into());
         }
 
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_basic_checks");
+
         // Verify votes extensions
         // We don't need to verify votes extension signatures once again after tenderdash
         // here, because we will do it bellow broadcasting withdrawal transactions.
@@ -154,6 +163,9 @@ where
             return Ok(validation_result.into());
         };
 
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_vote_ext");
+
         // Verify commit
 
         // In production this will always be true
@@ -188,6 +200,9 @@ where
             }
         }
 
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_verify_commit");
+
         if height == self.config.abci.genesis_height {
             self.drive
                 .set_genesis_time(block_state_info.block_time_ms());
@@ -205,13 +220,20 @@ where
 
         to_commit_block_info.core_height = block_header.core_chain_locked_height;
 
-        if !transaction_to_extension_matches.is_empty() {
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_block_info");
+
+        let broadcast_withdrawals = !transaction_to_extension_matches.is_empty();
+        if broadcast_withdrawals {
             self.append_signatures_and_broadcast_withdrawal_transactions(
                 transaction_to_extension_matches,
                 platform_version,
             )?;
         }
 
+        #[cfg(debug_assertions)]
+        laps.lap_if(broadcast_withdrawals, "fbp_wd_broadcast");
+
         // Update platform (drive abci) state
 
         let extended_block_info = ExtendedBlockInfoV0 {
@@ -225,12 +247,21 @@ where
         }
         .into();
 
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_ext_block_info");
+
         self.update_drive_cache(&block_execution_context, platform_version)?;
 
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_drive_cache");
+
         // Check if we should create a checkpoint (must be done before consuming block_execution_context)
         let checkpoint_needed =
             self.should_checkpoint(&block_execution_context, platform_version)?;
 
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_should_checkpoint");
+
         let block_platform_state = block_execution_context.block_platform_state_owned();
 
         self.update_state_cache(
@@ -240,6 +271,9 @@ where
             platform_version,
         )?;
 
+        #[cfg(debug_assertions)]
+        laps.lap("fbp_state_cache");
+
         // Gather some metrics
         crate::metrics::abci_last_block_time(block_header.time.seconds as u64);
         crate::metrics::abci_last_platform_height(height);

packages/rs-drive-abci/src/execution/engine/run_block_proposal/mod.rs

@@ -53,6 +53,9 @@ where
         timer: Option<&HistogramTiming>,
     ) -> Result<ValidationResult<block_execution_outcome::v0::BlockExecutionOutcome, Error>, Error>
     {
+        #[cfg(debug_assertions)]
+        let mut laps = crate::perf::Laps::new();
+
         // Epoch information is always calculated with the last committed platform version
         // even if we are switching to a new version in this block.
         let last_committed_platform_version = platform_state.current_platform_version()?;
@@ -66,6 +69,9 @@ where
             last_committed_platform_version,
         )?;
 
+        #[cfg(debug_assertions)]
+        laps.lap("epoch_info");
+
         // Cleanup block cache before we execute a new proposal.
         //
         // This has to happen before `perform_events_on_first_block_of_protocol_change` below:
@@ -74,9 +80,15 @@ where
         // them, leaving those reads to fall back to pre-change global cache entries.
         self.clear_drive_block_cache(last_committed_platform_version)?;
 
+        #[cfg(debug_assertions)]
+        laps.lap("clear_block_cache");
+
         // Create a bock state from previous committed state
         let mut block_platform_state = platform_state.clone();
 
+        #[cfg(debug_assertions)]
+        laps.lap("state_clone");
+
         // Determine a platform version for this block
         let block_platform_version = if epoch_info.is_epoch_change_but_not_genesis()
             && platform_state.next_epoch_protocol_version()