From 8eebb74088c6960923310870b7870b42f744f32b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1s=20Gr=C3=BCner?= <47506558+MegaRedHand@users.noreply.github.com> Date: Mon, 18 May 2026 15:24:20 -0300 Subject: [PATCH 1/2] debug(blockchain): trace-level instrumentation for build_block loop Adds tracing inside build_block's fixed-point attestation-selection loop so we can investigate sparse or empty blocks. Each iteration emits: - a "start" event with candidate count, current justified checkpoint, and how many AttestationData entries are already chosen; - "skipped" events tagged with a reason (max_attestation_data_cap, head_root_unknown, source_not_justified, chain_mismatch, target_already_justified); - "selected" events with available vs selected bits and proof counts; - a "converged" or "post-block checkpoint" event when the inner loop ends or the fixed point continues. Implementation notes: - Uses trace_span!("build_block", slot, proposer_index) and trace_span!("iter", iteration) so those fields ride along on every event instead of being typed out each time. - Skip paths go through a single trace_skipped_attestation helper. - available_bits / selected_bits HashSet computation is gated behind tracing::enabled!(TRACE) so no allocations happen when trace logging is off. Enable with RUST_LOG=ethlambda_blockchain=trace. --- crates/blockchain/src/store.rs | 83 ++++++++++++++++++++++++++++++++-- 1 file changed, 79 insertions(+), 4 deletions(-) diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs index 037778f0..ea43782b 100644 --- a/crates/blockchain/src/store.rs +++ b/crates/blockchain/src/store.rs @@ -18,7 +18,7 @@ use ethlambda_types::{ signature::ValidatorSignature, state::State, }; -use tracing::{info, trace, warn}; +use tracing::{info, trace, trace_span, warn}; use crate::{ GOSSIP_DISPARITY_INTERVALS, INTERVALS_PER_SLOT, MAX_ATTESTATIONS_DATA, @@ -1032,6 +1032,21 @@ fn extend_proofs_greedily( } } +fn trace_skipped_attestation(reason: &'static str, att: &AttestationData, data_root: &H256) { + trace!( + reason, + attestation_slot = att.slot, + source_slot = att.source.slot, + source_root = %ShortRoot(&att.source.root.0), + target_slot = att.target.slot, + target_root = %ShortRoot(&att.target.root.0), + head_slot = att.head.slot, + head_root = %ShortRoot(&att.head.root.0), + data_root = %ShortRoot(&data_root.0), + "skipped" + ); +} + /// Build a valid block on top of this state. /// /// Works directly with aggregated payloads keyed by data_root, filtering @@ -1072,18 +1087,37 @@ fn build_block( let mut sorted_entries: Vec<_> = aggregated_payloads.iter().collect(); sorted_entries.sort_by_key(|(_, (data, _))| data.target.slot); + let _build_span = trace_span!("build_block", slot, proposer_index).entered(); + let mut iteration: u32 = 0; loop { + iteration += 1; + let _iter_span = trace_span!("iter", iteration).entered(); let mut found_new = false; + let mut iter_selected: u32 = 0; + let mut iter_skipped: u32 = 0; + + trace!( + candidates = sorted_entries.len(), + already_selected = processed_data_roots.len(), + current_justified_slot = current_justified.slot, + current_justified_root = %ShortRoot(¤t_justified.root.0), + "start" + ); for &(data_root, (att_data, proofs)) in &sorted_entries { if processed_data_roots.contains(data_root) { continue; } + // Cap distinct AttestationData entries per block (leanSpec #536). if processed_data_roots.len() >= MAX_ATTESTATIONS_DATA { + trace_skipped_attestation("max_attestation_data_cap", att_data, data_root); + iter_skipped += 1; break; } if !known_block_roots.contains(&att_data.head.root) { + trace_skipped_attestation("head_root_unknown", att_data, data_root); + iter_skipped += 1; continue; } if !justified_slots_ops::is_slot_justified( @@ -1091,10 +1125,14 @@ fn build_block( current_finalized_slot, att_data.source.slot, ) { + trace_skipped_attestation("source_not_justified", att_data, data_root); + iter_skipped += 1; continue; } if !attestation_data_matches_chain(&extended_historical_block_hashes, att_data) { + trace_skipped_attestation("chain_mismatch", att_data, data_root); + iter_skipped += 1; continue; } @@ -1110,16 +1148,45 @@ fn build_block( att_data.target.slot, ) { + trace_skipped_attestation("target_already_justified", att_data, data_root); + iter_skipped += 1; continue; } processed_data_roots.insert(*data_root); found_new = true; + let before = selected.len(); extend_proofs_greedily(proofs, &mut selected, att_data); + + if tracing::enabled!(tracing::Level::TRACE) { + let available_bits: HashSet = + proofs.iter().flat_map(|p| p.participant_indices()).collect(); + let selected_bits: HashSet = selected[before..] + .iter() + .flat_map(|(att, _)| validator_indices(&att.aggregation_bits)) + .collect(); + trace!( + attestation_slot = att_data.slot, + target_slot = att_data.target.slot, + data_root = %ShortRoot(&data_root.0), + available_bits = available_bits.len(), + selected_bits = selected_bits.len(), + available_proofs = proofs.len(), + selected_proofs = selected.len() - before, + "selected" + ); + } + iter_selected += 1; } if !found_new { + trace!( + iter_selected, + iter_skipped, + selected_total = processed_data_roots.len(), + "converged: no new candidates" + ); break; } @@ -1141,9 +1208,17 @@ fn build_block( process_slots(&mut post_state, slot)?; process_block(&mut post_state, &candidate)?; - if post_state.latest_justified != current_justified - || post_state.latest_finalized.slot != current_finalized_slot - { + let advanced = post_state.latest_justified != current_justified + || post_state.latest_finalized.slot != current_finalized_slot; + trace!( + iter_selected, + iter_skipped, + advanced, + justified_slot = post_state.latest_justified.slot, + justified_root = %ShortRoot(&post_state.latest_justified.root.0), + "post-block checkpoint" + ); + if advanced { current_justified = post_state.latest_justified; current_justified_slots = post_state.justified_slots.clone(); current_finalized_slot = post_state.latest_finalized.slot; From 4d9a31b26f58b9edf1c9b0abf8f1c15a47ac5e80 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1s=20Gr=C3=BCner?= <47506558+MegaRedHand@users.noreply.github.com> Date: Mon, 18 May 2026 15:43:02 -0300 Subject: [PATCH 2/2] debug(blockchain): replace build_block spans with one INFO line Removes the trace_span!("build_block") and trace_span!("iter") that carried slot/proposer_index/iteration onto every event. Instead emits a single info! "Building block" line once per call with slot + proposer_index; the trace events that follow are correlated by timestamp / log order. Also adds source/target/head slot+root to the "selected" event so it carries the same identification triplet as "skipped". --- crates/blockchain/src/store.rs | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs index ea43782b..935d3f75 100644 --- a/crates/blockchain/src/store.rs +++ b/crates/blockchain/src/store.rs @@ -18,7 +18,7 @@ use ethlambda_types::{ signature::ValidatorSignature, state::State, }; -use tracing::{info, trace, trace_span, warn}; +use tracing::{info, trace, warn}; use crate::{ GOSSIP_DISPARITY_INTERVALS, INTERVALS_PER_SLOT, MAX_ATTESTATIONS_DATA, @@ -1087,11 +1087,9 @@ fn build_block( let mut sorted_entries: Vec<_> = aggregated_payloads.iter().collect(); sorted_entries.sort_by_key(|(_, (data, _))| data.target.slot); - let _build_span = trace_span!("build_block", slot, proposer_index).entered(); - let mut iteration: u32 = 0; + info!(slot, proposer_index, "Building block"); + loop { - iteration += 1; - let _iter_span = trace_span!("iter", iteration).entered(); let mut found_new = false; let mut iter_selected: u32 = 0; let mut iter_skipped: u32 = 0; @@ -1160,15 +1158,22 @@ fn build_block( extend_proofs_greedily(proofs, &mut selected, att_data); if tracing::enabled!(tracing::Level::TRACE) { - let available_bits: HashSet = - proofs.iter().flat_map(|p| p.participant_indices()).collect(); + let available_bits: HashSet = proofs + .iter() + .flat_map(|p| p.participant_indices()) + .collect(); let selected_bits: HashSet = selected[before..] .iter() .flat_map(|(att, _)| validator_indices(&att.aggregation_bits)) .collect(); trace!( attestation_slot = att_data.slot, + source_slot = att_data.source.slot, + source_root = %ShortRoot(&att_data.source.root.0), target_slot = att_data.target.slot, + target_root = %ShortRoot(&att_data.target.root.0), + head_slot = att_data.head.slot, + head_root = %ShortRoot(&att_data.head.root.0), data_root = %ShortRoot(&data_root.0), available_bits = available_bits.len(), selected_bits = selected_bits.len(),