Repository: stacks-network/stacks-core (language: python)

Issue:
Update block validation endpoint to return the processing time
~~In addition to reporting if the block is valid, the node should also report the block cost.~~ EDIT: it already reports the block costs.

In addition to reporting if the block is valid, the node should also report the processing time.

See #5434.


Discussion / hints:
Does it not already do this? https://github.com/stacks-network/stacks-core/blob/bac1b07baf316ffc124d7a0b348af23afa727a99/stackslib/src/net/api/postblock_proposal.rs#L146 
> Does it not already do this?

Updated to add the processing time instead.

Fix patch:
diff --git a/stackslib/src/net/api/postblock_proposal.rs b/stackslib/src/net/api/postblock_proposal.rs
index b67b6166aa..38843174b0 100644
--- a/stackslib/src/net/api/postblock_proposal.rs
+++ b/stackslib/src/net/api/postblock_proposal.rs
@@ -145,6 +145,7 @@ pub struct BlockValidateOk {
     pub signer_signature_hash: Sha512Trunc256Sum,
     pub cost: ExecutionCost,
     pub size: u64,
+    pub validation_time_ms: u64,
 }
 
 /// This enum is used for serializing the response to block
@@ -356,7 +357,12 @@ impl NakamotoBlockProposal {
         }
         let ts_start = get_epoch_time_ms();
         // Measure time from start of function
-        let time_elapsed = || get_epoch_time_ms().saturating_sub(ts_start);
+        let time_elapsed = || {
+            get_epoch_time_ms()
+                .saturating_sub(ts_start)
+                .try_into()
+                .unwrap_or(u64::MAX)
+        };
 
         let mainnet = self.chain_id == CHAIN_ID_MAINNET;
         if self.chain_id != chainstate.chain_id || mainnet != chainstate.mainnet {
@@ -544,6 +550,8 @@ impl NakamotoBlockProposal {
             });
         }
 
+        let validation_time_ms = time_elapsed();
+
         info!(
             "Participant: validated anchored block";
             "block_header_hash" => %computed_block_header_hash,
@@ -552,7 +560,7 @@ impl NakamotoBlockProposal {
             "parent_stacks_block_id" => %block.header.parent_block_id,
             "block_size" => size,
             "execution_cost" => %cost,
-            "validation_time_ms" => time_elapsed(),
+            "validation_time_ms" => validation_time_ms,
             "tx_fees_microstacks" => block.txs.iter().fold(0, |agg: u64, tx| {
                 agg.saturating_add(tx.get_tx_fee())
             })
@@ -562,6 +570,7 @@ impl NakamotoBlockProposal {
             signer_signature_hash: block.header.signer_signature_hash(),
             cost,
             size,
+            validation_time_ms,
         })
     }
 }


Test patch:
diff --git a/stackslib/src/net/api/tests/postblock_proposal.rs b/stackslib/src/net/api/tests/postblock_proposal.rs
index 4f553efd21..7ce3828cf6 100644
--- a/stackslib/src/net/api/tests/postblock_proposal.rs
+++ b/stackslib/src/net/api/tests/postblock_proposal.rs
@@ -238,7 +238,7 @@ fn test_try_make_response() {
 
     let miner_privk = &rpc_test.peer_1.miner.nakamoto_miner_key();
 
-    let mut block = {
+    let mut good_block = {
         let chainstate = rpc_test.peer_1.chainstate();
         let parent_stacks_header =
             NakamotoChainState::get_block_header(chainstate.db(), &stacks_tip)
@@ -313,12 +313,12 @@ fn test_try_make_response() {
     };
 
     // Increment the timestamp by 1 to ensure it is different from the previous block
-    block.header.timestamp += 1;
-    rpc_test.peer_1.miner.sign_nakamoto_block(&mut block);
+    good_block.header.timestamp += 1;
+    rpc_test.peer_1.miner.sign_nakamoto_block(&mut good_block);
 
     // post the valid block proposal
     let proposal = NakamotoBlockProposal {
-        block: block.clone(),
+        block: good_block.clone(),
         chain_id: 0x80000000,
     };
 
@@ -333,12 +333,16 @@ fn test_try_make_response() {
     requests.push(request);
 
     // Set the timestamp to a value in the past
-    block.header.timestamp -= 10000;
-    rpc_test.peer_1.miner.sign_nakamoto_block(&mut block);
+    let mut early_time_block = good_block.clone();
+    early_time_block.header.timestamp -= 10000;
+    rpc_test
+        .peer_1
+        .miner
+        .sign_nakamoto_block(&mut early_time_block);
 
     // post the invalid block proposal
     let proposal = NakamotoBlockProposal {
-        block: block.clone(),
+        block: early_time_block,
         chain_id: 0x80000000,
     };
 
@@ -353,12 +357,16 @@ fn test_try_make_response() {
     requests.push(request);
 
     // Set the timestamp to a value in the future
-    block.header.timestamp += 20000;
-    rpc_test.peer_1.miner.sign_nakamoto_block(&mut block);
+    let mut late_time_block = good_block.clone();
+    late_time_block.header.timestamp += 20000;
+    rpc_test
+        .peer_1
+        .miner
+        .sign_nakamoto_block(&mut late_time_block);
 
     // post the invalid block proposal
     let proposal = NakamotoBlockProposal {
-        block: block.clone(),
+        block: late_time_block,
         chain_id: 0x80000000,
     };
 
@@ -380,7 +388,7 @@ fn test_try_make_response() {
 
     let response = responses.remove(0);
 
-    // Wait for the results to be non-empty
+    // Wait for the results of all 3 requests
     loop {
         if proposal_observer
             .lock()
@@ -401,7 +409,23 @@ fn test_try_make_response() {
     let mut results = observer.results.lock().unwrap();
 
     let result = results.remove(0);
-    assert!(result.is_ok());
+    match result {
+        Ok(postblock_proposal::BlockValidateOk {
+            signer_signature_hash,
+            cost,
+            size,
+            validation_time_ms,
+        }) => {
+            assert_eq!(
+                signer_signature_hash,
+                good_block.header.signer_signature_hash()
+            );
+            assert_eq!(cost, ExecutionCost::zero());
+            assert_eq!(size, 180);
+            assert!(validation_time_ms > 0 && validation_time_ms < 60000);
+        }
+        _ => panic!("expected ok"),
+    }
 
     let result = results.remove(0);
     match result {