From f0b772f4d60e57d3fa28e7536045cabcc50b63ae Mon Sep 17 00:00:00 2001
From: stasatdaglabs <stas@daglabs.com>
Date: Sun, 31 Jan 2021 09:56:22 +0200
Subject: [PATCH] Add more logs, In TestPickVirtualParents, only print relevant
 logs.

---
 .../calculate_past_utxo.go                    |  4 +++-
 .../pick_virtual_parents_test.go              | 21 +++++++++++++++----
 .../processes/ghostdagmanager/ghostdag.go     |  4 ++++
 .../processes/ghostdagmanager/log.go          |  7 +++++++
 4 files changed, 31 insertions(+), 5 deletions(-)
 create mode 100644 domain/consensus/processes/ghostdagmanager/log.go

diff --git a/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go b/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go
index 3bf0328cf..fa7f5b5d3 100644
--- a/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go
+++ b/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go
@@ -118,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)
diff --git a/domain/consensus/processes/consensusstatemanager/pick_virtual_parents_test.go b/domain/consensus/processes/consensusstatemanager/pick_virtual_parents_test.go
index a163f4253..7d421bc8e 100644
--- a/domain/consensus/processes/consensusstatemanager/pick_virtual_parents_test.go
+++ b/domain/consensus/processes/consensusstatemanager/pick_virtual_parents_test.go
@@ -15,8 +15,6 @@ func TestPickVirtualParents(t *testing.T) {
 	params := dagconfig.DevnetParams
 	params.SkipProofOfWork = true
 
-	logger.SetLogLevels("debug")
-
 	factory := consensus.NewFactory()
 	testConsensus, teardown, err := factory.NewTestConsensus(&params, false, "TestPickVirtualParents")
 	if err != nil {
@@ -24,6 +22,8 @@ func TestPickVirtualParents(t *testing.T) {
 	}
 	defer teardown(false)
 
+	found := false
+
 	// Build three chains over the genesis
 	for chainIndex := 0; chainIndex < 3; chainIndex++ {
 		const chainSize = 1000
@@ -31,22 +31,35 @@ func TestPickVirtualParents(t *testing.T) {
 
 		tipHash := params.GenesisHash
 		for blockIndex := 0; blockIndex < chainSize; blockIndex++ {
-			fmt.Printf("\n\n\nBUILD BLOCK WITH PARENTS\n\n\n")
+			if found {
+				fmt.Printf("\n\n\nBUILD BLOCK WITH PARENTS\n\n\n")
+			}
 			block, _, err := testConsensus.BuildBlockWithParents([]*externalapi.DomainHash{tipHash}, nil, nil)
 			if err != nil {
 				t.Fatalf("Could not build block: %s", err)
 			}
 			blockHash := consensushashing.BlockHash(block)
 			start := time.Now()
-			fmt.Printf("\n\n\nVALIDATE AND INSERT BLOCK\n\n\n")
+			if found {
+				fmt.Printf("\n\n\nVALIDATE AND INSERT BLOCK\n\n\n")
+			}
 			_, err = testConsensus.ValidateAndInsertBlock(block)
 			if err != nil {
 				t.Fatalf("Failed to validate block %s: %s", blockHash, err)
 			}
 			validationTime := time.Since(start)
+
 			accumulatedValidationTime += validationTime
 			fmt.Printf("Validated block #%d in chain #%d, took %s\n", blockIndex, chainIndex, validationTime)
 			tipHash = blockHash
+
+			if found {
+				t.Fatalf("DONE")
+			}
+			if validationTime > 100*time.Millisecond {
+				found = true
+				logger.SetLogLevels("debug")
+			}
 		}
 
 		averageValidationTime := accumulatedValidationTime / 1000
diff --git a/domain/consensus/processes/ghostdagmanager/ghostdag.go b/domain/consensus/processes/ghostdagmanager/ghostdag.go
index b72d775dd..03c764e27 100644
--- a/domain/consensus/processes/ghostdagmanager/ghostdag.go
+++ b/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),
diff --git a/domain/consensus/processes/ghostdagmanager/log.go b/domain/consensus/processes/ghostdagmanager/log.go
new file mode 100644
index 000000000..5a6bddcc6
--- /dev/null
+++ b/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)