Wip - trace piecrust

Cargo.toml

@@ -61,7 +61,7 @@ jubjub-schnorr = { version = "0.5", default-features = false }
 kadcast = "0.7"
 phoenix-circuits = { version = "0.5", default-features = false }
 phoenix-core = { version = "0.33.1", default-features = false }
-piecrust = "0.27.1"
+piecrust = "0.28.0-rc"
 piecrust-uplink = "0.17.3"
 poseidon-merkle = "0.7"
 

node/src/chain/acceptor.rs

@@ -681,6 +681,7 @@ impl<DB: database::DB, VM: vm::VMExecution, N: Network> Acceptor<N, DB, VM> {
         blk: &Block,
         enable_consensus: bool,
     ) -> anyhow::Result<bool> {
+        info!(src = "try_accept", event = "init");
         let mut events = vec![];
         let mut task = self.task.write().await;
 
@@ -701,9 +702,15 @@ impl<DB: database::DB, VM: vm::VMExecution, N: Network> Acceptor<N, DB, VM> {
         )
         .await?;
 
+        let header_verification_elapsed = header_verification_start.elapsed();
+        info!(
+            src = "try_accept",
+            event = "header verified",
+            dur = header_verification_elapsed.as_millis()
+        );
         // Elapsed time header verification
         histogram!("dusk_block_header_elapsed")
-            .record(header_verification_start.elapsed());
+            .record(header_verification_elapsed);
 
         let start = std::time::Instant::now();
         let mut est_elapsed_time = Duration::default();
@@ -718,12 +725,14 @@ impl<DB: database::DB, VM: vm::VMExecution, N: Network> Acceptor<N, DB, VM> {
 
             let (contract_events, finality) =
                 self.db.read().await.update(|db| {
+                    info!(src = "try_accept", event = "before accept",);
                     let (txs, verification_output, contract_events) = vm
                         .accept(
                             prev_header.state_hash,
                             blk,
                             &prev_block_voters[..],
                         )?;
+                    info!(src = "try_accept", event = "after accept",);
 
                     for spent_tx in txs.iter() {
                         events
@@ -740,14 +749,17 @@ impl<DB: database::DB, VM: vm::VMExecution, N: Network> Acceptor<N, DB, VM> {
                         verification_output.event_bloom
                     );
 
+                    info!(src = "try_accept", event = "before rolling",);
                     let finality =
                         self.rolling_finality::<DB>(pni, blk, db, &mut events)?;
+                    info!(src = "try_accept", event = "after rolling",);
 
                     let label = finality.0;
                     // Store block with updated transactions with Error and
                     // GasSpent
                     block_size_on_disk =
                         db.store_block(header, &txs, blk.faults(), label)?;
+                    info!(src = "try_accept", event = "after store_block",);
 
                     Ok((contract_events, finality))
                 })?;
@@ -811,11 +823,13 @@ impl<DB: database::DB, VM: vm::VMExecution, N: Network> Acceptor<N, DB, VM> {
                 slashed_count += 1;
             }
 
+            info!(src = "try_accept", event = "before selective_update",);
             let selective_update = Self::selective_update(
                 header.height,
                 &stakes,
                 &mut provisioners_list,
             );
+            info!(src = "try_accept", event = "after selective_update",);
 
             if let Err(e) = selective_update {
                 warn!("Resync provisioners due to {e:?}");
@@ -839,12 +853,18 @@ impl<DB: database::DB, VM: vm::VMExecution, N: Network> Acceptor<N, DB, VM> {
                     new_finals.pop_last().expect("new_finals to be not empty");
                 let new_final_state_root = new_final_state.state_root;
                 // old final state roots to merge too
-                let old_final_state_roots = new_finals
-                    .into_values()
-                    .map(|finalized_info| finalized_info.state_root)
-                    .chain([prev_final_state_root])
+
+                let old_final_state_roots = [prev_final_state_root]
+                    .into_iter()
+                    .chain(
+                        new_finals
+                            .into_values()
+                            .map(|finalized_info| finalized_info.state_root),
+                    )
                     .collect::<Vec<_>>();
+                info!(src = "try_accept", event = "before finalize",);
                 vm.finalize_state(new_final_state_root, old_final_state_roots)?;
+                info!(src = "try_accept", event = "after finalize",);
             }
 
             anyhow::Ok((label, finalized))

rusk/src/lib/node/rusk.rs

@@ -321,7 +321,11 @@ impl Rusk {
             }
         }
 
-        self.set_current_commit(session.commit()?);
+        info!(src = "vm_accept", event = "before commit");
+        let commit = session.commit()?;
+        info!(src = "vm_accept", event = "after commit");
+        self.set_current_commit(commit);
+        info!(src = "vm_accept", event = "after set_current_commit");
 
         let contract_events = events.clone();
         for event in events {
@@ -551,6 +555,8 @@ fn accept(
     Session,
     Vec<ContractTxEvent>,
 )> {
+    info!(src = "vm_accept", event = "init");
+
     let mut session = session;
 
     let mut block_gas_left = block_gas_limit;
@@ -564,7 +570,10 @@ fn accept(
     for unspent_tx in txs {
         let tx = &unspent_tx.inner;
         let tx_id = unspent_tx.id();
+
+        info!(src = "vm_accept", event = "before execute");
         let receipt = execute(&mut session, tx, execution_config)?;
+        info!(src = "vm_accept", event = "after execute");
 
         event_bloom.add_events(&receipt.events);
 
@@ -595,6 +604,7 @@ fn accept(
         });
     }
 
+    info!(src = "vm_accept", event = "before reward");
     let coinbase_events = reward_slash_and_update_root(
         &mut session,
         block_height,
@@ -603,6 +613,7 @@ fn accept(
         slashing,
         voters,
     )?;
+    info!(src = "vm_accept", event = "after reward");
 
     event_bloom.add_events(&coinbase_events);
 
@@ -615,7 +626,9 @@ fn accept(
         .collect();
     events.extend(coinbase_events);
 
+    info!(src = "vm_accept", event = "before calculating root");
     let state_root = session.root();
+    info!(src = "vm_accept", event = "after calculating root");
 
     Ok((
         spent_txs,