gnosis/lighthouse
1
0
Fork 0
mirror of https://github.com/sigp/lighthouse.git synced 2026-03-03 00:31:50 +00:00
Code Issues Packages Projects Releases Wiki Activity

Refine delayed head block logging (#7705)

Browse Source 
Small tweak to `Delayed head block` logging to make it more representative of actual issues. Previously we used the total import delay to determine whether a block was late, but this includes the time taken for IO (and now hdiff computation) which happens _after_ the block is made attestable.

This PR changes the logic to use the attestable delay (where possible) falling back to the previous value if the block doesn't have one; e.g. if it didn't meet the conditions to make it into the attestable cache.
This commit is contained in:
Michael Sproul
2025-07-23 10:29:18 +10:00
committed by GitHub
parent e6089fe7db
commit ce99e0c383
1 changed files with 31 additions and 31 deletions
Download Patch File Download Diff File Expand all files Collapse all files

62
beacon_node/beacon_chain/src/canonical_head.rs
View File

@@ -38,7 +38,7 @@ use crate::{
block_times_cache::BlockTimesCache,
events::ServerSentEventHandler,
metrics,
validator_monitor::{get_slot_delay_ms, timestamp_now},
validator_monitor::get_slot_delay_ms,
BeaconChain, BeaconChainError as Error, BeaconChainTypes, BeaconSnapshot,
};
use eth2::types::{EventKind, SseChainReorg, SseFinalizedCheckpoint, SseHead, SseLateHead};
@@ -1287,7 +1287,10 @@ fn observe_head_block_delays<E: EthSpec, S: SlotClock>(
slot_clock: &S,
event_handler: Option<&ServerSentEventHandler<E>>,
) {
let block_time_set_as_head = timestamp_now();
let Some(block_time_set_as_head) = slot_clock.now_duration() else {
// Practically unreachable: the slot clock's time should not be before the UNIX epoch.
return;
};
let head_block_root = head_block.root;
let head_block_slot = head_block.slot;
let head_block_is_optimistic = head_block.execution_status.is_optimistic_or_invalid();
@@ -1308,10 +1311,6 @@ fn observe_head_block_delays<E: EthSpec, S: SlotClock>(
// If a block comes in from over 4 slots ago, it is most likely a block from sync.
let block_from_sync = block_delay_total > slot_clock.slot_duration() * 4;
// Determine whether the block has been set as head too late for proper attestation
// production.
let late_head = block_delay_total >= slot_clock.unagg_attestation_production_delay();
// Do not store metrics if the block was > 4 slots old, this helps prevent noise during
// sync.
if !block_from_sync {
@@ -1410,6 +1409,14 @@ fn observe_head_block_delays<E: EthSpec, S: SlotClock>(
.as_millis() as i64,
);
// Consider the block late if the time it became attestable is after the attestation
// deadline. If the block was not made attestable, use the set-as-head time.
let attestable_delay = block_delays.attestable.unwrap_or(block_delay_total);
// Determine whether the block has been set as head too late for proper attestation
// production.
let late_head = attestable_delay >= slot_clock.unagg_attestation_production_delay();
// If the block was enshrined as head too late for attestations to be created for it,
// log a debug warning and increment a metric.
let format_delay = |delay: &Option<Duration>| {
@@ -1432,6 +1439,24 @@ fn observe_head_block_delays<E: EthSpec, S: SlotClock>(
set_as_head_time_ms = format_delay(&block_delays.set_as_head),
"Delayed head block"
);
if let Some(event_handler) = event_handler {
if event_handler.has_late_head_subscribers() {
let peer_info = block_times_cache.get_peer_info(head_block_root);
event_handler.register(EventKind::LateHead(SseLateHead {
slot: head_block_slot,
block: head_block_root,
peer_id: peer_info.id,
peer_client: peer_info.client,
proposer_index: head_block_proposer_index,
proposer_graffiti: head_block_graffiti,
block_delay: block_delay_total,
observed_delay: block_delays.observed,
imported_delay: block_delays.imported,
set_as_head_delay: block_delays.set_as_head,
execution_optimistic: head_block_is_optimistic,
}));
}
}
} else {
debug!(
block_root = ?head_block_root,
@@ -1450,29 +1475,4 @@ fn observe_head_block_delays<E: EthSpec, S: SlotClock>(
);
}
}
if let Some(event_handler) = event_handler {
if !block_from_sync && late_head && event_handler.has_late_head_subscribers() {
let peer_info = block_times_cache.get_peer_info(head_block_root);
let block_delays = block_times_cache.get_block_delays(
head_block_root,
slot_clock
.start_of(head_block_slot)
.unwrap_or_else(|| Duration::from_secs(0)),
);
event_handler.register(EventKind::LateHead(SseLateHead {
slot: head_block_slot,
block: head_block_root,
peer_id: peer_info.id,
peer_client: peer_info.client,
proposer_index: head_block_proposer_index,
proposer_graffiti: head_block_graffiti,
block_delay: block_delay_total,
observed_delay: block_delays.observed,
imported_delay: block_delays.imported,
set_as_head_delay: block_delays.set_as_head,
execution_optimistic: head_block_is_optimistic,
}));
}
}
}