common, core: add block age into info logs #17718 (#947)

common/format.go

@@ -17,6 +17,7 @@
 package common
 
 import (
+	"fmt"
 	"regexp"
 	"strings"
 	"time"
@@ -37,3 +38,45 @@ func (d PrettyDuration) String() string {
 	}
 	return label
 }
+
+// PrettyAge is a pretty printed version of a time.Duration value that rounds
+// the values up to a single most significant unit, days/weeks/years included.
+type PrettyAge time.Time
+
+// ageUnits is a list of units the age pretty printing uses.
+var ageUnits = []struct {
+	Size   time.Duration
+	Symbol string
+}{
+	{12 * 30 * 24 * time.Hour, "y"},
+	{30 * 24 * time.Hour, "mo"},
+	{7 * 24 * time.Hour, "w"},
+	{24 * time.Hour, "d"},
+	{time.Hour, "h"},
+	{time.Minute, "m"},
+	{time.Second, "s"},
+}
+
+// String implements the Stringer interface, allowing pretty printing of duration
+// values rounded to the most significant time unit.
+func (t PrettyAge) String() string {
+	// Calculate the time difference and handle the 0 cornercase
+	diff := time.Since(time.Time(t))
+	if diff < time.Second {
+		return "0"
+	}
+	// Accumulate a precision of 3 components before returning
+	result, prec := "", 0
+
+	for _, unit := range ageUnits {
+		if diff > unit.Size {
+			result = fmt.Sprintf("%s%d%s", result, diff/unit.Size, unit.Symbol)
+			diff %= unit.Size
+
+			if prec += 1; prec >= 3 {
+				break
+			}
+		}
+	}
+	return result
+}

core/blockchain.go

@@ -421,9 +421,9 @@ func (bc *BlockChain) loadLastState() error {
 	blockTd := bc.GetTd(currentBlock.Hash(), currentBlock.NumberU64())
 	fastTd := bc.GetTd(currentFastBlock.Hash(), currentFastBlock.NumberU64())
 
-	log.Info("Loaded most recent local header", "number", currentHeader.Number, "hash", currentHeader.Hash(), "td", headerTd)
+	log.Info("Loaded most recent local header", "number", currentHeader.Number, "hash", currentHeader.Hash(), "td", headerTd, "age", common.PrettyAge(time.Unix(currentHeader.Time.Int64(), 0)))
-	log.Info("Loaded most recent local full block", "number", currentBlock.Number(), "hash", currentBlock.Hash(), "td", blockTd)
+	log.Info("Loaded most recent local full block", "number", currentBlock.Number(), "hash", currentBlock.Hash(), "td", blockTd, "age", common.PrettyAge(time.Unix(currentBlock.Time().Int64(), 0)))
-	log.Info("Loaded most recent local fast block", "number", currentFastBlock.Number(), "hash", currentFastBlock.Hash(), "td", fastTd)
+	log.Info("Loaded most recent local fast block", "number", currentFastBlock.Number(), "hash", currentFastBlock.Hash(), "td", fastTd, "age", common.PrettyAge(time.Unix(currentFastBlock.Time().Int64(), 0)))
 
 	return nil
 }
@@ -1308,13 +1308,16 @@ func (bc *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain [
 	}
 	bc.chainmu.Unlock()
 
-	log.Info("Imported new block receipts",
+	context := []interface{}{
-		"count", stats.processed,
+		"count", stats.processed, "elapsed", common.PrettyDuration(time.Since(start)),
-		"elapsed", common.PrettyDuration(time.Since(start)),
+		"number", head.Number(), "hash", head.Hash(), "age", common.PrettyAge(time.Unix(head.Time().Int64(), 0)),
-		"number", head.Number(),
-		"hash", head.Hash(),
 		"size", common.StorageSize(bytes),
-		"ignored", stats.ignored)
+	}
+	if stats.ignored > 0 {
+		context = append(context, []interface{}{"ignored", stats.ignored}...)
+	}
+	log.Info("Imported new block receipts", context...)
+
 	return 0, nil
 }
 
@@ -2288,8 +2291,13 @@ func (st *insertStats) report(chain []*types.Block, index int, dirty common.Stor
 		context := []interface{}{
 			"blocks", st.processed, "txs", txs, "mgas", float64(st.usedGas) / 1000000,
 			"elapsed", common.PrettyDuration(elapsed), "mgasps", float64(st.usedGas) * 1000 / float64(elapsed),
-			"number", end.Number(), "hash", end.Hash(), "dirty", dirty,
+			"number", end.Number(), "hash", end.Hash(),
 		}
+		if timestamp := time.Unix(end.Time().Int64(), 0); time.Since(timestamp) > time.Minute {
+			context = append(context, []interface{}{"age", common.PrettyAge(timestamp)}...)
+		}
+		context = append(context, []interface{}{"cache", dirty}...)
+
 		if st.queued > 0 {
 			context = append(context, []interface{}{"queued", st.queued}...)
 		}
@@ -2297,6 +2305,7 @@ func (st *insertStats) report(chain []*types.Block, index int, dirty common.Stor
 			context = append(context, []interface{}{"ignored", st.ignored}...)
 		}
 		log.Info("Imported new chain segment", context...)
+
 		*st = insertStats{startTime: now, lastIndex: index + 1}
 	}
 }

core/headerchain.go

@@ -299,8 +299,18 @@ func (hc *HeaderChain) InsertHeaderChain(chain []*types.Header, writeHeader WhCa
 	}
 	// Report some public statistics so the user has a clue what's going on
 	last := chain[len(chain)-1]
-	log.Info("Imported new block headers", "count", stats.processed, "elapsed", common.PrettyDuration(time.Since(start)),
+
-		"number", last.Number, "hash", last.Hash(), "ignored", stats.ignored)
+	context := []interface{}{
+		"count", stats.processed, "elapsed", common.PrettyDuration(time.Since(start)),
+		"number", last.Number, "hash", last.Hash(),
+	}
+	if timestamp := time.Unix(last.Time.Int64(), 0); time.Since(timestamp) > time.Minute {
+		context = append(context, []interface{}{"age", common.PrettyAge(timestamp)}...)
+	}
+	if stats.ignored > 0 {
+		context = append(context, []interface{}{"ignored", stats.ignored}...)
+	}
+	log.Info("Imported new block headers", context...)
 
 	return 0, nil
 }