Log progress during state-sync restore

[mhofman]

What is the Problem Being Solved?

Some steps of state-sync restore such as exporting the swing-store shadow copy from IAVl, or importing the swing-store export take significant amount of time on the agoric-3 mainnet chain, which make it appear like the process has stalled or failed.

Description of the Design

Add some progress logging during these steps. In particular:

• Log when starting the "swingset extension" part of the state-sync restore (just before iterating the swingset KVStore)
• Log during the KVStore iteration at regular interval (it currently takes about 45 minutes)
• Log during the swing-store import at regular interval (before any artifact may be too verbose)

Test Plan

Perform a restore of mainnet using a patched agoric-sdk, and observe regular updates

Upgrade Considerations

Chain software upgrade, but technically this should be compatible without a consensus upgrade.

[Muneeb147]

@mhofman I see we have already added some logging before/after restore from KVstore: https://github.com/Agoric/agoric-sdk/pull/8975

Are we looking for some other logging in this github issue?

[mhofman]

Here are a few places I think are missing on snapshot creation (not as critical since validators don't pay close attentions to this):

• When entering SnapshotExtension: this is when the cosmos side is done, and we're about to retrieve and add the swingset artifacts
• When entering OnExportRetrieved: this is after the artifact info has been retreived from the JS side. If JS is slower than cosmos to produce the artifacts, there will be a delay after the log entry of SnapshotExtension.
• This still leaves a major gap in the cosmos side adding the IAVL entries, but without modifying cosmos-sdk to log incremental progress, I'm not sure what we could do there. It might be interesting to see if we could log the creation of snapshot "chunks" in cosmos-sdk.

For snapshot restore, it's more important to provide regular progress, I think the following places are missing:

• Some way at the cosmos-sdk layer to periodically get progress on the insertion of entries in the cosmos DBs / IAVL. This is probably the biggest black box we have right now.
  • From what I recall, cosmos 0.46 changed the way snapshot chunks are consumed in such a way that the "applied" log produced by cosmos-sdk (or tendermint?) no longer means cosmos-sdk actually processed the chunk. It was somewhat useful to see that actual progress.
• During WriteSwingStoreExportToDirectory, some way to track the progress of getting entries from exportDataReader when writing to the exportDataFile. I have found that this iteration can be quite slow.
• During the JS side of the restore, some way of getting progress as well. I don't have data right now, but the whole step take a while on mainnet sized data, and I suspect that the insertion of kv entries is currently quite slow.