Added prints to collect information about the append cycle

core/block_validator.go

@@ -18,11 +18,13 @@ package core
 
 import (
 	"fmt"
+	"time"
 
 	"github.com/dominant-strategies/go-quai/common"
 	"github.com/dominant-strategies/go-quai/consensus"
 	"github.com/dominant-strategies/go-quai/core/state"
 	"github.com/dominant-strategies/go-quai/core/types"
+	"github.com/dominant-strategies/go-quai/log"
 	"github.com/dominant-strategies/go-quai/params"
 	"github.com/dominant-strategies/go-quai/trie"
 )
@@ -93,27 +95,33 @@ func (v *BlockValidator) ValidateBody(block *types.Block) error {
 // itself. ValidateState returns a database batch if the validation was a success
 // otherwise nil and an error is returned.
 func (v *BlockValidator) ValidateState(block *types.Block, statedb *state.StateDB, receipts types.Receipts, usedGas uint64) error {
+	start := time.Now()
 	nodeCtx := common.NodeLocation.Context()
 	header := block.Header()
+	time1 := common.PrettyDuration(time.Since(start))
 	if block.GasUsed() != usedGas {
 		return fmt.Errorf("invalid gas used (remote: %d local: %d)", block.GasUsed(), usedGas)
 	}
+	time2 := common.PrettyDuration(time.Since(start))
 	// Validate the received block's bloom with the one derived from the generated receipts.
 	// For valid blocks this should always validate to true.
 	rbloom := types.CreateBloom(receipts)
 	if rbloom != header.Bloom() {
 		return fmt.Errorf("invalid bloom (remote: %x  local: %x)", header.Bloom(), rbloom)
 	}
+	time3 := common.PrettyDuration(time.Since(start))
 	// Tre receipt Trie's root (R = (Tr [[H1, R1], ... [Hn, Rn]]))
 	receiptSha := types.DeriveSha(receipts, trie.NewStackTrie(nil))
 	if receiptSha != header.ReceiptHash() {
 		return fmt.Errorf("invalid receipt root hash (remote: %x local: %x)", header.ReceiptHash(), receiptSha)
 	}
+	time4 := common.PrettyDuration(time.Since(start))
 	// Validate the state root against the received state root and throw
 	// an error if they don't match.
 	if root := statedb.IntermediateRoot(v.config.IsEIP158(header.Number())); header.Root() != root {
 		return fmt.Errorf("invalid merkle root (remote: %x local: %x)", header.Root(), root)
 	}
+	time5 := common.PrettyDuration(time.Since(start))
 	// Collect ETXs emitted from each successful transaction
 	var emittedEtxs types.Transactions
 	for _, receipt := range receipts {
@@ -123,22 +131,29 @@ func (v *BlockValidator) ValidateState(block *types.Block, statedb *state.StateD
 			}
 		}
 	}
+	time6 := common.PrettyDuration(time.Since(start))
 	// Confirm the ETXs emitted by the transactions in this block exactly match the
 	// ETXs given in the block body
 	if etxHash := types.DeriveSha(emittedEtxs, trie.NewStackTrie(nil)); etxHash != header.EtxHash() {
 		return fmt.Errorf("invalid etx hash (remote: %x local: %x)", header.EtxHash(), etxHash)
 	}
+	time7 := common.PrettyDuration(time.Since(start))
+	var time7_1 common.PrettyDuration
 	if nodeCtx > common.PRIME_CTX {
 		// Collect the ETX rollup with emitted ETXs since the last coincident block,
 		// excluding this block.
 		etxRollup, err := v.hc.CollectEtxRollup(block)
 		if err != nil {
 			return fmt.Errorf("unable to get ETX rollup")
 		}
+		time7_1 = common.PrettyDuration(time.Since(start))
 		if etxRollupHash := types.DeriveSha(etxRollup, trie.NewStackTrie(nil)); etxRollupHash != header.EtxRollupHash() {
 			return fmt.Errorf("invalid etx rollup hash (remote: %x local: %x)", header.EtxRollupHash(), etxRollupHash)
 		}
 	}
+	time8 := common.PrettyDuration(time.Since(start))
+	log.Info("times during validate state:", "t1:", time1, "t2:", time2, "t3:", time3, "t4:", time4, "t5:", time5, "t6:", time6, "t7:", time7, "t7_1:", time7_1, "t8:", time8)
+
 	return nil
 }
 

