Local gas

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/genesis.go

@@ -400,7 +400,7 @@ func DefaultOrchardGenesisBlock() *Genesis {
 		Config:     params.OrchardChainConfig,
 		Nonce:      68,
 		ExtraData:  hexutil.MustDecode("0x3535353535353535353535353535353535353535353535353535353535353535"),
-		GasLimit:   []uint64{1000000, 1000000, 1000000},
+		GasLimit:   []uint64{40000000, 40000000, 40000000},
 		Difficulty: big.NewInt(2048576),
 		Alloc:      decodePrealloc(orchardAllocData),
 	}
@@ -424,7 +424,7 @@ func DefaultLocalGenesisBlock() *Genesis {
 		Config:     params.LocalChainConfig,
 		Nonce:      67,
 		ExtraData:  hexutil.MustDecode("0x3535353535353535353535353535353535353535353535353535353535353535"),
-		GasLimit:   []uint64{1000000, 1000000, 1000000},
+		GasLimit:   []uint64{40000000, 40000000, 40000000},
 		Difficulty: big.NewInt(300000),
 		Alloc:      decodePrealloc(localAllocData),
 	}

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/rawdb/database.go

@@ -309,6 +309,7 @@ func InspectDatabase(db ethdb.Database, keyPrefix, keyStart []byte) error {
 		ancientReceiptsSize common.StorageSize
 		ancientTdsSize      common.StorageSize
 		ancientHashesSize   common.StorageSize
+		ancientEtxSetSize   common.StorageSize
 
 		// Les statistic
 		chtTrieNodes   stat
@@ -392,7 +393,7 @@ func InspectDatabase(db ethdb.Database, keyPrefix, keyStart []byte) error {
 		}
 	}
 	// Inspect append-only file store then.
-	ancientSizes := []*common.StorageSize{&ancientHeadersSize, &ancientBodiesSize, &ancientReceiptsSize, &ancientHashesSize, &ancientTdsSize}
+	ancientSizes := []*common.StorageSize{&ancientHeadersSize, &ancientBodiesSize, &ancientReceiptsSize, &ancientHashesSize, &ancientTdsSize, &ancientEtxSetSize}
 	for i, category := range []string{freezerHeaderTable, freezerBodiesTable, freezerReceiptTable, freezerHashTable, freezerDifficultyTable, freezerEtxSetsTable} {
 		if size, err := db.AncientSize(category); err == nil {
 			*ancientSizes[i] += common.StorageSize(size)
@@ -425,6 +426,7 @@ func InspectDatabase(db ethdb.Database, keyPrefix, keyStart []byte) error {
 		{"Ancient store", "Receipt lists", ancientReceiptsSize.String(), ancients.String()},
 		{"Ancient store", "Difficulties", ancientTdsSize.String(), ancients.String()},
 		{"Ancient store", "Block number->hash", ancientHashesSize.String(), ancients.String()},
+		{"Ancient store", "etx set", ancientEtxSetSize.String(), ancients.String()},
 		{"Light client", "CHT trie nodes", chtTrieNodes.Size(), chtTrieNodes.Count()},
 		{"Light client", "Bloom trie nodes", bloomTrieNodes.Size(), bloomTrieNodes.Count()},
 	}

core/slice.go

@@ -107,6 +107,8 @@ func NewSlice(db ethdb.Database, config *Config, txConfig *TxPoolConfig, isLocal
 		return nil, err
 	}
 
+	rawdb.InspectDatabase(sl.sliceDb, []byte("h"), []byte("h"))
+
 	return sl, nil
 }
 
@@ -136,27 +138,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 +175,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 +203,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 +219,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 +254,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,12 @@ func (p *StateProcessor) Apply(batch ethdb.Batch, block *types.Block, newInbound
 				}
 				triedb.Dereference(root.(common.Hash))
 			}
+			time11 = common.PrettyDuration(time.Since(start))
 		}
 	}
+	time12 := common.PrettyDuration(time.Since(start))
 	rawdb.WriteEtxSet(p.hc.bc.db, block.Hash(), block.NumberU64(), etxSet)
-
+	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/downloader/downloader.go

@@ -1012,7 +1012,9 @@ func (d *Downloader) fetchParts(deliveryCh chan dataPack, deliver func(dataPack)
 				if request.From > 0 {
 					peer.log.Trace("Requesting new batch of data", "type", kind, "from", request.From)
 				} else {
-					peer.log.Trace("Requesting new batch of data", "type", kind, "count", len(request.Headers), "from", request.Headers[0].Number())
+					if len(request.Headers) != 0 {
+						peer.log.Trace("Requesting new batch of data", "type", kind, "count", len(request.Headers), "from", request.Headers[0].Number())
+					}
 				}
 				// Fetch the chunk and make sure any errors return the hashes to the queue
 				if fetchHook != nil {