From 8e32a1e54a28f5322404d479a799cc9f9e4bea7b Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Thu, 16 Sep 2021 11:34:43 +1000 Subject: [PATCH] Log about historical backfill less frequently (#2600) * Log about backfill less often * Log when backfill complete * Update docs --- beacon_node/client/src/notifier.rs | 45 ++++++++++++++++++++---------- book/src/checkpoint-sync.md | 7 +++-- 2 files changed, 35 insertions(+), 17 deletions(-) diff --git a/beacon_node/client/src/notifier.rs b/beacon_node/client/src/notifier.rs index bce035c7a41..31fb6740639 100644 --- a/beacon_node/client/src/notifier.rs +++ b/beacon_node/client/src/notifier.rs @@ -19,6 +19,9 @@ const MINUTES_PER_HOUR: i64 = 60; /// The number of historical observations that should be used to determine the average sync time. const SPEEDO_OBSERVATIONS: usize = 4; +/// The number of slots between logs that give detail about backfill process. +const BACKFILL_LOG_INTERVAL: u64 = 5; + /// Spawns a notifier service which periodically logs information about the node. pub fn spawn_notifier( executor: task_executor::TaskExecutor, @@ -73,6 +76,7 @@ pub fn spawn_notifier( } // Perform post-genesis logging. + let mut last_backfill_log_slot = None; loop { interval.tick().await; let connected_peer_count = network.connected_peers(); @@ -181,9 +185,14 @@ pub fn spawn_notifier( "sync_state" =>format!("{}", current_sync_state) ); - // Log if we are syncing - if current_sync_state.is_syncing() { - metrics::set_gauge(&metrics::IS_SYNCED, 0); + // Log if we are backfilling. + let is_backfilling = matches!(current_sync_state, SyncState::BackFillSyncing { .. }); + if is_backfilling + && last_backfill_log_slot + .map_or(true, |slot| slot + BACKFILL_LOG_INTERVAL <= current_slot) + { + last_backfill_log_slot = Some(current_slot); + let distance = format!( "{} slots ({})", sync_distance.as_u64(), @@ -196,22 +205,30 @@ pub fn spawn_notifier( if display_speed { info!( log, - "Syncing"; - "peers" => peer_count_pretty(connected_peer_count), + "Downloading historical blocks"; "distance" => distance, "speed" => sync_speed_pretty(speed), - "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(current_slot)), + "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(original_anchor_slot.unwrap_or(current_slot))), ); } else { info!( log, - "Syncing"; - "peers" => peer_count_pretty(connected_peer_count), + "Downloading historical blocks"; "distance" => distance, - "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(current_slot)), + "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(original_anchor_slot.unwrap_or(current_slot))), ); } - } else if matches!(current_sync_state, SyncState::BackFillSyncing { .. }) { + } else if !is_backfilling && last_backfill_log_slot.is_some() { + last_backfill_log_slot = None; + info!( + log, + "Historical block download complete"; + ); + } + + // Log if we are syncing + if current_sync_state.is_syncing() { + metrics::set_gauge(&metrics::IS_SYNCED, 0); let distance = format!( "{} slots ({})", sync_distance.as_u64(), @@ -224,19 +241,19 @@ pub fn spawn_notifier( if display_speed { info!( log, - "Synced - Downloading historical blocks"; + "Syncing"; "peers" => peer_count_pretty(connected_peer_count), "distance" => distance, "speed" => sync_speed_pretty(speed), - "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(original_anchor_slot.unwrap_or(current_slot))), + "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(current_slot)), ); } else { info!( log, - "Synced - Downloading historical blocks"; + "Syncing"; "peers" => peer_count_pretty(connected_peer_count), "distance" => distance, - "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(original_anchor_slot.unwrap_or(current_slot))), + "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(current_slot)), ); } } else if current_sync_state.is_synced() { diff --git a/book/src/checkpoint-sync.md b/book/src/checkpoint-sync.md index 5245c19ded5..f6d8611854e 100644 --- a/book/src/checkpoint-sync.md +++ b/book/src/checkpoint-sync.md @@ -46,13 +46,14 @@ as soon as forwards sync completes. Once forwards sync completes, Lighthouse will commence a "backfill sync" to download the blocks from the checkpoint back to genesis. -The beacon node will log messages similar to the following while it completes backfill sync: +The beacon node will log messages similar to the following each minute while it completes backfill +sync: ``` -INFO Synced - Downloading historical blocks est_time: 5 hrs 0 mins, speed: 111.96 slots/sec, distance: 2020451 slots (40 weeks 0 days), peers: 50, service: slot_notifier +INFO Downloading historical blocks est_time: 5 hrs 0 mins, speed: 111.96 slots/sec, distance: 2020451 slots (40 weeks 0 days), service: slot_notifier ``` -When the sync status changes to `INFO Synced`, the backfill sync is complete. +Once backfill is complete, a `INFO Historical block download complete` log will be emitted. ## FAQ