diff --git a/core/block_validator.go b/core/block_validator.go index 66789dde5e..5a4f437f77 100644 --- a/core/block_validator.go +++ b/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,11 +131,14 @@ 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. @@ -135,10 +146,14 @@ func (v *BlockValidator) ValidateState(block *types.Block, statedb *state.StateD 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 } diff --git a/core/bodydb.go b/core/bodydb.go index 9fa2b4445d..fbf7e41961 100644 --- a/core/bodydb.go +++ b/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()) diff --git a/core/headerchain.go b/core/headerchain.go index 5ef8d7356a..3b4896e950 100644 --- a/core/headerchain.go +++ b/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 { diff --git a/core/slice.go b/core/slice.go index e18b398a32..ab35010166 100644 --- a/core/slice.go +++ b/core/slice.go @@ -136,19 +136,19 @@ 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) @@ -156,7 +156,7 @@ func (sl *Slice) Append(header *types.Header, domPendingHeader *types.Header, do 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(), diff --git a/core/state_processor.go b/core/state_processor.go index 48c72d2eef..a274ba5215 100644 --- a/core/state_processor.go +++ b/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 } diff --git a/eth/protocols/eth/handlers.go b/eth/protocols/eth/handlers.go index ba0b01d158..e0bc94d075 100644 --- a/eth/protocols/eth/handlers.go +++ b/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 } } diff --git a/internal/quaiapi/api.go b/internal/quaiapi/api.go index 42965d4ca8..53fc19680c 100644 --- a/internal/quaiapi/api.go +++ b/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 }