Skip to content

Log about historical backfill less frequently#2600

Merged
michaelsproul merged 3 commits intosigp:weak-subj-syncfrom
paulhauner:ws-logs-2
Sep 16, 2021
Merged

Log about historical backfill less frequently#2600
michaelsproul merged 3 commits intosigp:weak-subj-syncfrom
paulhauner:ws-logs-2

Conversation

@paulhauner
Copy link
Member

@paulhauner paulhauner commented Sep 15, 2021

Issue Addressed

NA

Proposed Changes

This proposal changes the way we log when we're doing a historical back fill. Presently, we log like this:

INFO New block received                      hash: 0x0a7f36b4dd0755da69cbcd50015ca9398222e7c2037b77b8fb94f8fbc137af30, slot: 1265603
INFO Synced - Downloading historical blocks  est_time: 2 hrs 37 mins, speed: 132.00 slots/sec, distance: 1246433 slots (24 weeks 5 days), peers: 45, service: slot_notifier
INFO New block received                      hash: 0xdfd08ffd942a88c4ae0e4eabfba2716ac4c7a7a5dab6d7acdad0e0b5da80eb87, slot: 1265604
INFO Synced - Downloading historical blocks  est_time: 4 hrs 43 mins, speed: 73.33 slots/sec, distance: 1246433 slots (24 weeks 5 days), peers: 45, service: slot_notifier
INFO New block received                      hash: 0x1dce940086f301ea1b58717fc71bba6167a29fbad63c083d9d8a13cbf95df921, slot: 1265605
INFO Synced - Downloading historical blocks  est_time: 4 hrs 59 mins, speed: 69.34 slots/sec, distance: 1244257 slots (24 weeks 4 days), peers: 46, service: slot_notifier
INFO New block received                      hash: 0x8e84cf0a2312177424c091f3a42c8335a1cb7ad14a8b4d656e805ee0e3ab62f9, slot: 1265606
INFO Synced - Downloading historical blocks  est_time: 3 hrs 55 mins, speed: 87.98 slots/sec, distance: 1242210 slots (24 weeks 4 days), peers: 43, service: slot_notifier

This PR changes it so the logs look more like this:

INFO Downloading historical blocks           est_time: 1 hr 48 mins, speed: 144.01 slots/sec, distance: 935201 slots (18 weeks 3 days), service: slot_notifier
INFO Synced                                  slot: 1265824, block: 0x211a…b6cc, epoch: 39557, finalized_epoch: 39555, finalized_root: 0xc39c…2a5f, peers: 14, service: slot_notifier
INFO New block received                      hash: 0x74ddf3b377d499ab0c185e487fc59b5839dcfd9299423507c2a8bc2ffe3d6d15, slot: 1265825
INFO Synced                                  slot: 1265825, block: 0x74dd…6d15, epoch: 39557, finalized_epoch: 39555, finalized_root: 0xc39c…2a5f, peers: 23, service: slot_notifier
INFO Synced                                  slot: 1265826, block:    …  empty, epoch: 39557, finalized_epoch: 39555, finalized_root: 0xc39c…2a5f, peers: 30, service: slot_notifier
INFO New block received                      hash: 0x1a9cf144823e21a006a654cced535f419878d36890f84ee84e48fd0074159455, slot: 1265827
INFO Synced                                  slot: 1265827, block: 0x1a9c…9455, epoch: 39557, finalized_epoch: 39555, finalized_root: 0xc39c…2a5f, peers: 30, service: slot_notifier
INFO Synced                                  slot: 1265828, block:    …  empty, epoch: 39557, finalized_epoch: 39555, finalized_root: 0xc39c…2a5f, peers: 37, service: slot_notifier
INFO New block received                      hash: 0x1a6089665a565d901bbe2a3226112469c6d883bbc9995a9d70674b3a0a6852e8, slot: 1265829
INFO Downloading historical blocks           est_time: 2 hrs 18 mins, speed: 112.01 slots/sec, distance: 928481 slots (18 weeks 2 days), service: slot_notifier
INFO Synced                                  slot: 1265829, block: 0x1a60…52e8, epoch: 39557, finalized_epoch: 39555, finalized_root: 0xc39c…2a5f, peers: 37, service: slot_notifier

In this new logging format we log the typical Synced logs and then every 5 slots (1 minute) we log about the historical back fill progress (if back fill is in progress).

I think logging the typical Synced messages with the occasional back fill message will place the "your node is synced and ready" message in the foreground and the "backfill is in progress" message in the background. I worry the existing logs might place the historical sync at the foreground, without making it clear that we're ready to go for staking.

Also, the typical Synced messages print info about the current slot, epoch and finalized epoch which I think is handy to see.

Additional Info

I've added a little Historical block download complete message when the notifier sees that we were back filling, but aren't anymore. I haven't actually seen this log fire because my node hasn't finished back filling yet. I'll keep an eye on it.

@paulhauner paulhauner added the ready-for-review The code is ready for review label Sep 15, 2021
michaelsproul
michaelsproul approved these changes Sep 16, 2021
View reviewed changes
Copy link
Member

@michaelsproul michaelsproul left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice, this is much neater, thanks

@michaelsproul michaelsproul merged commit 8e32a1e into sigp:weak-subj-sync Sep 16, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@michaelsproul michaelsproul michaelsproul approved these changes

Assignees

No one assigned

Labels

ready-for-review The code is ready for review

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@paulhauner @michaelsproul