From 64500ab0fa68bd2c45e2f5459462faaaa675cb28 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Szil=C3=A1gyi?= Date: Tue, 18 Oct 2016 11:18:07 +0300 Subject: [PATCH] common, core, eth/downloader: adjust import log formatting --- common/format.go | 40 ++++++++++++++++++++++++++++++++++++ core/blockchain.go | 39 ++++++++++++++++++++--------------- core/headerchain.go | 9 ++++++-- eth/downloader/downloader.go | 2 +- 4 files changed, 71 insertions(+), 19 deletions(-) create mode 100644 common/format.go diff --git a/common/format.go b/common/format.go new file mode 100644 index 000000000..119637d2e --- /dev/null +++ b/common/format.go @@ -0,0 +1,40 @@ +// Copyright 2016 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package common + +import ( + "fmt" + "regexp" + "strings" + "time" +) + +// PrettyDuration is a pretty printed version of a time.Duration value that cuts +// the unnecessary precision off from the formatted textual representation. +type PrettyDuration time.Duration + +var prettyDurationRe = regexp.MustCompile("\\.[0-9]+") + +// String implements the Stringer interface, allowing pretty printing of duration +// values rounded to three decimals. +func (d PrettyDuration) String() string { + label := fmt.Sprintf("%v", time.Duration(d)) + if match := prettyDurationRe.FindString(label); len(match) > 4 { + label = strings.Replace(label, match, match[:4], 1) + } + return label +} diff --git a/core/blockchain.go b/core/blockchain.go index 7657fce78..07a9e91f4 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -769,8 +769,12 @@ func (self *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain // Report some public statistics so the user has a clue what's going on first, last := blockChain[0], blockChain[len(blockChain)-1] - glog.V(logger.Info).Infof("imported %d receipt(s) (%d ignored) in %v. #%d [%x… / %x…]", stats.processed, stats.ignored, - time.Since(start), last.Number(), first.Hash().Bytes()[:4], last.Hash().Bytes()[:4]) + + ignored := "" + if stats.ignored > 0 { + ignored = fmt.Sprintf(" (%d ignored)", stats.ignored) + } + glog.V(logger.Info).Infof("imported %d receipts%s in %9v. #%d [%x… / %x…]", stats.processed, ignored, common.PrettyDuration(time.Since(start)), last.Number(), first.Hash().Bytes()[:4], last.Hash().Bytes()[:4]) return 0, nil } @@ -947,7 +951,7 @@ func (self *BlockChain) InsertChain(chain types.Blocks) (int, error) { switch status { case CanonStatTy: if glog.V(logger.Debug) { - glog.Infof("[%v] inserted block #%d (%d TXs %v G %d UNCs) (%x...). Took %v\n", time.Now().UnixNano(), block.Number(), len(block.Transactions()), block.GasUsed(), len(block.Uncles()), block.Hash().Bytes()[0:4], time.Since(bstart)) + glog.Infof("inserted block #%d [%x…] in %9v: %3d txs %7v gas %d uncles.", block.Number(), block.Hash().Bytes()[0:4], common.PrettyDuration(time.Since(bstart)), len(block.Transactions()), block.GasUsed(), len(block.Uncles())) } events = append(events, ChainEvent{block, block.Hash(), logs}) @@ -965,7 +969,7 @@ func (self *BlockChain) InsertChain(chain types.Blocks) (int, error) { } case SideStatTy: if glog.V(logger.Detail) { - glog.Infof("inserted forked block #%d (TD=%v) (%d TXs %d UNCs) (%x...). Took %v\n", block.Number(), block.Difficulty(), len(block.Transactions()), len(block.Uncles()), block.Hash().Bytes()[0:4], time.Since(bstart)) + glog.Infof("inserted forked block #%d [%x…] (TD=%v) in %9v: %3d txs %d uncles.", block.Number(), block.Hash().Bytes()[0:4], block.Difficulty(), common.PrettyDuration(time.Since(bstart)), len(block.Transactions()), len(block.Uncles())) } events = append(events, ChainSideEvent{block, logs}) @@ -991,24 +995,27 @@ type insertStats struct { startTime time.Time } -const ( - statsReportLimit = 1024 - statsReportTimeLimit = 8 * time.Second -) +// statsReportLimit is the time limit during import after which we always print +// out progress. This avoids the user wondering what's going on. +const statsReportLimit = 8 * time.Second // report prints statistics if some number of blocks have been processed // or more than a few seconds have passed since the last message. func (st *insertStats) report(chain []*types.Block, index int) { - limit := statsReportLimit - if index == len(chain)-1 { - limit = 0 // Always print a message for the last block. - } - now := time.Now() - duration := now.Sub(st.startTime) - if duration > statsReportTimeLimit || st.queued > limit || st.processed > limit || st.ignored > limit { + var ( + now = time.Now() + elapsed = now.Sub(st.startTime) + ) + if index == len(chain)-1 || elapsed >= statsReportLimit { start, end := chain[st.lastIndex], chain[index] txcount := countTransactions(chain[st.lastIndex : index+1]) - glog.Infof("imported %d block(s) (%d queued %d ignored) including %d txs in %v. #%v [%x / %x]\n", st.processed, st.queued, st.ignored, txcount, duration, end.Number(), start.Hash().Bytes()[:4], end.Hash().Bytes()[:4]) + + extra := "" + if st.queued > 0 || st.ignored > 0 { + extra = fmt.Sprintf(" (%d queued %d ignored)", st.queued, st.ignored) + } + glog.Infof("imported %d blocks%s, %5d txs in %9v. #%v [%x… / %x…]\n", st.processed, extra, txcount, common.PrettyDuration(elapsed), end.Number(), start.Hash().Bytes()[:4], end.Hash().Bytes()[:4]) + *st = insertStats{startTime: now, lastIndex: index} } } diff --git a/core/headerchain.go b/core/headerchain.go index 0f9dd7208..8ca06d9b4 100644 --- a/core/headerchain.go +++ b/core/headerchain.go @@ -18,6 +18,7 @@ package core import ( crand "crypto/rand" + "fmt" "math" "math/big" mrand "math/rand" @@ -321,8 +322,12 @@ func (hc *HeaderChain) InsertHeaderChain(chain []*types.Header, checkFreq int, w } // Report some public statistics so the user has a clue what's going on first, last := chain[0], chain[len(chain)-1] - glog.V(logger.Info).Infof("imported %d header(s) (%d ignored) in %v. #%v [%x… / %x…]", stats.processed, stats.ignored, - time.Since(start), last.Number, first.Hash().Bytes()[:4], last.Hash().Bytes()[:4]) + + ignored := "" + if stats.ignored > 0 { + ignored = fmt.Sprintf(" (%d ignored)", stats.ignored) + } + glog.V(logger.Info).Infof("imported %d headers%s in %9v. #%v [%x… / %x…]", stats.processed, ignored, common.PrettyDuration(time.Since(start)), last.Number, first.Hash().Bytes()[:4], last.Hash().Bytes()[:4]) return 0, nil } diff --git a/eth/downloader/downloader.go b/eth/downloader/downloader.go index fb63757aa..526ecbeca 100644 --- a/eth/downloader/downloader.go +++ b/eth/downloader/downloader.go @@ -952,7 +952,7 @@ func (d *Downloader) fetchNodeData() error { // Log a message to the user and return if delivered > 0 { - glog.V(logger.Info).Infof("imported %d state entries in %v: processed %d, pending at least %d", delivered, time.Since(start), d.syncStatsStateDone, pending) + glog.V(logger.Info).Infof("imported %d state entries in %9v: processed %d, pending at least %d", delivered, common.PrettyDuration(time.Since(start)), d.syncStatsStateDone, pending) } }) }