From fd1907ee0f2c29dfa026bee251a36058fea11591 Mon Sep 17 00:00:00 2001 From: Pablo Deymonnaz Date: Fri, 13 Mar 2026 18:35:09 -0300 Subject: [PATCH 1/3] 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 00389f0..fdd739f 100644 --- a/crates/blockchain/src/store.rs +++ b/crates/blockchain/src/store.rs @@ -1175,6 +1175,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.block.block; let attestations = &block.body.attestations; let attestation_signatures = &signed_block.signature.attestation_signatures; @@ -1189,6 +1191,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); @@ -1224,6 +1227,7 @@ fn verify_signatures( } } } + let aggregated_elapsed = aggregated_start.elapsed(); let proposer_attestation = &signed_block.block.proposer_attestation; @@ -1253,9 +1257,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 4042de44720104992cb59b8b9bb9eb130636a1dd Mon Sep 17 00:00:00 2001 From: Pablo Deymonnaz Date: Fri, 13 Mar 2026 18:50:06 -0300 Subject: [PATCH 2/3] 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 fdd739f..85eb598 100644 --- a/crates/blockchain/src/store.rs +++ b/crates/blockchain/src/store.rs @@ -532,6 +532,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.block.block; let block_root = block.tree_hash_root(); @@ -553,17 +554,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.block.block.clone(); let proposer_attestation = signed_block.block.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; @@ -647,7 +652,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(()) } From d344901af4c3a195935764e0eaffc643e2d0c847 Mon Sep 17 00:00:00 2001 From: Pablo Deymonnaz Date: Thu, 26 Mar 2026 16:43:00 -0300 Subject: [PATCH 3/3] Use Duration Debug impl and move proposer timer to include deserialization Address review feedback: use tracing's ?field syntax for Duration's Debug impl instead of manual _ms conversions, and move proposer_start earlier to include signature deserialization and pubkey decoding in the measurement. --- crates/blockchain/src/store.rs | 21 +++++++++++---------- 1 file changed, 11 insertions(+), 10 deletions(-) diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs index 85eb598..094600a 100644 --- a/crates/blockchain/src/store.rs +++ b/crates/blockchain/src/store.rs @@ -559,7 +559,7 @@ fn on_block_core( // Validate cryptographic signatures verify_signatures(&parent_state, &signed_block)?; } - let sig_verification_ms = sig_verification_start.elapsed().as_millis() as u64; + let sig_verification = sig_verification_start.elapsed(); let block = signed_block.block.block.clone(); let proposer_attestation = signed_block.block.proposer_attestation.clone(); @@ -568,7 +568,7 @@ fn on_block_core( 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; + let state_transition = state_transition_start.elapsed(); // Cache the state root in the latest block header let state_root = block.state_root; @@ -652,14 +652,14 @@ fn on_block_core( ); } - let block_total_ms = block_start.elapsed().as_millis() as u64; + let block_total = block_start.elapsed(); info!( %slot, %block_root, %state_root, - sig_verification_ms, - state_transition_ms, - block_total_ms, + ?sig_verification, + ?state_transition, + ?block_total, "Processed new block" ); Ok(()) @@ -1243,6 +1243,8 @@ fn verify_signatures( } let aggregated_elapsed = aggregated_start.elapsed(); + let proposer_start = std::time::Instant::now(); + let proposer_attestation = &signed_block.block.proposer_attestation; if proposer_attestation.validator_id != block.proposer_index { @@ -1271,7 +1273,6 @@ 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); } @@ -1281,9 +1282,9 @@ fn verify_signatures( 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, + ?aggregated_elapsed, + ?proposer_elapsed, + ?total_elapsed, "Signature verification timing" );