Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log about historical backfill less frequently #2600

Merged
merged 3 commits into from
Sep 16, 2021
Merged

Log about historical backfill less frequently #2600

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
99e9640
Log about backfill less often
paulhauner Sep 15, 2021
2940353
Log when backfill complete
paulhauner Sep 15, 2021
ae12a4e
Update docs
paulhauner Sep 15, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 31 additions & 14 deletions beacon_node/client/src/notifier.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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(),
Expand All @@ -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(),
Expand All @@ -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() {
Expand Down
7 changes: 4 additions & 3 deletions book/src/checkpoint-sync.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down