From cd25c30adb70b185da0b96a8785cbc656f243725 Mon Sep 17 00:00:00 2001
From: Pablo Deymonnaz <pdeymon@fi.uba.ar>
Date: Fri, 13 Mar 2026 18:35:09 -0300
Subject: [PATCH 1/2] Add timing logs to XMSS signature verification for
 diagnosing block processing latency

Instruments verify_signatures() with std::time::Instant to log per-phase
breakdown: aggregated attestation signatures, proposer signature, and total
elapsed time in milliseconds. This helps diagnose issue #197 where
lean_fork_choice_block_processing_time_seconds shows constant ~1s on devnet.
---
 crates/blockchain/src/store.rs | 17 +++++++++++++++++
 1 file changed, 17 insertions(+)

diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs
index e15e324..2075662 100644
--- a/crates/blockchain/src/store.rs
+++ b/crates/blockchain/src/store.rs
@@ -1159,6 +1159,8 @@ fn verify_signatures(
     use ethlambda_crypto::verify_aggregated_signature;
     use ethlambda_types::signature::ValidatorSignature;
 
+    let total_start = std::time::Instant::now();
+
     let block = &signed_block.message.block;
     let attestations = &block.body.attestations;
     let attestation_signatures = &signed_block.signature.attestation_signatures;
@@ -1173,6 +1175,7 @@ fn verify_signatures(
     let num_validators = validators.len() as u64;
 
     // Verify each attestation's signature proof
+    let aggregated_start = std::time::Instant::now();
     for (attestation, aggregated_proof) in attestations.iter().zip(attestation_signatures) {
         if attestation.aggregation_bits != aggregated_proof.participants {
             return Err(StoreError::ParticipantsMismatch);
@@ -1208,6 +1211,7 @@ fn verify_signatures(
             }
         }
     }
+    let aggregated_elapsed = aggregated_start.elapsed();
 
     let proposer_attestation = &signed_block.message.proposer_attestation;
 
@@ -1230,9 +1234,22 @@ fn verify_signatures(
         .expect("slot exceeds u32");
     let message = proposer_attestation.data.tree_hash_root();
 
+    let proposer_start = std::time::Instant::now();
     if !proposer_signature.is_valid(&proposer_pubkey, slot, &message) {
         return Err(StoreError::ProposerSignatureVerificationFailed);
     }
+    let proposer_elapsed = proposer_start.elapsed();
+
+    let total_elapsed = total_start.elapsed();
+    info!(
+        slot = block.slot,
+        attestation_count = attestations.len(),
+        aggregated_sigs_ms = aggregated_elapsed.as_millis() as u64,
+        proposer_sig_ms = proposer_elapsed.as_millis() as u64,
+        total_ms = total_elapsed.as_millis() as u64,
+        "Signature verification timing"
+    );
+
     Ok(())
 }
 

From 5ca255fe3c019ffff6c528a8d913d6d34f348864 Mon Sep 17 00:00:00 2001
From: Pablo Deymonnaz <pdeymon@fi.uba.ar>
Date: Fri, 13 Mar 2026 18:50:06 -0300
Subject: [PATCH 2/2] Add timing logs to on_block_core for full block
 processing breakdown

Adds sig_verification_ms, state_transition_ms, and block_total_ms fields
to the existing "Processed new block" log line. This allows comparing
the overall block processing time against the signature verification
breakdown from the previous commit.
---
 crates/blockchain/src/store.rs | 16 +++++++++++++++-
 1 file changed, 15 insertions(+), 1 deletion(-)

diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs
index 2075662..e72cd02 100644
--- a/crates/blockchain/src/store.rs
+++ b/crates/blockchain/src/store.rs
@@ -531,6 +531,7 @@ fn on_block_core(
     verify: bool,
 ) -> Result<(), StoreError> {
     let _timing = metrics::time_fork_choice_block_processing();
+    let block_start = std::time::Instant::now();
 
     let block = &signed_block.message.block;
     let block_root = block.tree_hash_root();
@@ -552,17 +553,21 @@ fn on_block_core(
                 slot,
             })?;
 
+    let sig_verification_start = std::time::Instant::now();
     if verify {
         // Validate cryptographic signatures
         verify_signatures(&parent_state, &signed_block)?;
     }
+    let sig_verification_ms = sig_verification_start.elapsed().as_millis() as u64;
 
     let block = signed_block.message.block.clone();
     let proposer_attestation = signed_block.message.proposer_attestation.clone();
 
     // Execute state transition function to compute post-block state
+    let state_transition_start = std::time::Instant::now();
     let mut post_state = parent_state;
     ethlambda_state_transition::state_transition(&mut post_state, &block)?;
+    let state_transition_ms = state_transition_start.elapsed().as_millis() as u64;
 
     // Cache the state root in the latest block header
     let state_root = block.state_root;
@@ -645,7 +650,16 @@ fn on_block_core(
         );
     }
 
-    info!(%slot, %block_root, %state_root, "Processed new block");
+    let block_total_ms = block_start.elapsed().as_millis() as u64;
+    info!(
+        %slot,
+        %block_root,
+        %state_root,
+        sig_verification_ms,
+        state_transition_ms,
+        block_total_ms,
+        "Processed new block"
+    );
     Ok(())
 }