Clean up debug log level by moving many frequent logs to trace level (#2004)

* Clean up debug log level and move most/frequent logs to trace level

* Change function call traces to trace log level
This commit is contained in:
Michael Sutton 2022-04-03 23:25:29 +03:00 committed by GitHub
parent 71afc62298
commit 80879cabe1
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
13 changed files with 38 additions and 38 deletions

View File

@ -20,8 +20,8 @@ func (f *FlowContext) OnNewBlock(block *externalapi.DomainBlock,
virtualChangeSet *externalapi.VirtualChangeSet) error { virtualChangeSet *externalapi.VirtualChangeSet) error {
hash := consensushashing.BlockHash(block) hash := consensushashing.BlockHash(block)
log.Debugf("OnNewBlock start for block %s", hash) log.Tracef("OnNewBlock start for block %s", hash)
defer log.Debugf("OnNewBlock end for block %s", hash) defer log.Tracef("OnNewBlock end for block %s", hash)
unorphaningResults, err := f.UnorphanBlocks(block) unorphaningResults, err := f.UnorphanBlocks(block)
if err != nil { if err != nil {

View File

@ -79,8 +79,8 @@ func (csm *consensusStateManager) AddBlock(stagingArea *model.StagingArea, block
func (csm *consensusStateManager) isCandidateToBeNextVirtualSelectedParent( func (csm *consensusStateManager) isCandidateToBeNextVirtualSelectedParent(
stagingArea *model.StagingArea, blockHash *externalapi.DomainHash) (bool, error) { stagingArea *model.StagingArea, blockHash *externalapi.DomainHash) (bool, error) {
log.Debugf("isCandidateToBeNextVirtualSelectedParent start for block %s", blockHash) log.Tracef("isCandidateToBeNextVirtualSelectedParent start for block %s", blockHash)
defer log.Debugf("isCandidateToBeNextVirtualSelectedParent end for block %s", blockHash) defer log.Tracef("isCandidateToBeNextVirtualSelectedParent end for block %s", blockHash)
if blockHash.Equal(csm.genesisHash) { if blockHash.Equal(csm.genesisHash) {
log.Debugf("Block %s is the genesis block, therefore it is "+ log.Debugf("Block %s is the genesis block, therefore it is "+
@ -106,8 +106,8 @@ func (csm *consensusStateManager) isCandidateToBeNextVirtualSelectedParent(
} }
func (csm *consensusStateManager) addTip(stagingArea *model.StagingArea, newTipHash *externalapi.DomainHash) (newTips []*externalapi.DomainHash, err error) { func (csm *consensusStateManager) addTip(stagingArea *model.StagingArea, newTipHash *externalapi.DomainHash) (newTips []*externalapi.DomainHash, err error) {
log.Debugf("addTip start for new tip %s", newTipHash) log.Tracef("addTip start for new tip %s", newTipHash)
defer log.Debugf("addTip end for new tip %s", newTipHash) defer log.Tracef("addTip end for new tip %s", newTipHash)
log.Debugf("Calculating the new tips for new tip %s", newTipHash) log.Debugf("Calculating the new tips for new tip %s", newTipHash)
newTips, err = csm.calculateNewTips(stagingArea, newTipHash) newTips, err = csm.calculateNewTips(stagingArea, newTipHash)
@ -124,8 +124,8 @@ func (csm *consensusStateManager) addTip(stagingArea *model.StagingArea, newTipH
func (csm *consensusStateManager) calculateNewTips( func (csm *consensusStateManager) calculateNewTips(
stagingArea *model.StagingArea, newTipHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) { stagingArea *model.StagingArea, newTipHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) {
log.Debugf("calculateNewTips start for new tip %s", newTipHash) log.Tracef("calculateNewTips start for new tip %s", newTipHash)
defer log.Debugf("calculateNewTips end for new tip %s", newTipHash) defer log.Tracef("calculateNewTips end for new tip %s", newTipHash)
if newTipHash.Equal(csm.genesisHash) { if newTipHash.Equal(csm.genesisHash) {
log.Debugf("The new tip is the genesis block, therefore it is the only tip by definition") log.Debugf("The new tip is the genesis block, therefore it is the only tip by definition")

View File

@ -145,8 +145,8 @@ func (csm *consensusStateManager) applyMergeSetBlocks(stagingArea *model.Staging
selectedParentPastUTXODiff externalapi.UTXODiff, daaScore uint64) ( selectedParentPastUTXODiff externalapi.UTXODiff, daaScore uint64) (
externalapi.AcceptanceData, externalapi.MutableUTXODiff, error) { externalapi.AcceptanceData, externalapi.MutableUTXODiff, error) {
log.Debugf("applyMergeSetBlocks start for block %s", blockHash) log.Tracef("applyMergeSetBlocks start for block %s", blockHash)
defer log.Debugf("applyMergeSetBlocks end for block %s", blockHash) defer log.Tracef("applyMergeSetBlocks end for block %s", blockHash)
mergeSetHashes, err := csm.ghostdagManager.GetSortedMergeSet(stagingArea, blockHash) mergeSetHashes, err := csm.ghostdagManager.GetSortedMergeSet(stagingArea, blockHash)
if err != nil { if err != nil {

View File

@ -8,8 +8,8 @@ import (
func (csm *consensusStateManager) isViolatingFinality(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, func (csm *consensusStateManager) isViolatingFinality(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash,
) (isViolatingFinality bool, shouldSendNotification bool, err error) { ) (isViolatingFinality bool, shouldSendNotification bool, err error) {
log.Debugf("isViolatingFinality start for block %s", blockHash) log.Tracef("isViolatingFinality start for block %s", blockHash)
defer log.Debugf("isViolatingFinality end for block %s", blockHash) defer log.Tracef("isViolatingFinality end for block %s", blockHash)
if blockHash.Equal(csm.genesisHash) { if blockHash.Equal(csm.genesisHash) {
log.Debugf("Block %s is the genesis block, "+ log.Debugf("Block %s is the genesis block, "+

View File

@ -30,8 +30,8 @@ func (csm *consensusStateManager) ImportPruningPointUTXOSet(stagingArea *model.S
} }
func (csm *consensusStateManager) importPruningPointUTXOSet(stagingArea *model.StagingArea, newPruningPoint *externalapi.DomainHash) error { func (csm *consensusStateManager) importPruningPointUTXOSet(stagingArea *model.StagingArea, newPruningPoint *externalapi.DomainHash) error {
log.Debugf("importPruningPointUTXOSet start") log.Tracef("importPruningPointUTXOSet start")
defer log.Debugf("importPruningPointUTXOSet end") defer log.Tracef("importPruningPointUTXOSet end")
// TODO: We should validate the imported pruning point doesn't violate finality as part of the headers proof. // TODO: We should validate the imported pruning point doesn't violate finality as part of the headers proof.

View File

@ -13,8 +13,8 @@ func (csm *consensusStateManager) calculateMultiset(stagingArea *model.StagingAr
blockGHOSTDAGData *externalapi.BlockGHOSTDAGData, blockGHOSTDAGData *externalapi.BlockGHOSTDAGData,
daaScore uint64) (model.Multiset, error) { daaScore uint64) (model.Multiset, error) {
log.Debugf("calculateMultiset start for block with selected parent %s", blockGHOSTDAGData.SelectedParent()) log.Tracef("calculateMultiset start for block with selected parent %s", blockGHOSTDAGData.SelectedParent())
defer log.Debugf("calculateMultiset end for block with selected parent %s", blockGHOSTDAGData.SelectedParent()) defer log.Tracef("calculateMultiset end for block with selected parent %s", blockGHOSTDAGData.SelectedParent())
if blockHash.Equal(csm.genesisHash) { if blockHash.Equal(csm.genesisHash) {
log.Debugf("Selected parent is nil, which could only happen for the genesis. " + log.Debugf("Selected parent is nil, which could only happen for the genesis. " +

View File

@ -120,8 +120,8 @@ func (csm *consensusStateManager) selectedParentInfo(
stagingArea *model.StagingArea, unverifiedBlocks []*externalapi.DomainHash) ( stagingArea *model.StagingArea, unverifiedBlocks []*externalapi.DomainHash) (
*externalapi.DomainHash, externalapi.BlockStatus, externalapi.UTXODiff, error) { *externalapi.DomainHash, externalapi.BlockStatus, externalapi.UTXODiff, error) {
log.Debugf("findSelectedParentStatus start") log.Tracef("findSelectedParentStatus start")
defer log.Debugf("findSelectedParentStatus end") defer log.Tracef("findSelectedParentStatus end")
lastUnverifiedBlock := unverifiedBlocks[len(unverifiedBlocks)-1] lastUnverifiedBlock := unverifiedBlocks[len(unverifiedBlocks)-1]
if lastUnverifiedBlock.Equal(csm.genesisHash) { if lastUnverifiedBlock.Equal(csm.genesisHash) {
@ -156,8 +156,8 @@ func (csm *consensusStateManager) selectedParentInfo(
func (csm *consensusStateManager) getUnverifiedChainBlocks(stagingArea *model.StagingArea, func (csm *consensusStateManager) getUnverifiedChainBlocks(stagingArea *model.StagingArea,
blockHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) { blockHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) {
log.Debugf("getUnverifiedChainBlocks start for block %s", blockHash) log.Tracef("getUnverifiedChainBlocks start for block %s", blockHash)
defer log.Debugf("getUnverifiedChainBlocks end for block %s", blockHash) defer log.Tracef("getUnverifiedChainBlocks end for block %s", blockHash)
var unverifiedBlocks []*externalapi.DomainHash var unverifiedBlocks []*externalapi.DomainHash
currentHash := blockHash currentHash := blockHash

View File

@ -8,8 +8,8 @@ import (
func (csm *consensusStateManager) stageDiff(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, func (csm *consensusStateManager) stageDiff(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash,
utxoDiff externalapi.UTXODiff, utxoDiffChild *externalapi.DomainHash) { utxoDiff externalapi.UTXODiff, utxoDiffChild *externalapi.DomainHash) {
log.Debugf("stageDiff start for block %s", blockHash) log.Tracef("stageDiff start for block %s", blockHash)
defer log.Debugf("stageDiff end for block %s", blockHash) defer log.Tracef("stageDiff end for block %s", blockHash)
log.Debugf("Staging block %s as the diff child of %s", utxoDiffChild, blockHash) log.Debugf("Staging block %s as the diff child of %s", utxoDiffChild, blockHash)
csm.utxoDiffStore.Stage(stagingArea, blockHash, utxoDiff, utxoDiffChild) csm.utxoDiffStore.Stage(stagingArea, blockHash, utxoDiff, utxoDiffChild)

View File

@ -19,8 +19,8 @@ func (csm *consensusStateManager) verifyUTXO(stagingArea *model.StagingArea, blo
blockHash *externalapi.DomainHash, pastUTXODiff externalapi.UTXODiff, acceptanceData externalapi.AcceptanceData, blockHash *externalapi.DomainHash, pastUTXODiff externalapi.UTXODiff, acceptanceData externalapi.AcceptanceData,
multiset model.Multiset) error { multiset model.Multiset) error {
log.Debugf("verifyUTXO start for block %s", blockHash) log.Tracef("verifyUTXO start for block %s", blockHash)
defer log.Debugf("verifyUTXO end for block %s", blockHash) defer log.Tracef("verifyUTXO end for block %s", blockHash)
log.Debugf("Validating UTXO commitment for block %s", blockHash) log.Debugf("Validating UTXO commitment for block %s", blockHash)
err := csm.validateUTXOCommitment(block, blockHash, multiset) err := csm.validateUTXOCommitment(block, blockHash, multiset)

View File

@ -39,8 +39,8 @@ func New(databaseContext model.DBReader,
} }
func (fm *finalityManager) VirtualFinalityPoint(stagingArea *model.StagingArea) (*externalapi.DomainHash, error) { func (fm *finalityManager) VirtualFinalityPoint(stagingArea *model.StagingArea) (*externalapi.DomainHash, error) {
log.Debugf("virtualFinalityPoint start") log.Tracef("virtualFinalityPoint start")
defer log.Debugf("virtualFinalityPoint end") defer log.Tracef("virtualFinalityPoint end")
virtualFinalityPoint, err := fm.calculateFinalityPoint(stagingArea, model.VirtualBlockHash, false) virtualFinalityPoint, err := fm.calculateFinalityPoint(stagingArea, model.VirtualBlockHash, false)
if err != nil { if err != nil {
@ -52,8 +52,8 @@ func (fm *finalityManager) VirtualFinalityPoint(stagingArea *model.StagingArea)
} }
func (fm *finalityManager) FinalityPoint(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, isBlockWithTrustedData bool) (*externalapi.DomainHash, error) { func (fm *finalityManager) FinalityPoint(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, isBlockWithTrustedData bool) (*externalapi.DomainHash, error) {
log.Debugf("FinalityPoint start") log.Tracef("FinalityPoint start")
defer log.Debugf("FinalityPoint end") defer log.Tracef("FinalityPoint end")
if blockHash.Equal(model.VirtualBlockHash) { if blockHash.Equal(model.VirtualBlockHash) {
return fm.VirtualFinalityPoint(stagingArea) return fm.VirtualFinalityPoint(stagingArea)
} }
@ -82,8 +82,8 @@ func (fm *finalityManager) calculateAndStageFinalityPoint(
func (fm *finalityManager) calculateFinalityPoint(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, isBlockWithTrustedData bool) ( func (fm *finalityManager) calculateFinalityPoint(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, isBlockWithTrustedData bool) (
*externalapi.DomainHash, error) { *externalapi.DomainHash, error) {
log.Debugf("calculateFinalityPoint start") log.Tracef("calculateFinalityPoint start")
defer log.Debugf("calculateFinalityPoint end") defer log.Tracef("calculateFinalityPoint end")
if isBlockWithTrustedData { if isBlockWithTrustedData {
return model.VirtualGenesisBlockHash, nil return model.VirtualGenesisBlockHash, nil

View File

@ -314,7 +314,7 @@ func (rt *reachabilityManager) addChild(stagingArea *model.StagingArea, node, ch
} }
reindexTimeElapsed := time.Since(reindexStartTime) reindexTimeElapsed := time.Since(reindexStartTime)
log.Debugf("Reachability reindex triggered for "+ log.Tracef("Reachability reindex triggered for "+
"block %s. Took %dms.", "block %s. Took %dms.",
node, reindexTimeElapsed.Milliseconds()) node, reindexTimeElapsed.Milliseconds())
@ -352,7 +352,7 @@ func (rt *reachabilityManager) updateReindexRoot(stagingArea *model.StagingArea,
rc := newReindexContext(rt) rc := newReindexContext(rt)
if !newReindexRoot.Equal(reindexRootAncestor) { if !newReindexRoot.Equal(reindexRootAncestor) {
log.Debugf("Concentrating the intervals towards the new reindex root") log.Tracef("Concentrating the intervals towards the new reindex root")
// Iterate from reindexRootAncestor towards newReindexRoot // Iterate from reindexRootAncestor towards newReindexRoot
for { for {
chosenChild, err := rt.FindNextAncestor(stagingArea, selectedTip, reindexRootAncestor) chosenChild, err := rt.FindNextAncestor(stagingArea, selectedTip, reindexRootAncestor)
@ -375,12 +375,12 @@ func (rt *reachabilityManager) updateReindexRoot(stagingArea *model.StagingArea,
reindexRootAncestor = chosenChild reindexRootAncestor = chosenChild
} }
} else { } else {
log.Debugf("newReindexRoot is the same as reindexRootAncestor. Skipping concentration...") log.Tracef("newReindexRoot is the same as reindexRootAncestor. Skipping concentration...")
} }
// Update reindex root data store // Update reindex root data store
rt.stageReindexRoot(stagingArea, newReindexRoot) rt.stageReindexRoot(stagingArea, newReindexRoot)
log.Debugf("Updated the reindex root to %s", newReindexRoot) log.Tracef("Updated the reindex root to %s", newReindexRoot)
return nil return nil
} }

View File

@ -12,9 +12,9 @@ import (
// the time duration the function had ran. // the time duration the function had ran.
func LogAndMeasureExecutionTime(log *Logger, functionName string) (onEnd func()) { func LogAndMeasureExecutionTime(log *Logger, functionName string) (onEnd func()) {
start := time.Now() start := time.Now()
log.Debugf("%s start", functionName) log.Tracef("%s start", functionName)
return func() { return func() {
log.Debugf("%s end. Took: %s", functionName, time.Since(start)) log.Tracef("%s end. Took: %s", functionName, time.Since(start))
} }
} }

View File

@ -77,8 +77,8 @@ func exit(log *logger.Logger, reason string, currentThreadStackTrace []byte, gor
func handleSpawnedFunction(log *logger.Logger, stackTrace []byte, spawnedFunctionName string, spawnedFunction func()) { func handleSpawnedFunction(log *logger.Logger, stackTrace []byte, spawnedFunctionName string, spawnedFunction func()) {
goroutineID := atomic.AddUint64(&goroutineLastID, 1) goroutineID := atomic.AddUint64(&goroutineLastID, 1)
goroutineName := fmt.Sprintf("%s %d", spawnedFunctionName, goroutineID) goroutineName := fmt.Sprintf("%s %d", spawnedFunctionName, goroutineID)
utilLog.Debugf("Started goroutine `%s`", goroutineName) utilLog.Tracef("Started goroutine `%s`", goroutineName)
defer utilLog.Debugf("Ended goroutine `%s`", goroutineName) defer utilLog.Tracef("Ended goroutine `%s`", goroutineName)
defer HandlePanic(log, goroutineName, stackTrace) defer HandlePanic(log, goroutineName, stackTrace)
spawnedFunction() spawnedFunction()
} }