Fix: Improve the withdrawal packaging performance

crates/block-producer/src/block_producer.rs

@@ -254,6 +254,7 @@ impl BlockProducer {
         // try issue next block
         let mut retry_count = 0;
         while retry_count <= MAX_BLOCK_OUTPUT_PARAM_RETRY_COUNT {
+            let t = Instant::now();
             let (block_number, tx, next_global_state) = match self
                 .compose_next_block_submit_tx(rollup_input_since, rollup_cell.clone(), retry_count)
                 .await
@@ -262,20 +263,23 @@ impl BlockProducer {
                 Err(err) if err.downcast_ref::<GreaterBlockTimestampError>().is_some() => {
                     // Wait next l1 tip block median time
                     log::debug!(
-                        "[produce block] block timestamp is greater than rollup input since, wait next median time"
+                        target: "produce-block",
+                        "block timestamp is greater than rollup input since, wait next median time"
                     );
                     return Ok(());
                 }
                 Err(err) => {
                     retry_count += 1;
                     log::warn!(
-                        "[produce block] retry compose next block submit tx, retry: {}, reason: {}",
+                        target: "produce-block",
+                        "retry compose next block submit tx, retry: {}, reason: {}",
                         retry_count,
                         err
                     );
                     continue;
                 }
             };
+            log::debug!(target: "produce-block", "Produce l2block #{} ({}ms)", block_number, t.elapsed().as_millis());
 
             let expected_next_block_number = global_state.block().count().unpack();
             if expected_next_block_number != block_number {
@@ -287,8 +291,11 @@ impl BlockProducer {
             }
 
             let submitted_tx_hash = tx.hash();
+            let t = Instant::now();
             match self.submit_block_tx(block_number, tx).await {
                 Ok(SubmitResult::Submitted) => {
+                    log::debug!(target: "produce-block", "Submitted l2block #{} in {} ({}ms)",
+                        block_number, hex::encode(&submitted_tx_hash), t.elapsed().as_millis());
                     self.last_committed_l2_block = LastCommittedL2Block {
                         committed_tip_block_hash: l2_tip_block_hash,
                         committed_at: Instant::now(),
@@ -300,7 +307,8 @@ impl BlockProducer {
                 Err(err) => {
                     retry_count += 1;
                     log::warn!(
-                        "[produce block] retry submit block tx , retry: {}, reason: {}",
+                        target: "produce-block",
+                        "retry submit block tx , retry: {}, reason: {}",
                         retry_count,
                         err
                     );
@@ -335,13 +343,19 @@ impl BlockProducer {
         let (opt_finalized_custodians, block_param) = {
             let (mem_block, post_block_state) = {
                 let t = Instant::now();
-                log::debug!("[compose_next_block_submit_tx] acquire mem-pool",);
+                log::debug!(target: "produce-block", "acquire mem-pool",);
                 let mem_pool = self.mem_pool.lock().await;
                 log::debug!(
-                    "[compose_next_block_submit_tx] unlock mem-pool {}ms",
+                    target: "produce-block", "unlock mem-pool {}ms",
+                    t.elapsed().as_millis()
+                );
+                let t = Instant::now();
+                let r = mem_pool.output_mem_block(&OutputParam::new(retry_count));
+                log::debug!(
+                    target: "produce-block", "output mem block {}ms",
                     t.elapsed().as_millis()
                 );
-                mem_pool.output_mem_block(&OutputParam::new(retry_count))
+                r
             };
 
             let t = Instant::now();
@@ -363,12 +377,14 @@ impl BlockProducer {
                 query.await?.expect_any()
             };
             log::debug!(
+                target: "produce-block",
                 "finalized custodians {:?}",
                 finalized_custodians.cells_info.len()
             );
 
             log::debug!(
-                "[compose_next_block_submit_tx] generate produce block param {}ms",
+                target: "produce-block",
+                "generate produce block param {}ms",
                 t.elapsed().as_millis()
             );
             (Some(finalized_custodians), produce_block_param)
@@ -389,7 +405,13 @@ impl BlockProducer {
             block_param,
         };
         let db = self.store.begin_transaction();
+        let t = Instant::now();
         let block_result = produce_block(&db, &self.generator, param)?;
+        log::debug!(
+            target: "produce-block",
+            "produce block {}ms",
+            t.elapsed().as_millis()
+        );
         let ProduceBlockResult {
             mut block,
             mut global_state,
@@ -416,6 +438,7 @@ impl BlockProducer {
         let block_txs = block.transactions().len();
         let block_withdrawals = block.withdrawals().len();
         log::info!(
+            target: "produce-block",
             "produce new block #{} (txs: {}, deposits: {}, withdrawals: {})",
             number,
             block_txs,
@@ -453,14 +476,16 @@ impl BlockProducer {
             Ok(tx) => tx,
             Err(err) => {
                 log::error!(
-                    "[produce_next_block] Failed to composite submitting transaction: {}",
+                    target: "produce-block",
+                    "Failed to composite submitting transaction: {}",
                     err
                 );
                 return Err(err);
             }
         };
         log::debug!(
-            "[compose_next_block_submit_tx] complete tx skeleton {}ms",
+            target: "produce-block",
+            "complete tx skeleton {}ms",
             t.elapsed().as_millis()
         );
         if tx.as_slice().len() <= MAX_BLOCK_BYTES as usize
@@ -494,6 +519,7 @@ impl BlockProducer {
         let cycles = match self.rpc_client.dry_run_transaction(&tx).await {
             Ok(cycles) => {
                 log::info!(
+                    target: "produce-block",
                     "Tx({}) L2 block #{} execution cycles: {}",
                     block_number,
                     hex::encode(tx.hash()),
@@ -510,7 +536,10 @@ impl BlockProducer {
                         log::error!("[contracts dep] refresh failed {}", err);
                     }
 
-                    log::info!("Skip submitting l2 block since CKB can't resolve tx, previous block may haven't been processed by CKB");
+                    log::info!(
+                        target: "produce-block",
+                        "Skip submitting l2 block since CKB can't resolve tx, previous block may haven't been processed by CKB"
+                    );
                     return Ok(SubmitResult::Skip);
                 } else {
                     if err_str.contains(TRANSACTION_SCRIPT_ERROR)
@@ -533,12 +562,14 @@ impl BlockProducer {
             }
         };
         log::debug!(
-            "[compose_next_block_submit_tx] dry run {}ms",
+            target: "produce-block",
+            "dry run {}ms",
             t.elapsed().as_millis()
         );
 
         if cycles > self.debug_config.expected_l1_tx_upper_bound_cycles {
             log::warn!(
+                target: "produce-block",
                 "Submitting l2 block is cost unexpected cycles: {:?}, expected upper bound: {}",
                 cycles,
                 self.debug_config.expected_l1_tx_upper_bound_cycles
@@ -555,14 +586,15 @@ impl BlockProducer {
         match self.rpc_client.send_transaction(&tx).await {
             Ok(tx_hash) => {
                 log::info!(
+                    target: "produce-block",
                     "Submitted l2 block {} in tx {}",
                     block_number,
                     hex::encode(tx_hash.as_slice())
                 );
                 Ok(SubmitResult::Submitted)
             }
             Err(err) => {
-                log::error!("Submitting l2 block error: {}", err);
+                log::error!(target: "produce-block", "Submitting l2 block error: {}", err);
 
                 // dumping script error transactions
                 let err_str = err.to_string();
@@ -586,6 +618,7 @@ impl BlockProducer {
                         .as_secs();
                     if since_last_committed_secs < WAIT_PRODUCE_BLOCK_SECONDS {
                         log::debug!(
+                            target: "produce-block",
                             "last committed is {}s ago, dump tx",
                             since_last_committed_secs
                         );

crates/chain/src/chain.rs

@@ -259,12 +259,12 @@ impl Chain {
                 log::debug!("[complete_initial_syncing] acquire mem-pool",);
                 let t = Instant::now();
                 let mut mem_pool = mem_pool.lock().await;
-                mem_pool.notify_new_tip(tip_block_hash).await?;
-                mem_pool.mem_pool_state().set_completed_initial_syncing();
                 log::debug!(
                     "[complete_initial_syncing] unlock mem-pool {}ms",
                     t.elapsed().as_millis()
                 );
+                mem_pool.notify_new_tip(tip_block_hash).await?;
+                mem_pool.mem_pool_state().set_completed_initial_syncing();
             }
         }
         self.complete_initial_syncing = true;
@@ -825,27 +825,32 @@ impl Chain {
         }
 
         // update layer1 actions
-        for action in param.updates {
+        log::debug!(target: "sync-block", "sync {} actions", param.updates.len());
+        for (i, action) in param.updates.into_iter().enumerate() {
+            let t = Instant::now();
             self.update_l1action(&db, action)?;
+            log::debug!(target: "sync-block", "process {}th action cost {}ms", i, t.elapsed().as_millis());
             match self.last_sync_event() {
                 SyncEvent::Success => (),
                 _ => db.commit()?,
             }
         }
 
         db.commit()?;
-        log::debug!("commit db after sync");
 
         let tip_block_hash: H256 = self.local_state.tip.hash().into();
         if let Some(mem_pool) = &self.mem_pool {
             if matches!(self.last_sync_event, SyncEvent::Success)
                 && (is_revert_happend || self.complete_initial_syncing)
             {
                 // update mem pool state
-                log::debug!("[sync] acquire mem-pool",);
+                log::debug!(target: "sync-block", "acquire mem-pool",);
                 let t = Instant::now();
-                mem_pool.lock().await.notify_new_tip(tip_block_hash).await?;
-                log::debug!("[sync] unlock mem-pool {}ms", t.elapsed().as_millis());
+                let mut mem_pool = mem_pool.lock().await;
+                log::debug!(target: "sync-block", "unlock mem-pool {}ms", t.elapsed().as_millis());
+                let t = Instant::now();
+                mem_pool.notify_new_tip(tip_block_hash).await?;
+                log::debug!(target: "sync-block", "notify mem-pool new tip cost {}ms", t.elapsed().as_millis());
             }
         }
 
@@ -870,6 +875,7 @@ impl Chain {
             "check account tree"
         );
 
+        log::debug!(target: "sync-block", "Complete");
         Ok(())
     }
 

crates/config/src/config.rs

@@ -221,7 +221,7 @@ fn default_enable_debug_rpc() -> bool {
 
 impl Default for DebugConfig {
     fn default() -> Self {
-        const EXPECTED_TX_UPPER_BOUND_CYCLES: u64 = 70000000u64;
+        const EXPECTED_TX_UPPER_BOUND_CYCLES: u64 = 350000000u64;
         const DEFAULT_DEBUG_TX_DUMP_PATH: &str = "debug-tx-dump";
 
         Self {

crates/mem-pool/src/constants.rs

@@ -1,7 +1,7 @@
 /// MAX deposits in the mem block
-pub const MAX_MEM_BLOCK_DEPOSITS: usize = 50;
+pub const MAX_MEM_BLOCK_DEPOSITS: usize = 100;
 /// MAX withdrawals in the mem block
-pub const MAX_MEM_BLOCK_WITHDRAWALS: usize = 50;
+pub const MAX_MEM_BLOCK_WITHDRAWALS: usize = 100;
 /// MAX withdrawals in the mem block
 pub const MAX_MEM_BLOCK_TXS: usize = 1000;
 /// MIN CKB deposit capacity, calculated from custodian cell size