Better benchmark

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)