Skip to content

Add timing logs for block processing and XMSS signature verification #225

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
pablodeymo wants to merge 2 commits into
base: main
Choose a base branch
from
Open

Add timing logs for block processing and XMSS signature verification #225

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
cd25c30
Add timing logs to XMSS signature verification for diagnosing block p…
pablodeymo Mar 13, 2026
5ca255f
Add timing logs to on_block_core for full block processing breakdown
pablodeymo Mar 13, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
33 changes: 32 additions & 1 deletion crates/blockchain/src/store.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand All @@ -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;
Expand Down Expand Up @@ -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,
Comment on lines +658 to +660
Copy link
Collaborator

@MegaRedHand MegaRedHand Mar 13, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should use the Debug impl of Duration for prettier logs

"Processed new block"
);
Ok(())
}

Expand Down Expand Up @@ -1159,6 +1173,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;
Expand All @@ -1173,6 +1189,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);
Expand Down Expand Up @@ -1208,6 +1225,7 @@ fn verify_signatures(
}
}
}
let aggregated_elapsed = aggregated_start.elapsed();

let proposer_attestation = &signed_block.message.proposer_attestation;

Expand All @@ -1230,9 +1248,22 @@ fn verify_signatures(
.expect("slot exceeds u32");
let message = proposer_attestation.data.tree_hash_root();

let proposer_start = std::time::Instant::now();
Copy link
Contributor

@greptile-apps greptile-apps bot Mar 13, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Proposer timer starts after deserialization, creating an unaccounted gap

proposer_start is created after the proposer signature bytes have been deserialized and the public key has been decoded. Both of those calls process cryptographic material and their cost is included in total_ms but not in proposer_sig_ms. This means total_ms - (aggregated_sigs_ms + proposer_sig_ms) will be non-zero and could be confusing when reading the logs to diagnose the timing bottleneck.

Since the goal of this PR is to account for all time inside verify_signatures(), consider moving proposer_start to just before the ValidatorSignature::from_bytes call on line 1218. That way the logged fields are fully self-consistent: aggregated_sigs_ms + proposer_sig_ms would account for nearly all of total_ms.

Prompt To Fix With AI 
This is a comment left during a code review.
Path: crates/blockchain/src/store.rs
Line: 1237

Comment:
**Proposer timer starts after deserialization, creating an unaccounted gap**

`proposer_start` is created after the proposer signature bytes have been deserialized and the public key has been decoded. Both of those calls process cryptographic material and their cost is included in `total_ms` but not in `proposer_sig_ms`. This means `total_ms - (aggregated_sigs_ms + proposer_sig_ms)` will be non-zero and could be confusing when reading the logs to diagnose the timing bottleneck.

Since the goal of this PR is to account for all time inside `verify_signatures()`, consider moving `proposer_start` to just before the `ValidatorSignature::from_bytes` call on line 1218. That way the logged fields are fully self-consistent: `aggregated_sigs_ms + proposer_sig_ms` would account for nearly all of `total_ms`.

How can I resolve this? If you propose a fix, please make it concise.

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(())
}

Expand Down
Loading