From 1dccdf1af4260b247d9885bab7a94839c481d849 Mon Sep 17 00:00:00 2001
From: Eval EXEC <execvy@gmail.com>
Date: Thu, 2 Nov 2023 18:49:26 +0800
Subject: [PATCH] Add trace timecost log for ChainService

Signed-off-by: Eval EXEC <execvy@gmail.com>
---
 chain/src/chain.rs                            | 48 +++++++++++++++++--
 .../src/contextual_block_verifier.rs          |  4 ++
 2 files changed, 47 insertions(+), 5 deletions(-)

diff --git a/chain/src/chain.rs b/chain/src/chain.rs
index 3297d76f67f..0cca4575d5a 100644
--- a/chain/src/chain.rs
+++ b/chain/src/chain.rs
@@ -33,8 +33,9 @@ use ckb_verification::{BlockVerifier, InvalidParentError, NonContextualBlockTxsV
 use ckb_verification_contextual::{ContextualBlockVerifier, VerifyContext};
 use ckb_verification_traits::{Switch, Verifier};
 use std::collections::{HashSet, VecDeque};
+use std::ops::AddAssign;
 use std::sync::Arc;
-use std::{cmp, thread};
+use std::{cmp, thread, time::Duration};
 
 type ProcessBlockRequest = Request<(Arc<BlockView>, Switch), Result<bool, Error>>;
 type TruncateRequest = Request<Byte32, Result<(), Error>>;
@@ -196,12 +197,24 @@ impl GlobalIndex {
     }
 }
 
+#[derive(Default, Debug)]
+struct TimeCost {
+    wait_process_block: Duration,
+    process_block: Duration,
+
+    db_commit: Duration,
+    resolve_block_transactions: Duration,
+    contextual_block_verifier: Duration,
+    verify_script: Duration,
+}
+
 /// Chain background service
 ///
 /// The ChainService provides a single-threaded background executor.
 pub struct ChainService {
     shared: Shared,
     proposal_table: ProposalTable,
+    time_cost: TimeCost,
 }
 
 impl ChainService {
@@ -210,6 +223,7 @@ impl ChainService {
         ChainService {
             shared,
             proposal_table,
+            time_cost: TimeCost::default(),
         }
     }
 
@@ -228,6 +242,7 @@ impl ChainService {
 
         let thread = thread_builder
             .spawn(move || loop {
+                let trace_start = std::time::Instant::now();
                 select! {
                     recv(signal_receiver) -> _ => {
                         break;
@@ -235,7 +250,9 @@ impl ChainService {
                     recv(process_block_receiver) -> msg => match msg {
                         Ok(Request { responder, arguments: (block, verify) }) => {
                             let _ = tx_control.suspend_chunk_process();
+                            self.time_cost.wait_process_block.add_assign(trace_start.elapsed());
                             let _ = responder.send(self.process_block(block, verify));
+                            self.time_cost.process_block.add_assign(trace_start.elapsed());
                             let _ = tx_control.continue_chunk_process();
                         },
                         _ => {
@@ -347,10 +364,16 @@ impl ChainService {
             warn!("receive 0 number block: 0-{}", block_hash);
         }
 
-        self.insert_block(block, switch).map(|ret| {
+        let result = self.insert_block(block, switch).map(|ret| {
             debug!("finish processing block");
             ret
-        })
+        });
+
+        if block_number % 100_000 == 0 {
+            info!("block:{}, time_cost {:?}", block_number, self.time_cost);
+        }
+
+        result
     }
 
     fn non_contextual_verify(&self, block: &BlockView) -> Result<(), Error> {
@@ -373,6 +396,7 @@ impl ChainService {
     }
 
     fn insert_block(&mut self, block: Arc<BlockView>, switch: Switch) -> Result<bool, Error> {
+        let start_time = std::time::Instant::now();
         let db_txn = Arc::new(self.shared.store().begin_transaction());
         let txn_snapshot = db_txn.get_snapshot();
         let _snapshot_tip_hash = db_txn.get_update_for_tip_hash(&txn_snapshot);
@@ -472,6 +496,8 @@ impl ChainService {
         }
         db_txn.commit()?;
 
+        self.time_cost.db_commit.add_assign(start_time.elapsed());
+
         if new_best_block {
             let tip_header = block.header();
             info!(
@@ -719,7 +745,7 @@ impl ChainService {
 
     // we found new best_block
     pub(crate) fn reconcile_main_chain(
-        &self,
+        &mut self,
         txn: Arc<StoreTransaction>,
         fork: &mut ForkChanges,
         switch: Switch,
@@ -753,9 +779,13 @@ impl ChainService {
             .iter()
             .zip(fork.attached_blocks.iter().skip(verified_len))
         {
+            let start_time = std::time::Instant::now();
             if !switch.disable_all() {
                 if found_error.is_none() {
                     let resolved = self.resolve_block_transactions(&txn, b, &verify_context);
+                    self.time_cost
+                        .resolve_block_transactions
+                        .add_assign(start_time.elapsed());
                     match resolved {
                         Ok(resolved) => {
                             let verified = {
@@ -766,7 +796,15 @@ impl ChainService {
                                     Arc::clone(&txs_verify_cache),
                                     &mmr,
                                 );
-                                contextual_block_verifier.verify(&resolved, b)
+                                let result = contextual_block_verifier.verify(
+                                    &resolved,
+                                    b,
+                                    &mut self.time_cost.verify_script,
+                                );
+                                self.time_cost
+                                    .contextual_block_verifier
+                                    .add_assign(start_time.elapsed());
+                                result
                             };
                             match verified {
                                 Ok((cycles, cache_entries)) => {
diff --git a/verification/contextual/src/contextual_block_verifier.rs b/verification/contextual/src/contextual_block_verifier.rs
index 739ac67f0ea..d8b8ebd3f16 100644
--- a/verification/contextual/src/contextual_block_verifier.rs
+++ b/verification/contextual/src/contextual_block_verifier.rs
@@ -33,6 +33,7 @@ use ckb_verification::{BlockTransactionsError, EpochError, TxVerifyEnv};
 use ckb_verification_traits::Switch;
 use rayon::iter::{IndexedParallelIterator, IntoParallelRefIterator, ParallelIterator};
 use std::collections::{HashMap, HashSet};
+use std::ops::AddAssign;
 use std::sync::Arc;
 use tokio::sync::{oneshot, RwLock};
 
@@ -644,6 +645,7 @@ impl<'a, CS: ChainStore + VersionbitsIndexer + 'static, MS: MMRStore<HeaderDiges
         &'a self,
         resolved: &'a [Arc<ResolvedTransaction>],
         block: &'a BlockView,
+        verify_script_cost: &mut std::time::Duration,
     ) -> Result<(Cycle, Vec<Completed>), Error> {
         let parent_hash = block.data().header().raw().parent_hash();
         let header = block.header();
@@ -690,6 +692,7 @@ impl<'a, CS: ChainStore + VersionbitsIndexer + 'static, MS: MMRStore<HeaderDiges
 
         BlockExtensionVerifier::new(&self.context, self.chain_root_mmr, &parent).verify(block)?;
 
+        let start_time = std::time::Instant::now();
         let ret = BlockTxsVerifier::new(
             self.context.clone(),
             header,
@@ -697,6 +700,7 @@ impl<'a, CS: ChainStore + VersionbitsIndexer + 'static, MS: MMRStore<HeaderDiges
             &self.txs_verify_cache,
         )
         .verify(resolved, self.switch.disable_script())?;
+        verify_script_cost.add_assign(start_time.elapsed());
         Ok(ret)
     }
 }