Log about historical backfill less frequently (#2600)

* Log about backfill less often * Log when backfill complete * Update docs
sigp · Sep 16, 2021 · 8e32a1e · 8e32a1e
1 parent 81ed51a
commit 8e32a1e
Show file tree

Hide file tree

Showing 2 changed files with 35 additions and 17 deletions.
diff --git 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<T: BeaconChainTypes>(
     executor: task_executor::TaskExecutor,
@@ -73,6 +76,7 @@ pub fn spawn_notifier<T: BeaconChainTypes>(
         }
 
         // 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<T: BeaconChainTypes>(
                 "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<T: BeaconChainTypes>(
                 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<T: BeaconChainTypes>(
                 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
@@ -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