Better benchmark

* In kaspaminer, don't crash on submitBlock timeout.

* Make timeout messages have a log level of Warn.

* Wait for a second after receiving a reject for IBD.

Co-authored-by: Elichai Turkel <elichai.turkel@gmail.com>

app/protocol/flows/testing/handle_relay_invs_test.go

@@ -1411,8 +1411,8 @@ func TestHandleRelayInvs(t *testing.T) {
 					select {
 					case err := <-errChan:
 						checkFlowError(t, err, test.expectsProtocolError, test.expectsBan, test.expectsErrToContain)
-					case <-time.After(time.Second):
-						t.Fatalf("waiting for error timed out after %s", time.Second)
+					case <-time.After(10 * time.Second):
+						t.Fatalf("waiting for error timed out after %s", 10*time.Second)
 					}
 				}
 

cmd/kaspaminer/mineloop.go

@@ -117,8 +117,14 @@ func handleFoundBlock(client *minerClient, block *externalapi.DomainBlock) error
 
 	rejectReason, err := client.SubmitBlock(block)
 	if err != nil {
+		if nativeerrors.Is(err, router.ErrTimeout) {
+			log.Warnf("Got timeout while submitting block %s to %s: %s", blockHash, client.Address(), err)
+			return nil
+		}
 		if rejectReason == appmessage.RejectReasonIsInIBD {
-			log.Warnf("Block %s was rejected because the node is in IBD", blockHash)
+			const waitTime = 1 * time.Second
+			log.Warnf("Block %s was rejected because the node is in IBD. Waiting for %s", blockHash, waitTime)
+			time.Sleep(waitTime)
 			return nil
 		}
 		return errors.Errorf("Error submitting block %s to %s: %s", blockHash, client.Address(), err)
@@ -152,7 +158,7 @@ func templatesLoop(client *minerClient, miningAddr util.Address,
 	getBlockTemplate := func() {
 		template, err := client.GetBlockTemplate(miningAddr.String())
 		if nativeerrors.Is(err, router.ErrTimeout) {
-			log.Infof("Got timeout while requesting block template from %s", client.Address())
+			log.Warnf("Got timeout while requesting block template from %s: %s", client.Address(), err)
 			return
 		} else if err != nil {
 			errChan <- errors.Errorf("Error getting block template from %s: %s", client.Address(), err)

domain/consensus/model/testapi/test_consensus.go

@@ -8,6 +8,20 @@ import (
 	"io"
 )
 
+// MineJSONBlockType indicates which type of blocks MineJSON mines
+type MineJSONBlockType int
+
+const (
+	// MineJSONBlockTypeUTXOValidBlock indicates for MineJSON to mine valid blocks.
+	MineJSONBlockTypeUTXOValidBlock MineJSONBlockType = iota
+
+	// MineJSONBlockTypeUTXOInvalidBlock indicates for MineJSON to mine UTXO invalid blocks.
+	MineJSONBlockTypeUTXOInvalidBlock
+
+	// MineJSONBlockTypeUTXOInvalidHeader indicates for MineJSON to mine UTXO invalid headers.
+	MineJSONBlockTypeUTXOInvalidHeader
+)
+
 // TestConsensus wraps the Consensus interface with some methods that are needed by tests only
 type TestConsensus interface {
 	externalapi.Consensus
@@ -33,7 +47,7 @@ type TestConsensus interface {
 	AddUTXOInvalidBlock(parentHashes []*externalapi.DomainHash) (*externalapi.DomainHash,
 		*externalapi.BlockInsertionResult, error)
 
-	MineJSON(r io.Reader) (tips []*externalapi.DomainHash, err error)
+	MineJSON(r io.Reader, blockType MineJSONBlockType) (tips []*externalapi.DomainHash, err error)
 	DiscardAllStores()
 
 	AcceptanceDataStore() model.AcceptanceDataStore

domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go

@@ -4,6 +4,7 @@ import (
 	"github.com/kaspanet/kaspad/domain/consensus/utils/consensushashing"
 	"github.com/kaspanet/kaspad/domain/consensus/utils/multiset"
 	"github.com/kaspanet/kaspad/domain/consensus/utils/utxo"
+	"github.com/kaspanet/kaspad/infrastructure/logger"
 	"github.com/pkg/errors"
 
 	"github.com/kaspanet/kaspad/domain/consensus/model"
@@ -15,8 +16,10 @@ import (
 func (csm *consensusStateManager) CalculatePastUTXOAndAcceptanceData(blockHash *externalapi.DomainHash) (
 	model.UTXODiff, externalapi.AcceptanceData, model.Multiset, error) {
 
+	onEnd := logger.LogAndMeasureExecutionTime(log, "CalculatePastUTXOAndAcceptanceData")
+	defer onEnd()
+
 	log.Debugf("CalculatePastUTXOAndAcceptanceData start for block %s", blockHash)
-	defer log.Debugf("CalculatePastUTXOAndAcceptanceData end for block %s", blockHash)
 
 	if blockHash.Equal(csm.genesisHash) {
 		log.Debugf("Block %s is the genesis. By definition, "+
@@ -35,6 +38,9 @@ func (csm *consensusStateManager) CalculatePastUTXOAndAcceptanceData(blockHash *
 	if err != nil {
 		return nil, nil, nil, err
 	}
+	log.Debugf("Restored the past UTXO of block %s with selectedParent %s. "+
+		"Diff toAdd length: %d, toRemove length: %d", blockHash, blockGHOSTDAGData.SelectedParent(),
+		selectedParentPastUTXO.ToAdd().Len(), selectedParentPastUTXO.ToRemove().Len())
 
 	log.Debugf("Applying blue blocks to the selected parent past UTXO of block %s", blockHash)
 	acceptanceData, utxoDiff, err := csm.applyMergeSetBlocks(blockHash, selectedParentPastUTXO, blockGHOSTDAGData)
@@ -53,8 +59,10 @@ func (csm *consensusStateManager) CalculatePastUTXOAndAcceptanceData(blockHash *
 }
 
 func (csm *consensusStateManager) restorePastUTXO(blockHash *externalapi.DomainHash) (model.MutableUTXODiff, error) {
+	onEnd := logger.LogAndMeasureExecutionTime(log, "restorePastUTXO")
+	defer onEnd()
+
 	log.Debugf("restorePastUTXO start for block %s", blockHash)
-	defer log.Debugf("restorePastUTXO end for block %s", blockHash)
 
 	var err error
 
@@ -110,8 +118,10 @@ func (csm *consensusStateManager) applyMergeSetBlocks(blockHash *externalapi.Dom
 	selectedParentPastUTXODiff model.MutableUTXODiff, ghostdagData *model.BlockGHOSTDAGData) (
 	externalapi.AcceptanceData, model.MutableUTXODiff, error) {
 
+	onEnd := logger.LogAndMeasureExecutionTime(log, "applyMergeSetBlocks")
+	defer onEnd()
+
 	log.Debugf("applyMergeSetBlocks start for block %s", blockHash)
-	defer log.Tracef("applyMergeSetBlocks end for block %s", blockHash)
 
 	mergeSetHashes := ghostdagData.MergeSet()
 	log.Debugf("Merge set for block %s is %v", blockHash, mergeSetHashes)

domain/consensus/processes/consensusstatemanager/pick_virtual_parents.go

@@ -1,6 +1,7 @@
 package consensusstatemanager
 
 import (
+	"github.com/kaspanet/kaspad/infrastructure/logger"
 	"github.com/pkg/errors"
 
 	"github.com/kaspanet/kaspad/domain/consensus/model"
@@ -9,8 +10,10 @@ import (
 )
 
 func (csm *consensusStateManager) pickVirtualParents(tips []*externalapi.DomainHash) ([]*externalapi.DomainHash, error) {
+	onEnd := logger.LogAndMeasureExecutionTime(log, "pickVirtualParents")
+	defer onEnd()
+
 	log.Debugf("pickVirtualParents start for tips len: %d", len(tips))
-	defer log.Debugf("pickVirtualParents end for tips len: %d", len(tips))
 
 	log.Debugf("Pushing all tips into a DownHeap")
 	candidatesHeap := csm.dagTraversalManager.NewDownHeap()
@@ -84,8 +87,8 @@ func (csm *consensusStateManager) pickVirtualParents(tips []*externalapi.DomainH
 func (csm *consensusStateManager) selectVirtualSelectedParent(
 	candidatesHeap model.BlockHeap) (*externalapi.DomainHash, error) {
 
-	log.Tracef("selectVirtualSelectedParent start")
-	defer log.Tracef("selectVirtualSelectedParent end")
+	onEnd := logger.LogAndMeasureExecutionTime(log, "selectVirtualSelectedParent")
+	defer onEnd()
 
 	disqualifiedCandidates := hashset.New()
 
@@ -153,8 +156,8 @@ func (csm *consensusStateManager) selectVirtualSelectedParent(
 func (csm *consensusStateManager) mergeSetIncrease(
 	candidate *externalapi.DomainHash, selectedVirtualParents hashset.HashSet) (uint64, error) {
 
-	log.Tracef("mergeSetIncrease start")
-	defer log.Tracef("mergeSetIncrease end")
+	onEnd := logger.LogAndMeasureExecutionTime(log, "mergeSetIncrease")
+	defer onEnd()
 
 	visited := hashset.New()
 	queue := csm.dagTraversalManager.NewDownHeap()
@@ -204,8 +207,10 @@ func (csm *consensusStateManager) mergeSetIncrease(
 func (csm *consensusStateManager) boundedMergeBreakingParents(
 	parents []*externalapi.DomainHash) (hashset.HashSet, error) {
 
+	onEnd := logger.LogAndMeasureExecutionTime(log, "boundedMergeBreakingParents")
+	defer onEnd()
+
 	log.Tracef("boundedMergeBreakingParents start for parents: %s", parents)
-	defer log.Tracef("boundedMergeBreakingParents end for parents: %s", parents)
 
 	log.Debug("Temporarily setting virtual to all parents, so that we can run ghostdag on it")
 	err := csm.dagTopologyManager.SetParents(model.VirtualBlockHash, parents)

domain/consensus/processes/consensusstatemanager/pick_virtual_parents_test.go

@@ -0,0 +1,117 @@
+package consensusstatemanager_test
+
+import (
+	"bytes"
+	"fmt"
+	"github.com/kaspanet/kaspad/domain/consensus"
+	"github.com/kaspanet/kaspad/domain/consensus/model/externalapi"
+	"github.com/kaspanet/kaspad/domain/consensus/utils/consensushashing"
+	"github.com/kaspanet/kaspad/domain/consensus/utils/testutils"
+	"github.com/kaspanet/kaspad/domain/dagconfig"
+	"github.com/kaspanet/kaspad/infrastructure/logger"
+	"io/ioutil"
+	"os/user"
+	"path"
+	"runtime/pprof"
+	"testing"
+	"time"
+)
+var log, _ = logger.Get(logger.SubsystemTags.CMGR)
+
+func TestPickVirtualParents(t *testing.T) {
+	usr, err := user.Current()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	const chainSize = 97
+
+	params := dagconfig.DevnetParams
+	params.SkipProofOfWork = true
+
+	factory := consensus.NewFactory()
+
+	var chains [10][]*externalapi.DomainBlock
+	// Build three chains over the genesis
+	for chainIndex := range chains {
+		func() {
+			tipHash := params.GenesisHash
+			builder, teardown, err := factory.NewTestConsensus(&params, false, fmt.Sprintf("TestPickVirtualParents: %d", chainIndex))
+			if err != nil {
+				t.Fatalf("Error setting up consensus: %+v", err)
+			}
+			defer teardown(false)
+			for blockIndex := 0; blockIndex < chainSize; blockIndex++ {
+				scriptPubKey, _ := testutils.OpTrueScript()
+				extraData := []byte{byte(chainIndex)}
+				block, _, err := builder.BuildBlockWithParents([]*externalapi.DomainHash{tipHash}, &externalapi.DomainCoinbaseData{scriptPubKey, extraData}, nil)
+				if err != nil {
+					t.Fatalf("Could not build block: %s", err)
+				}
+				_, err = builder.ValidateAndInsertBlock(block)
+				if err != nil {
+					t.Fatalf("Could not build block: %s", err)
+				}
+				chains[chainIndex] = append(chains[chainIndex], block)
+				tipHash = consensushashing.BlockHash(block)
+			}
+			fmt.Printf("Finished Building chain: %d\n", chainIndex)
+		}()
+	}
+
+
+	testConsensus, teardown, err := factory.NewTestConsensus(&params, false, "TestPickVirtualParents")
+	if err != nil {
+		t.Fatalf("Error setting up consensus: %+v", err)
+	}
+	defer teardown(false)
+
+	var maxTime time.Duration
+	var maxString string
+	var profName string
+	maxProf := make([]byte, 0, 1024)
+	// Build three chains over the genesis
+	buf := bytes.NewBuffer(make([]byte, 0, 1024))
+	for chainIndex, chain := range chains {
+		accumulatedValidationTime := time.Duration(0)
+		for blockIndex, block := range chain {
+			if chainIndex == 9 && blockIndex > 90 {
+				logger.InitLog(path.Join(usr.HomeDir, "TestPickVirtualParents.log"), path.Join(usr.HomeDir, "TestPickVirtualParents_err.log"))
+				logger.SetLogLevels("debug")
+			}
+			log.Debugf("Starting chain:#%d, block: #%d", chainIndex, blockIndex)
+			blockHash := consensushashing.BlockHash(block)
+			buf.Reset()
+			err = pprof.StartCPUProfile(buf)
+			if err != nil {
+				t.Fatal(err)
+			}
+			start := time.Now()
+			_, err := testConsensus.ValidateAndInsertBlock(block)
+			validationTime := time.Since(start)
+			pprof.StopCPUProfile()
+			if err != nil {
+				t.Fatalf("Failed to validate block %s: %s", blockHash, err)
+			}
+			if validationTime > maxTime {
+				maxTime = validationTime
+				maxString = fmt.Sprintf("Chain: %d, Block: %d", chainIndex, blockIndex)
+				profName = fmt.Sprintf("TestPickVirtualParents-chain-%d-block-%d.pprof", chainIndex, blockIndex)
+				maxProf = append(maxProf[:0], buf.Bytes()...)
+			}
+
+			accumulatedValidationTime += validationTime
+			log.Debugf("Validated block #%d in chain #%d, took %s\n", blockIndex, chainIndex, validationTime)
+
+		}
+
+		averageValidationTime := accumulatedValidationTime / chainSize
+		fmt.Printf("Average validation time for chain #%d: %s\n", chainIndex, averageValidationTime)
+	}
+
+	err = ioutil.WriteFile(path.Join(usr.HomeDir, profName), maxProf, 0644)
+	if err != nil {
+		t.Fatal(err)
+	}
+	fmt.Printf("%s, took: %s\n", maxString, maxTime)
+}

domain/consensus/processes/consensusstatemanager/update_virtual.go

@@ -3,13 +3,16 @@ package consensusstatemanager
 import (
 	"github.com/kaspanet/kaspad/domain/consensus/model"
 	"github.com/kaspanet/kaspad/domain/consensus/model/externalapi"
+	"github.com/kaspanet/kaspad/infrastructure/logger"
 )
 
 func (csm *consensusStateManager) updateVirtual(newBlockHash *externalapi.DomainHash,
 	tips []*externalapi.DomainHash) (*externalapi.SelectedChainPath, error) {
 
+	onEnd := logger.LogAndMeasureExecutionTime(log, "updateVirtual")
+	defer onEnd()
+
 	log.Debugf("updateVirtual start for block %s", newBlockHash)
-	defer log.Debugf("updateVirtual end for block %s", newBlockHash)
 
 	log.Debugf("Saving a reference to the GHOSTDAG data of the old virtual")
 	var oldVirtualSelectedParent *externalapi.DomainHash
@@ -44,6 +47,9 @@ func (csm *consensusStateManager) updateVirtual(newBlockHash *externalapi.Domain
 	if err != nil {
 		return nil, err
 	}
+	log.Debugf("Calculated the past UTXO of the new virtual. "+
+		"Diff toAdd length: %d, toRemove length: %d",
+		virtualUTXODiff.ToAdd().Len(), virtualUTXODiff.ToRemove().Len())
 
 	log.Debugf("Staging new acceptance data for the virtual block")
 	csm.acceptanceDataStore.Stage(model.VirtualBlockHash, virtualAcceptanceData)
@@ -73,6 +79,8 @@ func (csm *consensusStateManager) updateVirtual(newBlockHash *externalapi.Domain
 		if err != nil {
 			return nil, err
 		}
+		log.Debugf("Selected parent chain changes: %d blocks were removed and %d blocks were added",
+			len(selectedParentChainChanges.Removed), len(selectedParentChainChanges.Added))
 	}
 
 	return selectedParentChainChanges, nil

domain/consensus/processes/ghostdagmanager/compare.go

@@ -3,9 +3,13 @@ package ghostdagmanager
 import (
 	"github.com/kaspanet/kaspad/domain/consensus/model"
 	"github.com/kaspanet/kaspad/domain/consensus/model/externalapi"
+	"github.com/kaspanet/kaspad/infrastructure/logger"
 )
 
 func (gm *ghostdagManager) findSelectedParent(parentHashes []*externalapi.DomainHash) (*externalapi.DomainHash, error) {
+	onEnd := logger.LogAndMeasureExecutionTime(log, "ghostdagManager.findSelectedParent")
+	defer onEnd()
+
 	var selectedParent *externalapi.DomainHash
 	for _, hash := range parentHashes {
 		if selectedParent == nil {

domain/consensus/processes/ghostdagmanager/ghostdag.go

@@ -3,6 +3,7 @@ package ghostdagmanager
 import (
 	"github.com/kaspanet/kaspad/domain/consensus/model"
 	"github.com/kaspanet/kaspad/domain/consensus/model/externalapi"
+	"github.com/kaspanet/kaspad/infrastructure/logger"
 	"github.com/kaspanet/kaspad/util/difficulty"
 	"github.com/pkg/errors"
 	"math/big"
@@ -40,6 +41,9 @@ func (bg *blockGHOSTDAGData) toModel() *model.BlockGHOSTDAGData {
 //
 // For further details see the article https://eprint.iacr.org/2018/104.pdf
 func (gm *ghostdagManager) GHOSTDAG(blockHash *externalapi.DomainHash) error {
+	onEnd := logger.LogAndMeasureExecutionTime(log, "GHOSTDAG")
+	defer onEnd()
+
 	newBlockData := &blockGHOSTDAGData{
 		blueWork:           new(big.Int),
 		mergeSetBlues:      make([]*externalapi.DomainHash, 0),
@@ -69,6 +73,7 @@ func (gm *ghostdagManager) GHOSTDAG(blockHash *externalapi.DomainHash) error {
 		return err
 	}
 
+	onMergeSetWithoutSelectedParentEnd := logger.LogAndMeasureExecutionTime(log, "GHOSTDAG.mergeSetWithoutSelectedParent")
 	for _, blueCandidate := range mergeSetWithoutSelectedParent {
 		isBlue, candidateAnticoneSize, candidateBluesAnticoneSizes, err := gm.checkBlueCandidate(newBlockData.toModel(), blueCandidate)
 		if err != nil {
@@ -86,6 +91,7 @@ func (gm *ghostdagManager) GHOSTDAG(blockHash *externalapi.DomainHash) error {
 			newBlockData.mergeSetReds = append(newBlockData.mergeSetReds, blueCandidate)
 		}
 	}
+	onMergeSetWithoutSelectedParentEnd()
 
 	if !isGenesis {
 		selectedParentGHOSTDAGData, err := gm.ghostdagDataStore.Get(gm.databaseContext, newBlockData.selectedParent)

domain/consensus/processes/ghostdagmanager/log.go

@@ -0,0 +1,7 @@
+package ghostdagmanager
+
+import (
+	"github.com/kaspanet/kaspad/infrastructure/logger"
+)
+
+var log, _ = logger.Get(logger.SubsystemTags.BDAG)

domain/consensus/processes/reachabilitymanager/reachability_stretch_test.go

@@ -54,7 +54,7 @@ func buildJsonDAG(t *testing.T, tc testapi.TestConsensus, attackJson bool) (tips
 	}
 	defer gzipReader.Close()
 
-	tips, err = tc.MineJSON(gzipReader)
+	tips, err = tc.MineJSON(gzipReader, testapi.MineJSONBlockTypeUTXOInvalidHeader)
 	if err != nil {
 		t.Fatal(err)
 	}

domain/consensus/test_consensus.go

@@ -106,7 +106,7 @@ func (tc *testConsensus) AddUTXOInvalidBlock(parentHashes []*externalapi.DomainH
 	return consensushashing.BlockHash(block), blockInsertionResult, nil
 }
 
-func (tc *testConsensus) MineJSON(r io.Reader) (tips []*externalapi.DomainHash, err error) {
+func (tc *testConsensus) MineJSON(r io.Reader, blockType testapi.MineJSONBlockType) (tips []*externalapi.DomainHash, err error) {
 	// jsonBlock is a json representation of a block in mine format
 	type jsonBlock struct {
 		ID      string   `json:"id"`
@@ -145,10 +145,28 @@ func (tc *testConsensus) MineJSON(r io.Reader) (tips []*externalapi.DomainHash,
 			}
 			delete(tipSet, *parentHashes[i])
 		}
-		blockHash, _, err := tc.AddUTXOInvalidHeader(parentHashes)
-		if err != nil {
-			return nil, err
+
+		var blockHash *externalapi.DomainHash
+		switch blockType {
+		case testapi.MineJSONBlockTypeUTXOValidBlock:
+			blockHash, _, err = tc.AddBlock(parentHashes, nil, nil)
+			if err != nil {
+				return nil, err
+			}
+		case testapi.MineJSONBlockTypeUTXOInvalidBlock:
+			blockHash, _, err = tc.AddUTXOInvalidBlock(parentHashes)
+			if err != nil {
+				return nil, err
+			}
+		case testapi.MineJSONBlockTypeUTXOInvalidHeader:
+			blockHash, _, err = tc.AddUTXOInvalidHeader(parentHashes)
+			if err != nil {
+				return nil, err
+			}
+		default:
+			return nil, errors.Errorf("unknwon block type %v", blockType)
 		}
+
 		parentsMap[block.ID] = blockHash
 		tipSet[*blockHash] = blockHash
 	}

infrastructure/network/netadapter/server/grpcserver/grpc_server.go

@@ -9,6 +9,7 @@ import (
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/peer"
 	"net"
+	"time"
 )
 
 type gRPCServer struct {
@@ -61,7 +62,20 @@ func (s *gRPCServer) listenOn(listenAddr string) error {
 }
 
 func (s *gRPCServer) Stop() error {
-	s.server.GracefulStop()
+	const stopTimeout = 2 * time.Second
+
+	stopChan := make(chan interface{})
+	spawn("gRPCServer.Stop", func() {
+		s.server.GracefulStop()
+		close(stopChan)
+	})
+
+	select {
+	case <-stopChan:
+	case <-time.After(stopTimeout):
+		log.Warnf("Could not gracefully stop %s: timed out after %s", s.name, stopTimeout)
+		s.server.Stop()
+	}
 	return nil
 }