core/bodydb.go

@@ -3,6 +3,7 @@ package core
 import (
 	"errors"
 	"sync"
+	"time"
 
 	"github.com/dominant-strategies/go-quai/common"
 	"github.com/dominant-strategies/go-quai/consensus"
@@ -67,11 +68,13 @@ func (bc *BodyDb) Append(batch ethdb.Batch, block *types.Block, newInboundEtxs t
 	bc.chainmu.Lock()
 	defer bc.chainmu.Unlock()
 
+	stateApply := time.Now()
 	// Process our block
 	logs, err := bc.processor.Apply(batch, block, newInboundEtxs)
 	if err != nil {
 		return nil, err
 	}
+	log.Info("Time taken to", "apply state:", common.PrettyDuration(time.Since(stateApply)))
 
 	if block.Hash() != block.Header().Hash() {
 		log.Info("BodyDb Append, Roots Mismatch:", "block.Hash:", block.Hash(), "block.Header.Hash", block.Header().Hash(), "parentHeader.Number:", block.NumberU64())

core/headerchain.go

@@ -187,6 +187,7 @@ func (hc *HeaderChain) Append(batch ethdb.Batch, block *types.Block, newInboundE
 		return err
 	}
 
+	collectBlockManifest := time.Now()
 	// Verify the manifest matches expected
 	// Load the manifest of blocks preceding this block
 	// note: prime manifest is non-existent, because a prime block cannot be
@@ -201,15 +202,18 @@ func (hc *HeaderChain) Append(batch ethdb.Batch, block *types.Block, newInboundE
 			return errors.New("manifest does not match hash")
 		}
 	}
+	elapsedCollectBlockManifest := common.PrettyDuration(time.Since(collectBlockManifest))
 
 	// Append header to the headerchain
 	rawdb.WriteHeader(batch, block.Header())
 
+	blockappend := time.Now()
 	// Append block else revert header append
 	logs, err := hc.bc.Append(batch, block, newInboundEtxs)
 	if err != nil {
 		return err
 	}
+	log.Info("Time taken to", "collectBlockManifest", elapsedCollectBlockManifest, "Append in bc", common.PrettyDuration(time.Since(blockappend)))
 
 	hc.bc.chainFeed.Send(ChainEvent{Block: block, Hash: block.Hash(), Logs: logs})
 	if len(logs) > 0 {

core/slice.go

@@ -136,27 +136,27 @@ func (sl *Slice) Append(header *types.Header, domPendingHeader *types.Header, do
 		log.Warn("Block has already been appended: ", "Hash: ", header.Hash())
 		return nil, ErrKnownBlock
 	}
-
+	time1 := common.PrettyDuration(time.Since(start))
 	// This is to prevent a crash when we try to insert blocks before domClient is on.
 	// Ideally this check should not exist here and should be fixed before we start the slice.
 	if sl.domClient == nil && nodeCtx != common.PRIME_CTX {
 		return nil, ErrDomClientNotUp
 	}
-
+	time2 := common.PrettyDuration(time.Since(start))
 	// Construct the block locally
 	block, err := sl.ConstructLocalBlock(header)
 	if err != nil {
 		return nil, err
 	}
-
+	time3 := common.PrettyDuration(time.Since(start))
 	batch := sl.sliceDb.NewBatch()
 
 	// Run Previous Coincident Reference Check (PCRC)
 	domTerminus, newTermini, err := sl.pcrc(batch, block.Header(), domTerminus, domOrigin)
 	if err != nil {
 		return nil, err
 	}
-
+	time4 := common.PrettyDuration(time.Since(start))
 	// If this was a coincident block, our dom will be passing us a set of newly confirmed ETXs
 	// If this is not a coincident block, we need to build up the list of confirmed ETXs using the subordinate manifest
 	subRollup := types.Transactions{}
@@ -173,23 +173,24 @@ func (sl *Slice) Append(header *types.Header, domPendingHeader *types.Header, do
 		}
 		subRollup = subRollups[nodeCtx+1]
 	}
+	time5 := common.PrettyDuration(time.Since(start))
 
 	// Append the new block
 	err = sl.hc.Append(batch, block, newInboundEtxs.FilterToLocation(common.NodeLocation))
 	if err != nil {
 		return nil, err
 	}
-
+	time6 := common.PrettyDuration(time.Since(start))
 	// Upate the local pending header
 	localPendingHeader, err := sl.miner.worker.GeneratePendingHeader(block)
 	if err != nil {
 		return nil, err
 	}
-
+	time7 := common.PrettyDuration(time.Since(start))
 	// Combine subordinates pending header with local pending header
 	pendingHeaderWithTermini := sl.computePendingHeader(types.PendingHeader{Header: localPendingHeader, Termini: newTermini}, domPendingHeader, domOrigin)
 	pendingHeaderWithTermini.Header.SetLocation(header.Location())
-
+	time8 := common.PrettyDuration(time.Since(start))
 	s := header.CalcS()
 
 	// Set the parent delta S prior to sending to sub
@@ -200,9 +201,11 @@ func (sl *Slice) Append(header *types.Header, domPendingHeader *types.Header, do
 			pendingHeaderWithTermini.Header.SetParentDeltaS(header.CalcDeltaS(), nodeCtx)
 		}
 	}
-
+	time9 := common.PrettyDuration(time.Since(start))
 	pendingHeaderWithTermini.Header.SetParentEntropy(s)
-
+	var time9_1 common.PrettyDuration
+	var time9_2 common.PrettyDuration
+	var time9_3 common.PrettyDuration
 	// Call my sub to append the block, and collect the rolled up ETXs from that sub
 	localPendingEtxs := []types.Transactions{types.Transactions{}, types.Transactions{}, types.Transactions{}}
 	subPendingEtxs := []types.Transactions{types.Transactions{}, types.Transactions{}, types.Transactions{}}
@@ -214,15 +217,18 @@ func (sl *Slice) Append(header *types.Header, domPendingHeader *types.Header, do
 			if err != nil {
 				return nil, err
 			}
+			time9_1 = common.PrettyDuration(time.Since(start))
 			// Cache the subordinate's pending ETXs
 			pEtxs := types.PendingEtxs{block.Header(), subPendingEtxs}
 			if !pEtxs.IsValid(trie.NewStackTrie(nil)) {
 				return nil, errors.New("sub pending ETXs faild validation")
 			}
+			time9_2 = common.PrettyDuration(time.Since(start))
 			sl.AddPendingEtxs(pEtxs)
+			time9_3 = common.PrettyDuration(time.Since(start))
 		}
 	}
