diff --git a/blockchain/chain.go b/blockchain/chain.go index c4d284ce88..4a4e82a42c 100644 --- a/blockchain/chain.go +++ b/blockchain/chain.go @@ -2221,8 +2221,9 @@ func New(ctx context.Context, config *Config) (*BlockChain, error) { bestHdr.hash) tip := b.bestChain.Tip() - log.Infof("Chain state: height %d, hash %v, total transactions %d, work %v", - tip.height, tip.hash, b.stateSnapshot.TotalTxns, tip.workSum) + log.Infof("Chain state: height %d, hash %v, total transactions %d, work "+ + "%v, progress %0.2f%%", tip.height, tip.hash, + b.stateSnapshot.TotalTxns, tip.workSum, b.VerifyProgress()) return &b, nil } diff --git a/blockchain/chainquery.go b/blockchain/chainquery.go index 1ce5d03eab..00008ea874 100644 --- a/blockchain/chainquery.go +++ b/blockchain/chainquery.go @@ -6,6 +6,7 @@ package blockchain import ( "bytes" + "math" "sort" "github.com/decred/dcrd/chaincfg/chainhash" @@ -233,3 +234,19 @@ func (b *BlockChain) NextNeededBlocks(maxResults uint8, exclude map[chainhash.Ha } return neededBlocks } + +// VerifyProgress returns a percentage that is a guess of the progress of the +// chain verification process. +// +// This function is safe for concurrent access. +func (b *BlockChain) VerifyProgress() float64 { + b.index.RLock() + bestHdr := b.index.bestHeader + b.index.RUnlock() + if bestHdr.height == 0 { + return 0.0 + } + + tip := b.bestChain.Tip() + return math.Min(float64(tip.height)/float64(bestHdr.height), 1.0) * 100 +} diff --git a/blockdb.go b/blockdb.go index 9cf6fa942a..977ace0374 100644 --- a/blockdb.go +++ b/blockdb.go @@ -240,7 +240,9 @@ func dumpBlockChain(params *chaincfg.Params, b *blockchain.BlockChain) error { msgBlock := bl.MsgBlock() forceLog := int64(msgBlock.Header.Height) >= tipHeight - progressLogger.LogProgress(msgBlock, forceLog) + progressLogger.LogProgress(msgBlock, forceLog, func() float64 { + return float64(msgBlock.Header.Height) / float64(tipHeight) * 100 + }) } srvrLog.Infof("Successfully dumped the blockchain (%v blocks) to %v.", diff --git a/internal/netsync/log.go b/internal/netsync/log.go index cbe84d3a1e..8db82c2a8d 100644 --- a/internal/netsync/log.go +++ b/internal/netsync/log.go @@ -1,4 +1,4 @@ -// Copyright (c) 2020 The Decred developers +// Copyright (c) 2020-2021 The Decred developers // Use of this source code is governed by an ISC // license that can be found in the LICENSE file. @@ -20,3 +20,12 @@ var log = slog.Disabled func UseLogger(logger slog.Logger) { log = logger } + +// 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 +} diff --git a/internal/netsync/manager.go b/internal/netsync/manager.go index 448d453132..3301a24032 100644 --- a/internal/netsync/manager.go +++ b/internal/netsync/manager.go @@ -781,6 +781,11 @@ func (m *SyncManager) handleBlockMsg(bmsg *blockMsg) { return } + // Save whether or not the chain believes it is current prior to processing + // the block for use below in determining logging behavior. + chain := m.cfg.Chain + wasChainCurrent := chain.IsCurrent() + // Process the block to include validation, best chain selection, etc. // // Also, remove the block from the request maps once it has been processed. @@ -819,15 +824,39 @@ func (m *SyncManager) handleBlockMsg(bmsg *blockMsg) { return } - // Log information about the block and update the chain state. + // Log information about the block. Use the progress logger when the chain + // was not already current prior to processing the block to provide nicer + // periodic logging with a progress percentage. Otherwise, log the block + // individually along with some stats. msgBlock := bmsg.block.MsgBlock() - forceLog := int64(msgBlock.Header.Height) >= m.SyncHeight() - m.progressLogger.LogProgress(msgBlock, forceLog) - + header := &msgBlock.Header + if !wasChainCurrent { + forceLog := int64(header.Height) >= m.SyncHeight() + m.progressLogger.LogProgress(msgBlock, forceLog, chain.VerifyProgress) + if chain.IsCurrent() { + best := chain.BestSnapshot() + log.Infof("Initial chain sync complete (hash %s, height %d)", + best.Hash, best.Height) + } + } else { + numTxns := uint64(len(msgBlock.Transactions)) + numTickets := uint64(header.FreshStake) + numVotes := uint64(header.Voters) + numRevokes := uint64(header.Revocations) + log.Infof("New block %s (%d %s, %d %s, %d %s, %d %s, height %d)", + blockHash, numTxns, pickNoun(numTxns, "transaction", "transactions"), + numTickets, pickNoun(numTickets, "ticket", "tickets"), + numVotes, pickNoun(numVotes, "vote", "votes"), + numRevokes, pickNoun(numRevokes, "revocation", "revocations"), + header.Height) + } + + // Perform some additional processing when the block extended the main + // chain. onMainChain := forkLen == 0 if onMainChain { // Prune invalidated transactions. - best := m.cfg.Chain.BestSnapshot() + best := chain.BestSnapshot() m.cfg.TxMemPool.PruneStakeTx(best.NextStakeDiff, best.Height) m.cfg.TxMemPool.PruneExpiredTx() @@ -842,7 +871,7 @@ func (m *SyncManager) handleBlockMsg(bmsg *blockMsg) { // the main chain, update the heights of other peers whose invs may have // been ignored when actively syncing while the chain was not yet current or // lost the lock announcement race. - blockHeight := int64(bmsg.block.MsgBlock().Header.Height) + blockHeight := int64(header.Height) peer.UpdateLastBlockHeight(blockHeight) if onMainChain && m.IsCurrent() { for _, p := range m.peers { @@ -1091,6 +1120,11 @@ func (m *SyncManager) handleHeadersMsg(hmsg *headersMsg) { // that the headers are synced. chain.MaybeUpdateIsCurrent() isChainCurrent = chain.IsCurrent() + if isChainCurrent { + best := chain.BestSnapshot() + log.Infof("Initial chain sync complete (hash %s, height %d)", + best.Hash, best.Height) + } } } diff --git a/internal/progresslog/logger.go b/internal/progresslog/logger.go index 4d1b1777c3..7d9a98eba8 100644 --- a/internal/progresslog/logger.go +++ b/internal/progresslog/logger.go @@ -62,8 +62,8 @@ func New(progressAction string, logger slog.Logger) *Logger { // {progressAction} {numProcessed} {blocks|block} in the last {timePeriod} // ({numTxs} {transactions|transaction}, {numTickets} {tickets|ticket}, // {numVotes} {votes|vote}, {numRevocations} {revocations|revocation}, -// height {lastBlockHeight}, {lastBlockTimeStamp}) -func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool) { +// height {lastBlockHeight}, progress {progress}%) +func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool, progressFn func() float64) { l.Lock() defer l.Unlock() @@ -81,14 +81,14 @@ func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool) { // Log information about chain progress. l.subsystemLogger.Infof("%s %d %s in the last %s (%d %s, %d %s, %d %s, "+ - "%d %s, height %d, %s)", l.progressAction, + "%d %s, height %d, progress %0.2f%%)", l.progressAction, l.receivedBlocks, pickNoun(l.receivedBlocks, "block", "blocks"), duration.Truncate(time.Millisecond*10), 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, header.Timestamp) + header.Height, progressFn()) l.receivedBlocks = 0 l.receivedTxns = 0 @@ -107,7 +107,7 @@ func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool) { // // The progress message is templated as follows: // {progressAction} {numProcessed} {headers|header} in the last {timePeriod} -// (progress ~{progress}%) +// (progress {progress}%) func (l *Logger) LogHeaderProgress(processedHeaders uint64, forceLog bool, progressFn func() float64) { l.receivedHeaders += processedHeaders diff --git a/internal/progresslog/logger_test.go b/internal/progresslog/logger_test.go index f7214ca7ac..37add29e04 100644 --- a/internal/progresslog/logger_test.go +++ b/internal/progresslog/logger_test.go @@ -131,13 +131,14 @@ func TestLogProgress(t *testing.T) { wantReceivedTickets: 0, }} + progressFn := func() float64 { return 0.0 } progressLogger := New("Wrote", testLog) for _, test := range tests { if test.reset { progressLogger = New("Wrote", testLog) } progressLogger.SetLastLogTime(test.inputLastLogTime) - progressLogger.LogProgress(test.inputBlock, test.forceLog) + progressLogger.LogProgress(test.inputBlock, test.forceLog, progressFn) wantBlockProgressLogger := &Logger{ receivedBlocks: test.wantReceivedBlocks, receivedTxns: test.wantReceivedTxns,