From 99e9640f72997905d6b80f2f55ac61de4e644071 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Wed, 15 Sep 2021 19:14:33 +1000 Subject: [PATCH 1/3] Log about backfill less often --- beacon_node/client/src/notifier.rs | 38 +++++++++++++++++++----------- 1 file changed, 24 insertions(+), 14 deletions(-) diff --git a/beacon_node/client/src/notifier.rs b/beacon_node/client/src/notifier.rs index bce035c7a41..c2fc5191beb 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,13 @@ 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. + if matches!(current_sync_state, SyncState::BackFillSyncing { .. }) + && 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 +204,24 @@ 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 { .. }) { + } + + // 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 +234,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() { From 2940353daf615034ee839b2a5765864ede7de8d7 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Wed, 15 Sep 2021 19:30:40 +1000 Subject: [PATCH 2/3] Log when backfill complete --- beacon_node/client/src/notifier.rs | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/beacon_node/client/src/notifier.rs b/beacon_node/client/src/notifier.rs index c2fc5191beb..31fb6740639 100644 --- a/beacon_node/client/src/notifier.rs +++ b/beacon_node/client/src/notifier.rs @@ -186,7 +186,8 @@ pub fn spawn_notifier( ); // Log if we are backfilling. - if matches!(current_sync_state, SyncState::BackFillSyncing { .. }) + 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) { @@ -217,6 +218,12 @@ pub fn spawn_notifier( "est_time" => estimated_time_pretty(speedo.estimated_time_till_slot(original_anchor_slot.unwrap_or(current_slot))), ); } + } 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 From ae12a4efdc3ef50cf735b493beddb7203f8aa976 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Wed, 15 Sep 2021 19:30:51 +1000 Subject: [PATCH 3/3] Update docs --- book/src/checkpoint-sync.md | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) 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