-
+	time10 := common.PrettyDuration(time.Since(start))
 	log.Trace("Entropy Calculations", "header", header.Hash(), "S", common.BigBitsToBits(s), "DeltaS", common.BigBitsToBits(header.CalcDeltaS()), "IntrinsicS", common.BigBitsToBits(header.CalcIntrinsicS()))
 	// Combine sub's pending ETXs, sub rollup, and our local ETXs into localPendingEtxs
 	// e.g. localPendingEtxs[ctx]:
@@ -246,16 +252,19 @@ func (sl *Slice) Append(header *types.Header, domPendingHeader *types.Header, do
 	localPendingEtxs[nodeCtx] = make(types.Transactions, len(block.ExtTransactions()))
 	copy(localPendingEtxs[nodeCtx], block.ExtTransactions()) // Assign our new ETXs without rolling up
 
+	time11 := common.PrettyDuration(time.Since(start))
 	//Append has succeeded write the batch
 	if err := batch.Write(); err != nil {
 		return nil, err
 	}
-
+	time12 := common.PrettyDuration(time.Since(start))
 	sl.writeToPhCacheAndPickPhHead(pendingHeaderWithTermini)
 
 	// Relay the new pendingHeader
 	go sl.relayPh(pendingHeaderWithTermini, domOrigin, block.Location())
-
+	time13 := common.PrettyDuration(time.Since(start))
+	log.Info("times during append:", "t1:", time1, "t2:", time2, "t3:", time3, "t4:", time4, "t5:", time5, "t6:", time6, "t7:", time7, "t8:", time8, "t9:", time9, "t10:", time10, "t11:", time11, "t12:", time12, "t13:", time13)
+	log.Info("times during sub append:", "t9_1:", time9_1, "t9_2:", time9_2, "t9_3:", time9_3)
 	log.Info("Appended new block", "number", block.Header().Number(), "hash", block.Hash(),
 		"uncles", len(block.Uncles()), "txs", len(block.Transactions()), "etxs", len(block.ExtTransactions()), "gas", block.GasUsed(),
 		"root", block.Root(),

core/state_processor.go

@@ -291,43 +291,51 @@ var lastWrite uint64
 func (p *StateProcessor) Apply(batch ethdb.Batch, block *types.Block, newInboundEtxs types.Transactions) ([]*types.Log, error) {
 	// Update the set of inbound ETXs which may be mined. This adds new inbound
 	// ETXs to the set and removes expired ETXs so they are no longer available
+	start := time.Now()
 	etxSet := rawdb.ReadEtxSet(p.hc.bc.db, block.ParentHash(), block.NumberU64()-1)
+	time1 := common.PrettyDuration(time.Since(start))
 	if etxSet == nil {
 		return nil, errors.New("failed to load etx set")
 	}
 	etxSet.Update(newInboundEtxs, block.NumberU64())
-
+	time2 := common.PrettyDuration(time.Since(start))
 	// Process our block
 	receipts, logs, statedb, usedGas, err := p.Process(block, etxSet)
 	if err != nil {
 		return nil, err
 	}
-
+	time3 := common.PrettyDuration(time.Since(start))
 	err = p.validator.ValidateState(block, statedb, receipts, usedGas)
 	if err != nil {
 		return nil, err
 	}
-
+	time4 := common.PrettyDuration(time.Since(start))
 	rawdb.WriteReceipts(batch, block.Hash(), block.NumberU64(), receipts)
+	time5 := common.PrettyDuration(time.Since(start))
 	rawdb.WritePreimages(batch, statedb.Preimages())
-
+	time6 := common.PrettyDuration(time.Since(start))
 	// Commit all cached state changes into underlying memory database.
 	root, err := statedb.Commit(true)
 	if err != nil {
 		return nil, err
 	}
 	triedb := p.stateCache.TrieDB()
-
+	time7 := common.PrettyDuration(time.Since(start))
+	var time8 common.PrettyDuration
+	var time9 common.PrettyDuration
+	var time10 common.PrettyDuration
+	var time11 common.PrettyDuration
 	// If we're running an archive node, always flush
 	if p.cacheConfig.TrieDirtyDisabled {
 		if err := triedb.Commit(root, false, nil); err != nil {
 			return nil, err
 		}
+		time8 = common.PrettyDuration(time.Since(start))
 	} else {
 		// Full but not archive node, do proper garbage collection
 		triedb.Reference(root, common.Hash{}) // metadata reference to keep trie alive
 		p.triegc.Push(root, -int64(block.NumberU64()))
-
+		time8 = common.PrettyDuration(time.Since(start))
 		if current := block.NumberU64(); current > TriesInMemory {
 			// If we exceeded our memory allowance, flush matured singleton nodes to disk
 			var (
@@ -339,7 +347,7 @@ func (p *StateProcessor) Apply(batch ethdb.Batch, block *types.Block, newInbound
 			}
 			// Find the next state trie we need to commit
 			chosen := current - TriesInMemory
-
+			time9 = common.PrettyDuration(time.Since(start))
 			// If we exceeded out time allowance, flush an entire trie to disk
 			if p.gcproc > p.cacheConfig.TrieTimeLimit {
 				// If the header is missing (canonical chain behind), we're reorging a low
@@ -359,6 +367,7 @@ func (p *StateProcessor) Apply(batch ethdb.Batch, block *types.Block, newInbound
 					p.gcproc = 0
 				}
 			}
+			time10 = common.PrettyDuration(time.Since(start))
 			// Garbage collect anything below our required write retention
 			for !p.triegc.Empty() {
 				root, number := p.triegc.Pop()
@@ -368,10 +377,13 @@ func (p *StateProcessor) Apply(batch ethdb.Batch, block *types.Block, newInbound
 				}
 				triedb.Dereference(root.(common.Hash))
 			}
+			time11 = common.PrettyDuration(time.Since(start))
 		}
 	}
 	rawdb.WriteEtxSet(p.hc.bc.db, block.Hash(), block.NumberU64(), etxSet)
+	time12 := common.PrettyDuration(time.Since(start))
 
+	log.Info("times during state processor apply:", "t1:", time1, "t2:", time2, "t3:", time3, "t4:", time4, "t5:", time5, "t6:", time6, "t7:", time7, "t8:", time8, "t9:", time9, "t10:", time10, "t11:", time11, "t12:", time12)
 	return logs, nil
 }
 

eth/protocols/eth/handlers.go

@@ -293,21 +293,21 @@ func handleNewBlock(backend Backend, msg Decoder, peer *Peer) error {
 		return err
 	}
 	if hash := types.CalcUncleHash(ann.Block.Uncles()); hash != ann.Block.UncleHash() {
-		log.Warn("Propagated block has invalid uncles", "have", hash, "exp", ann.Block.UncleHash())
+		log.Warn("Propagated block has invalid uncles", "peer", peer.id, "block hash", ann.Block.Hash(), "have", hash, "exp", ann.Block.UncleHash())
 		return nil // TODO(karalabe): return error eventually, but wait a few releases
 	}
 	if hash := types.DeriveSha(ann.Block.Transactions(), trie.NewStackTrie(nil)); hash != ann.Block.TxHash() {
-		log.Warn("Propagated block has invalid transaction", "have", hash, "exp", ann.Block.TxHash())
+		log.Warn("Propagated block has invalid transaction", "peer", peer.id, "block hash", ann.Block.Hash(), "have", hash, "exp", ann.Block.TxHash())
 		return nil // TODO(karalabe): return error eventually, but wait a few releases
 	}
 	if hash := types.DeriveSha(ann.Block.ExtTransactions(), trie.NewStackTrie(nil)); hash != ann.Block.EtxHash() {
-		log.Warn("Propagated block has invalid external transaction", "have", hash, "exp", ann.Block.EtxHash())
+		log.Warn("Propagated block has invalid external transaction", "peer", peer.id, "block hash", ann.Block.Hash(), "have", hash, "exp", ann.Block.EtxHash())
 		return nil // TODO(karalabe): return error eventually, but wait a few releases
 	}
 	// Dom nodes need to validate the subordinate manifest against the subordinate's manifesthash
 	if nodeCtx < common.ZONE_CTX {
 		if hash := types.DeriveSha(ann.Block.SubManifest(), trie.NewStackTrie(nil)); hash != ann.Block.ManifestHash(nodeCtx+1) {
-			log.Warn("Propagated block has invalid subordinate manifest", "have", hash, "exp", ann.Block.ManifestHash())
+			log.Warn("Propagated block has invalid subordinate manifest", "peer", peer.id, "block hash", ann.Block.Hash(), "have", hash, "exp", ann.Block.ManifestHash())
 			return nil
 		}
 	}

internal/quaiapi/api.go

@@ -705,7 +705,7 @@ func DoEstimateGas(ctx context.Context, b Backend, args TransactionArgs, blockNr
 			if transfer == nil {
 				transfer = new(hexutil.Big)
 			}
-			log.Warn("Gas estimation capped by limited funds", "original", hi, "balance", balance,
+			log.Debug("Gas estimation capped by limited funds", "original", hi, "balance", balance,
 				"sent", transfer.ToInt(), "maxFeePerGas", feeCap, "fundable", allowance)
 			hi = allowance.Uint64()
 		}
@@ -1327,9 +1327,9 @@ func SubmitTransaction(ctx context.Context, b Backend, tx *types.Transaction) (c
 
 	if tx.To() == nil {
 		addr := crypto.CreateAddress(from, tx.Nonce(), tx.Data())
-		log.Info("Submitted contract creation", "hash", tx.Hash().Hex(), "from", from, "nonce", tx.Nonce(), "contract", addr.Hex(), "value", tx.Value())
+		log.Debug("Submitted contract creation", "hash", tx.Hash().Hex(), "from", from, "nonce", tx.Nonce(), "contract", addr.Hex(), "value", tx.Value())
 	} else {
-		log.Info("Submitted transaction", "hash", tx.Hash().Hex(), "from", from, "nonce", tx.Nonce(), "recipient", tx.To(), "value", tx.Value())
+		log.Debug("Submitted transaction", "hash", tx.Hash().Hex(), "from", from, "nonce", tx.Nonce(), "recipient", tx.To(), "value", tx.Value())
 	}
 	return tx.Hash(), nil
 }