ae4281bcfc
This modifies blockchain, progresslog, and netsync to provide a progress percentage when logging the main chain verification process. A new method is added to blockchain that determines the verification progress of the current best chain based on how far along it towards the best known header and blockchain is also modified to log the verification progress in the initial chain state message when the blockchain is first loaded. In addition, the progess logger is modified to log the verification progress instead of the timestamp of the last block and the netsync code is updated to make use of the new verification progress func per above. Finally, the netsync code now determines when the chain is considered current and logs new blocks as they are connected along with their hash and additional details. This provides a cleaner distinction between the initial verification and catchup phase and steady state operation.
136 lines
4.2 KiB
Go
136 lines
4.2 KiB
Go
// Copyright (c) 2015-2021 The Decred developers
|
|
// Use of this source code is governed by an ISC
|
|
// license that can be found in the LICENSE file.
|
|
|
|
package progresslog
|
|
|
|
import (
|
|
"sync"
|
|
"time"
|
|
|
|
"github.com/decred/dcrd/wire"
|
|
"github.com/decred/slog"
|
|
)
|
|
|
|
// pickNoun returns the singular or plural form of a noun depending on the
|
|
// provided count.
|
|
func pickNoun(n uint64, singular, plural string) string {
|
|
if n == 1 {
|
|
return singular
|
|
}
|
|
return plural
|
|
}
|
|
|
|
// Logger provides periodic logging of progress towards some action such as
|
|
// syncing the chain.
|
|
type Logger struct {
|
|
sync.Mutex
|
|
subsystemLogger slog.Logger
|
|
progressAction string
|
|
|
|
// lastLogTime tracks the last time a log statement was shown.
|
|
lastLogTime time.Time
|
|
|
|
// These fields accumulate information about blocks between log statements.
|
|
receivedBlocks uint64
|
|
receivedTxns uint64
|
|
receivedVotes uint64
|
|
receivedRevokes uint64
|
|
receivedTickets uint64
|
|
|
|
// These fields accumulate information about headers between log statements.
|
|
receivedHeaders uint64
|
|
}
|
|
|
|
// New returns a new block progress logger.
|
|
func New(progressAction string, logger slog.Logger) *Logger {
|
|
return &Logger{
|
|
lastLogTime: time.Now(),
|
|
progressAction: progressAction,
|
|
subsystemLogger: logger,
|
|
}
|
|
}
|
|
|
|
// LogProgress accumulates details for the provided block and periodically
|
|
// (every 10 seconds) logs an information message to show progress to the user
|
|
// along with duration and totals included.
|
|
//
|
|
// The force flag may be used to force a log message to be shown regardless of
|
|
// the time the last one was shown.
|
|
//
|
|
// The progress message is templated as follows:
|
|
// {progressAction} {numProcessed} {blocks|block} in the last {timePeriod}
|
|
// ({numTxs} {transactions|transaction}, {numTickets} {tickets|ticket},
|
|
// {numVotes} {votes|vote}, {numRevocations} {revocations|revocation},
|
|
// height {lastBlockHeight}, progress {progress}%)
|
|
func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool, progressFn func() float64) {
|
|
l.Lock()
|
|
defer l.Unlock()
|
|
|
|
header := &block.Header
|
|
l.receivedBlocks++
|
|
l.receivedTxns += uint64(len(block.Transactions))
|
|
l.receivedVotes += uint64(header.Voters)
|
|
l.receivedRevokes += uint64(header.Revocations)
|
|
l.receivedTickets += uint64(header.FreshStake)
|
|
now := time.Now()
|
|
duration := now.Sub(l.lastLogTime)
|
|
if !forceLog && duration < time.Second*10 {
|
|
return
|
|
}
|
|
|
|
// Log information about chain progress.
|
|
l.subsystemLogger.Infof("%s %d %s in the last %0.2fs (%d %s, %d %s, %d %s, "+
|
|
"%d %s, height %d, progress %0.2f%%)", l.progressAction,
|
|
l.receivedBlocks, pickNoun(l.receivedBlocks, "block", "blocks"),
|
|
duration.Seconds(),
|
|
l.receivedTxns, pickNoun(l.receivedTxns, "transaction", "transactions"),
|
|
l.receivedTickets, pickNoun(l.receivedTickets, "ticket", "tickets"),
|
|
l.receivedVotes, pickNoun(l.receivedVotes, "vote", "votes"),
|
|
l.receivedRevokes, pickNoun(l.receivedRevokes, "revocation", "revocations"),
|
|
header.Height, progressFn())
|
|
|
|
l.receivedBlocks = 0
|
|
l.receivedTxns = 0
|
|
l.receivedVotes = 0
|
|
l.receivedTickets = 0
|
|
l.receivedRevokes = 0
|
|
l.lastLogTime = now
|
|
}
|
|
|
|
// LogHeaderProgress accumulates the provided number of processed headers and
|
|
// periodically (every 10 seconds) logs an information message to show the
|
|
// header sync progress to the user along with duration and totals included.
|
|
//
|
|
// The force flag may be used to force a log message to be shown regardless of
|
|
// the time the last one was shown.
|
|
//
|
|
// The progress message is templated as follows:
|
|
// {progressAction} {numProcessed} {headers|header} in the last {timePeriod}
|
|
// (progress {progress}%)
|
|
func (l *Logger) LogHeaderProgress(processedHeaders uint64, forceLog bool, progressFn func() float64) {
|
|
l.receivedHeaders += processedHeaders
|
|
|
|
now := time.Now()
|
|
duration := now.Sub(l.lastLogTime)
|
|
if !forceLog && duration < time.Second*10 {
|
|
return
|
|
}
|
|
|
|
// Log information about header progress.
|
|
l.subsystemLogger.Infof("%s %d %s in the last %0.2fs (progress %0.2f%%)",
|
|
l.progressAction, l.receivedHeaders,
|
|
pickNoun(l.receivedHeaders, "header", "headers"),
|
|
duration.Seconds(), progressFn())
|
|
|
|
l.receivedHeaders = 0
|
|
l.lastLogTime = now
|
|
}
|
|
|
|
// SetLastLogTime updates the last time data was logged to the provided time.
|
|
func (l *Logger) SetLastLogTime(time time.Time) {
|
|
l.Lock()
|
|
l.lastLogTime = time
|
|
l.Unlock()
|
|
}
|