Add specific log and metric for delayed blocks (#2308)

## Issue Addressed

NA

## Proposed Changes

- Adds a specific log and metric for when a block is enshrined as head with a delay that will caused bad attestations
    - We *technically* already expose this information, but it's a little tricky to determine during debugging. This makes it nice and explicit.
- Fixes a minor reporting bug with the validator monitor where it was expecting agg. attestations too early (at half-slot rather than two-thirds-slot).

## Additional Info

NA
This commit is contained in:
Paul Hauner 2021-04-13 02:16:59 +00:00
parent 0df7be1814
commit c1203f5e52
4 changed files with 40 additions and 5 deletions

View File

@ -2214,12 +2214,32 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
metrics::stop_timer(update_head_timer); metrics::stop_timer(update_head_timer);
let block_delay = get_slot_delay_ms(timestamp_now(), head_slot, &self.slot_clock);
// Observe the delay between the start of the slot and when we set the block as head. // Observe the delay between the start of the slot and when we set the block as head.
metrics::observe_duration( metrics::observe_duration(
&metrics::BEACON_BLOCK_HEAD_SLOT_START_DELAY_TIME, &metrics::BEACON_BLOCK_HEAD_SLOT_START_DELAY_TIME,
get_slot_delay_ms(timestamp_now(), head_slot, &self.slot_clock), block_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.
//
// Don't create this log if the block was > 4 slots old, this helps prevent noise during
// sync.
if block_delay >= self.slot_clock.unagg_attestation_production_delay()
&& block_delay < self.slot_clock.slot_duration() * 4
{
metrics::inc_counter(&metrics::BEACON_BLOCK_HEAD_SLOT_START_DELAY_EXCEEDED_TOTAL);
debug!(
self.log,
"Delayed head block";
"delay" => ?block_delay,
"root" => ?beacon_block_root,
"slot" => head_slot,
);
}
self.snapshot_cache self.snapshot_cache
.try_write_for(BLOCK_PROCESSING_CACHE_LOCK_TIMEOUT) .try_write_for(BLOCK_PROCESSING_CACHE_LOCK_TIMEOUT)
.map(|mut snapshot_cache| { .map(|mut snapshot_cache| {

View File

@ -629,6 +629,11 @@ lazy_static! {
"beacon_block_head_slot_start_delay_time", "beacon_block_head_slot_start_delay_time",
"Duration between the start of the blocks slot and the current time when it was as head.", "Duration between the start of the blocks slot and the current time when it was as head.",
); );
pub static ref BEACON_BLOCK_HEAD_SLOT_START_DELAY_EXCEEDED_TOTAL: Result<IntCounter> = try_create_int_counter(
"beacon_block_head_slot_start_delay_exceeded_total",
"Triggered when the duration between the start of the blocks slot and the current time \
will result in failed attestations.",
);
/* /*
* General block metrics * General block metrics

View File

@ -528,8 +528,7 @@ impl<T: EthSpec> ValidatorMonitor<T> {
.start_of(data.slot) .start_of(data.slot)
.and_then(|slot_start| seen_timestamp.checked_sub(slot_start)) .and_then(|slot_start| seen_timestamp.checked_sub(slot_start))
.and_then(|gross_delay| { .and_then(|gross_delay| {
let production_delay = slot_clock.slot_duration() / 3; gross_delay.checked_sub(slot_clock.unagg_attestation_production_delay())
gross_delay.checked_sub(production_delay)
}) })
.unwrap_or_else(|| Duration::from_secs(0)) .unwrap_or_else(|| Duration::from_secs(0))
} }
@ -619,8 +618,7 @@ impl<T: EthSpec> ValidatorMonitor<T> {
.start_of(data.slot) .start_of(data.slot)
.and_then(|slot_start| seen_timestamp.checked_sub(slot_start)) .and_then(|slot_start| seen_timestamp.checked_sub(slot_start))
.and_then(|gross_delay| { .and_then(|gross_delay| {
let production_delay = slot_clock.slot_duration() / 2; gross_delay.checked_sub(slot_clock.agg_attestation_production_delay())
gross_delay.checked_sub(production_delay)
}) })
.unwrap_or_else(|| Duration::from_secs(0)) .unwrap_or_else(|| Duration::from_secs(0))
} }

View File

@ -75,4 +75,16 @@ pub trait SlotClock: Send + Sync + Sized + Clone {
self.slot_of(self.now_duration()?.checked_sub(tolerance)?) self.slot_of(self.now_duration()?.checked_sub(tolerance)?)
.or_else(|| Some(self.genesis_slot())) .or_else(|| Some(self.genesis_slot()))
} }
/// Returns the delay between the start of the slot and when unaggregated attestations should be
/// produced.
fn unagg_attestation_production_delay(&self) -> Duration {
self.slot_duration() / 3
}
/// Returns the delay between the start of the slot and when aggregated attestations should be
/// produced.
fn agg_attestation_production_delay(&self) -> Duration {
self.slot_duration() * 2 / 3
}
} }