cmd/geth, trie: track and report trie cache misses

cmd/geth/chaincmd.go

@@ -31,6 +31,7 @@ import (
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/ethdb"
 	"github.com/ethereum/go-ethereum/logger/glog"
+	"github.com/ethereum/go-ethereum/trie"
 	"github.com/syndtr/goleveldb/leveldb/util"
 	"gopkg.in/urfave/cli.v1"
 )
@@ -89,21 +90,30 @@ func importChain(ctx *cli.Context) error {
 	if err := utils.ImportChain(chain, ctx.Args().First()); err != nil {
 		utils.Fatalf("Import error: %v", err)
 	}
-	fmt.Printf("Import done in %v, compacting...\n", time.Since(start))
+	fmt.Printf("Import done in %v.\n", time.Since(start))
 
-	// Compact the entire database to more accurately measure disk io and print the stats
 	if db, ok := chainDb.(*ethdb.LDBDatabase); ok {
-		start = time.Now()
-		if err := db.LDB().CompactRange(util.Range{}); err != nil {
-			utils.Fatalf("Compaction failed: %v", err)
-		}
-		fmt.Printf("Compaction done in %v.\n", time.Since(start))
-
+		// Output pre-compaction stats mostly to see the import trashing
 		stats, err := db.LDB().GetProperty("leveldb.stats")
 		if err != nil {
 			utils.Fatalf("Failed to read database stats: %v", err)
 		}
 		fmt.Println(stats)
+
+		// Compact the entire database to more accurately measure disk io and print the stats
+		start = time.Now()
+		fmt.Println("Compacting entire database...")
+		if err = db.LDB().CompactRange(util.Range{}); err != nil {
+			utils.Fatalf("Compaction failed: %v", err)
+		}
+		fmt.Printf("Compaction done in %v.\n", time.Since(start))
+
+		stats, err = db.LDB().GetProperty("leveldb.stats")
+		if err != nil {
+			utils.Fatalf("Failed to read database stats: %v", err)
+		}
+		fmt.Println(stats)
+		fmt.Println("Trie cache misses:", trie.CacheMisses())
 	}
 	return nil
 }

trie/trie.go

@@ -20,6 +20,7 @@ package trie
 import (
 	"bytes"
 	"fmt"
+	"sync/atomic"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/crypto/sha3"
@@ -34,6 +35,17 @@ var (
 	emptyState common.Hash
 )
 
+// cacheMisses maintains the number of times a trie node was loaded from disk.
+// Always use atomic operations when accessing this global variable.
+var cacheMisses uint64
+
+// CacheMisses retrieves a global counter measuring the number of cache misses
+// the trie did since process startup. This isn't useful for anything apart from
+// trie debugging purposes.
+func CacheMisses() uint64 {
+	return atomic.LoadUint64(&cacheMisses)
+}
+
 func init() {
 	sha3.NewKeccak256().Sum(emptyState[:0])
 }
@@ -419,6 +431,8 @@ func (t *Trie) resolve(n node, prefix, suffix []byte) (node, error) {
 }
 
 func (t *Trie) resolveHash(n hashNode, prefix, suffix []byte) (node, error) {
+	atomic.AddUint64(&cacheMisses, 1)
+
 	enc, err := t.db.Get(n)
 	if err != nil || enc == nil {
 		return nil, &MissingNodeError{