Skip to content

Commit 318923c

Browse files
authored
Add timing logs for block processing and XMSS signature verification (#225)
## Summary - Instruments `on_block_core()` with per-phase timing breakdown of full block processing - Instruments `verify_signatures()` with per-phase timing breakdown of XMSS signature verification - Helps diagnose #197 where `lean_fork_choice_block_processing_time_seconds` shows constant ~1s on devnet dashboards ## Context Issue #197 reports that block processing time on the devnet Grafana dashboard is always approximately 1 second. Investigation revealed that: 1. The `lean_fork_choice_block_processing_time_seconds` histogram has a bucket gap between `0.1s` and `1.0s`, which could cause Grafana's `histogram_quantile` to interpolate misleadingly 2. The actual bottleneck is likely in XMSS signature verification (post-quantum crypto), but there's no visibility into how long each phase takes This PR adds structured timing logs at two levels to pinpoint exactly where time is spent, without changing any behavior. ## Example output Each block produces two log lines — first the signature detail, then the block summary: ``` 2026-03-13T15:30:42.123456Z INFO ethlambda_blockchain::store: Signature verification timing slot=42 attestation_count=3 aggregated_sigs_ms=450 proposer_sig_ms=120 total_ms=572 2026-03-13T15:30:42.140123Z INFO ethlambda_blockchain::store: Processed new block slot=42 block_root=0xabcd1234 state_root=0xef567890 sig_verification_ms=572 state_transition_ms=15 block_total_ms=590 ``` In this example you can see: - **Signature verification dominates** — `sig_verification_ms=572` out of `block_total_ms=590` - **Aggregated sigs are the bottleneck** — `aggregated_sigs_ms=450` vs `proposer_sig_ms=120` - **State transition is fast** — `state_transition_ms=15` - **Minimal overhead** — `590 - 572 - 15 = 3ms` for storage, fork choice, etc. ## Logged fields ### Block processing breakdown (`on_block_core`) | Field | Description | |-------|-------------| | `sig_verification_ms` | Time spent in `verify_signatures()` (0 when verification is skipped) | | `state_transition_ms` | Time spent in `state_transition()` (process_slots + process_block) | | `block_total_ms` | Wall-clock time for the entire `on_block_core()` function | ### Signature verification breakdown (`verify_signatures`) | Field | Description | |-------|-------------| | `attestation_count` | Number of aggregated attestation signatures verified | | `aggregated_sigs_ms` | Total time verifying all aggregated attestation proofs (leanVM calls) | | `proposer_sig_ms` | Time verifying the proposer's individual XMSS signature | | `total_ms` | Wall-clock time for the entire `verify_signatures()` function | ## How to use ```bash # Full block processing breakdown grep "Processed new block" node.log # Signature verification detail grep "Signature verification timing" node.log # Key questions these logs answer: # - Is sig verification the bottleneck? (sig_verification_ms ≈ block_total_ms) # - Is state transition the bottleneck? (state_transition_ms >> sig_verification_ms) # - Within sigs, is it aggregated or proposer? (aggregated_sigs_ms vs proposer_sig_ms) # - Is there overhead outside both phases? (block_total_ms >> sig + state_transition) ``` ## Test plan - [x] `cargo check -p ethlambda-blockchain` passes - [x] `cargo fmt --all -- --check` passes - [x] `cargo clippy -p ethlambda-blockchain -- -D warnings` passes - [ ] Deploy to devnet and observe log output during block production - [ ] Compare timing fields to identify the dominant bottleneck Closes #197 (diagnostic step — may need follow-up based on findings)
1 parent f8acb93 commit 318923c

File tree

1 file changed

+33
-1
lines changed

1 file changed

+33
-1
lines changed

crates/blockchain/src/store.rs

Lines changed: 33 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -532,6 +532,7 @@ fn on_block_core(
532532
verify: bool,
533533
) -> Result<(), StoreError> {
534534
let _timing = metrics::time_fork_choice_block_processing();
535+
let block_start = std::time::Instant::now();
535536

536537
let block = &signed_block.block.block;
537538
let block_root = block.tree_hash_root();
@@ -553,17 +554,21 @@ fn on_block_core(
553554
slot,
554555
})?;
555556

557+
let sig_verification_start = std::time::Instant::now();
556558
if verify {
557559
// Validate cryptographic signatures
558560
verify_signatures(&parent_state, &signed_block)?;
559561
}
562+
let sig_verification = sig_verification_start.elapsed();
560563

561564
let block = signed_block.block.block.clone();
562565
let proposer_attestation = signed_block.block.proposer_attestation.clone();
563566

564567
// Execute state transition function to compute post-block state
568+
let state_transition_start = std::time::Instant::now();
565569
let mut post_state = parent_state;
566570
ethlambda_state_transition::state_transition(&mut post_state, &block)?;
571+
let state_transition = state_transition_start.elapsed();
567572

568573
// Cache the state root in the latest block header
569574
let state_root = block.state_root;
@@ -647,7 +652,16 @@ fn on_block_core(
647652
);
648653
}
649654

650-
info!(%slot, %block_root, %state_root, "Processed new block");
655+
let block_total = block_start.elapsed();
656+
info!(
657+
%slot,
658+
%block_root,
659+
%state_root,
660+
?sig_verification,
661+
?state_transition,
662+
?block_total,
663+
"Processed new block"
664+
);
651665
Ok(())
652666
}
653667

@@ -1175,6 +1189,8 @@ fn verify_signatures(
11751189
use ethlambda_crypto::verify_aggregated_signature;
11761190
use ethlambda_types::signature::ValidatorSignature;
11771191

1192+
let total_start = std::time::Instant::now();
1193+
11781194
let block = &signed_block.block.block;
11791195
let attestations = &block.body.attestations;
11801196
let attestation_signatures = &signed_block.signature.attestation_signatures;
@@ -1189,6 +1205,7 @@ fn verify_signatures(
11891205
let num_validators = validators.len() as u64;
11901206

11911207
// Verify each attestation's signature proof
1208+
let aggregated_start = std::time::Instant::now();
11921209
for (attestation, aggregated_proof) in attestations.iter().zip(attestation_signatures) {
11931210
if attestation.aggregation_bits != aggregated_proof.participants {
11941211
return Err(StoreError::ParticipantsMismatch);
@@ -1224,6 +1241,9 @@ fn verify_signatures(
12241241
}
12251242
}
12261243
}
1244+
let aggregated_elapsed = aggregated_start.elapsed();
1245+
1246+
let proposer_start = std::time::Instant::now();
12271247

12281248
let proposer_attestation = &signed_block.block.proposer_attestation;
12291249

@@ -1256,6 +1276,18 @@ fn verify_signatures(
12561276
if !proposer_signature.is_valid(&proposer_pubkey, slot, &message) {
12571277
return Err(StoreError::ProposerSignatureVerificationFailed);
12581278
}
1279+
let proposer_elapsed = proposer_start.elapsed();
1280+
1281+
let total_elapsed = total_start.elapsed();
1282+
info!(
1283+
slot = block.slot,
1284+
attestation_count = attestations.len(),
1285+
?aggregated_elapsed,
1286+
?proposer_elapsed,
1287+
?total_elapsed,
1288+
"Signature verification timing"
1289+
);
1290+
12591291
Ok(())
12601292
}
12611293

0 commit comments

Comments
 (0)