Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Merged
merged 5 commits into from
Apr 3, 2022
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
6a57bab
Clean up debug log level and move most/frequent logs to trace level
michaelsutton Apr 3, 2022
6ddc082
Revert "Clean up debug log level and move most/frequent logs to trace…
michaelsutton Apr 3, 2022
b0f8fb0
Merge remote-tracking branch 'origin/dev' into clean-debug-log
michaelsutton Apr 3, 2022
194b99e
Change function call tracing to trace log level
michaelsutton Apr 3, 2022
2f2a706
LogMemoryStats on debug level
michaelsutton Apr 3, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions app/protocol/flowcontext/blocks.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,8 +20,8 @@ func (f *FlowContext) OnNewBlock(block *externalapi.DomainBlock,
virtualChangeSet *externalapi.VirtualChangeSet) error {

hash := consensushashing.BlockHash(block)
log.Debugf("OnNewBlock start for block %s", hash)
defer log.Debugf("OnNewBlock end for block %s", hash)
log.Tracef("OnNewBlock start for block %s", hash)
defer log.Tracef("OnNewBlock end for block %s", hash)

unorphaningResults, err := f.UnorphanBlocks(block)
if err != nil {
Expand Down
12 changes: 6 additions & 6 deletions domain/consensus/processes/consensusstatemanager/add_block_to_virtual.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -79,8 +79,8 @@ func (csm *consensusStateManager) AddBlock(stagingArea *model.StagingArea, block
func (csm *consensusStateManager) isCandidateToBeNextVirtualSelectedParent(
stagingArea *model.StagingArea, blockHash *externalapi.DomainHash) (bool, error) {

log.Debugf("isCandidateToBeNextVirtualSelectedParent start for block %s", blockHash)
defer log.Debugf("isCandidateToBeNextVirtualSelectedParent end for block %s", blockHash)
log.Tracef("isCandidateToBeNextVirtualSelectedParent start for block %s", blockHash)
defer log.Tracef("isCandidateToBeNextVirtualSelectedParent end for block %s", blockHash)

if blockHash.Equal(csm.genesisHash) {
log.Debugf("Block %s is the genesis block, therefore it is "+
Expand All @@ -106,8 +106,8 @@ func (csm *consensusStateManager) isCandidateToBeNextVirtualSelectedParent(
}

func (csm *consensusStateManager) addTip(stagingArea *model.StagingArea, newTipHash *externalapi.DomainHash) (newTips []*externalapi.DomainHash, err error) {
log.Debugf("addTip start for new tip %s", newTipHash)
defer log.Debugf("addTip end for new tip %s", newTipHash)
log.Tracef("addTip start 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)
newTips, err = csm.calculateNewTips(stagingArea, newTipHash)
Expand All @@ -124,8 +124,8 @@ func (csm *consensusStateManager) addTip(stagingArea *model.StagingArea, newTipH
func (csm *consensusStateManager) calculateNewTips(
stagingArea *model.StagingArea, newTipHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) {

log.Debugf("calculateNewTips start for new tip %s", newTipHash)
defer log.Debugf("calculateNewTips end for new tip %s", newTipHash)
log.Tracef("calculateNewTips start for new tip %s", newTipHash)
defer log.Tracef("calculateNewTips end for new tip %s", newTipHash)

if newTipHash.Equal(csm.genesisHash) {
log.Debugf("The new tip is the genesis block, therefore it is the only tip by definition")
Expand Down
4 changes: 2 additions & 2 deletions domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -145,8 +145,8 @@ func (csm *consensusStateManager) applyMergeSetBlocks(stagingArea *model.Staging
selectedParentPastUTXODiff externalapi.UTXODiff, daaScore uint64) (
externalapi.AcceptanceData, externalapi.MutableUTXODiff, error) {

log.Debugf("applyMergeSetBlocks start for block %s", blockHash)
defer log.Debugf("applyMergeSetBlocks end for block %s", blockHash)
log.Tracef("applyMergeSetBlocks start for block %s", blockHash)
defer log.Tracef("applyMergeSetBlocks end for block %s", blockHash)

mergeSetHashes, err := csm.ghostdagManager.GetSortedMergeSet(stagingArea, blockHash)
if err != nil {
Expand Down
4 changes: 2 additions & 2 deletions domain/consensus/processes/consensusstatemanager/check_finality_violation.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,8 +8,8 @@ import (
func (csm *consensusStateManager) isViolatingFinality(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash,
) (isViolatingFinality bool, shouldSendNotification bool, err error) {

log.Debugf("isViolatingFinality start for block %s", blockHash)
defer log.Debugf("isViolatingFinality end for block %s", blockHash)
log.Tracef("isViolatingFinality start for block %s", blockHash)
defer log.Tracef("isViolatingFinality end for block %s", blockHash)

if blockHash.Equal(csm.genesisHash) {
log.Debugf("Block %s is the genesis block, "+
Expand Down
4 changes: 2 additions & 2 deletions domain/consensus/processes/consensusstatemanager/import_pruning_utxo_set.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,8 +30,8 @@ func (csm *consensusStateManager) ImportPruningPointUTXOSet(stagingArea *model.S
}

func (csm *consensusStateManager) importPruningPointUTXOSet(stagingArea *model.StagingArea, newPruningPoint *externalapi.DomainHash) error {
log.Debugf("importPruningPointUTXOSet start")
defer log.Debugf("importPruningPointUTXOSet end")
log.Tracef("importPruningPointUTXOSet start")
defer log.Tracef("importPruningPointUTXOSet end")

// TODO: We should validate the imported pruning point doesn't violate finality as part of the headers proof.

Expand Down
4 changes: 2 additions & 2 deletions domain/consensus/processes/consensusstatemanager/multisets.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,8 +13,8 @@ func (csm *consensusStateManager) calculateMultiset(stagingArea *model.StagingAr
blockGHOSTDAGData *externalapi.BlockGHOSTDAGData,
daaScore uint64) (model.Multiset, error) {

log.Debugf("calculateMultiset start for block with selected parent %s", blockGHOSTDAGData.SelectedParent())
defer log.Debugf("calculateMultiset end for block with selected parent %s", blockGHOSTDAGData.SelectedParent())
log.Tracef("calculateMultiset start 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) {
log.Debugf("Selected parent is nil, which could only happen for the genesis. " +
Expand Down
8 changes: 4 additions & 4 deletions domain/consensus/processes/consensusstatemanager/resolve_block_status.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -120,8 +120,8 @@ func (csm *consensusStateManager) selectedParentInfo(
stagingArea *model.StagingArea, unverifiedBlocks []*externalapi.DomainHash) (
*externalapi.DomainHash, externalapi.BlockStatus, externalapi.UTXODiff, error) {

log.Debugf("findSelectedParentStatus start")
defer log.Debugf("findSelectedParentStatus end")
log.Tracef("findSelectedParentStatus start")
defer log.Tracef("findSelectedParentStatus end")

lastUnverifiedBlock := unverifiedBlocks[len(unverifiedBlocks)-1]
if lastUnverifiedBlock.Equal(csm.genesisHash) {
Expand Down Expand Up @@ -156,8 +156,8 @@ func (csm *consensusStateManager) selectedParentInfo(
func (csm *consensusStateManager) getUnverifiedChainBlocks(stagingArea *model.StagingArea,
blockHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) {

log.Debugf("getUnverifiedChainBlocks start for block %s", blockHash)
defer log.Debugf("getUnverifiedChainBlocks end for block %s", blockHash)
log.Tracef("getUnverifiedChainBlocks start for block %s", blockHash)
defer log.Tracef("getUnverifiedChainBlocks end for block %s", blockHash)

var unverifiedBlocks []*externalapi.DomainHash
currentHash := blockHash
Expand Down
4 changes: 2 additions & 2 deletions domain/consensus/processes/consensusstatemanager/utxo_diffs.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,8 +8,8 @@ import (
func (csm *consensusStateManager) stageDiff(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash,
utxoDiff externalapi.UTXODiff, utxoDiffChild *externalapi.DomainHash) {

log.Debugf("stageDiff start for block %s", blockHash)
defer log.Debugf("stageDiff end for block %s", blockHash)
log.Tracef("stageDiff start 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)
csm.utxoDiffStore.Stage(stagingArea, blockHash, utxoDiff, utxoDiffChild)
Expand Down
4 changes: 2 additions & 2 deletions domain/consensus/processes/consensusstatemanager/verify_and_build_utxo.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,8 +19,8 @@ func (csm *consensusStateManager) verifyUTXO(stagingArea *model.StagingArea, blo
blockHash *externalapi.DomainHash, pastUTXODiff externalapi.UTXODiff, acceptanceData externalapi.AcceptanceData,
multiset model.Multiset) error {

log.Debugf("verifyUTXO start for block %s", blockHash)
defer log.Debugf("verifyUTXO end for block %s", blockHash)
log.Tracef("verifyUTXO start for block %s", blockHash)
defer log.Tracef("verifyUTXO end for block %s", blockHash)

log.Debugf("Validating UTXO commitment for block %s", blockHash)
err := csm.validateUTXOCommitment(block, blockHash, multiset)
Expand Down
12 changes: 6 additions & 6 deletions domain/consensus/processes/finalitymanager/finality_manager.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -39,8 +39,8 @@ func New(databaseContext model.DBReader,
}

func (fm *finalityManager) VirtualFinalityPoint(stagingArea *model.StagingArea) (*externalapi.DomainHash, error) {
log.Debugf("virtualFinalityPoint start")
defer log.Debugf("virtualFinalityPoint end")
log.Tracef("virtualFinalityPoint start")
defer log.Tracef("virtualFinalityPoint end")

virtualFinalityPoint, err := fm.calculateFinalityPoint(stagingArea, model.VirtualBlockHash, false)
if err != nil {
Expand All @@ -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) {
log.Debugf("FinalityPoint start")
defer log.Debugf("FinalityPoint end")
log.Tracef("FinalityPoint start")
defer log.Tracef("FinalityPoint end")
if blockHash.Equal(model.VirtualBlockHash) {
return fm.VirtualFinalityPoint(stagingArea)
}
Expand Down Expand Up @@ -82,8 +82,8 @@ func (fm *finalityManager) calculateAndStageFinalityPoint(
func (fm *finalityManager) calculateFinalityPoint(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, isBlockWithTrustedData bool) (
*externalapi.DomainHash, error) {

log.Debugf("calculateFinalityPoint start")
defer log.Debugf("calculateFinalityPoint end")
log.Tracef("calculateFinalityPoint start")
defer log.Tracef("calculateFinalityPoint end")

if isBlockWithTrustedData {
return model.VirtualGenesisBlockHash, nil
Expand Down
8 changes: 4 additions & 4 deletions domain/consensus/processes/reachabilitymanager/tree.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -314,7 +314,7 @@ func (rt *reachabilityManager) addChild(stagingArea *model.StagingArea, node, ch
}

reindexTimeElapsed := time.Since(reindexStartTime)
log.Debugf("Reachability reindex triggered for "+
log.Tracef("Reachability reindex triggered for "+
"block %s. Took %dms.",
node, reindexTimeElapsed.Milliseconds())

Expand Down Expand Up @@ -352,7 +352,7 @@ func (rt *reachabilityManager) updateReindexRoot(stagingArea *model.StagingArea,
rc := newReindexContext(rt)

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
for {
chosenChild, err := rt.FindNextAncestor(stagingArea, selectedTip, reindexRootAncestor)
Expand All @@ -375,12 +375,12 @@ func (rt *reachabilityManager) updateReindexRoot(stagingArea *model.StagingArea,
reindexRootAncestor = chosenChild
}
} 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
rt.stageReindexRoot(stagingArea, newReindexRoot)
log.Debugf("Updated the reindex root to %s", newReindexRoot)
log.Tracef("Updated the reindex root to %s", newReindexRoot)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe change to Debugf?

return nil
}

Expand Down
4 changes: 2 additions & 2 deletions infrastructure/logger/utils.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,9 +12,9 @@ import (
// the time duration the function had ran.
func LogAndMeasureExecutionTime(log *Logger, functionName string) (onEnd func()) {
start := time.Now()
log.Debugf("%s start", functionName)
log.Tracef("%s start", functionName)
return func() {
log.Debugf("%s end. Took: %s", functionName, time.Since(start))
log.Tracef("%s end. Took: %s", functionName, time.Since(start))
}
}

Expand Down
4 changes: 2 additions & 2 deletions util/panics/panics.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()) {
goroutineID := atomic.AddUint64(&goroutineLastID, 1)
goroutineName := fmt.Sprintf("%s %d", spawnedFunctionName, goroutineID)
utilLog.Debugf("Started goroutine `%s`", goroutineName)
defer utilLog.Debugf("Ended goroutine `%s`", goroutineName)
utilLog.Tracef("Started goroutine `%s`", goroutineName)
defer utilLog.Tracef("Ended goroutine `%s`", goroutineName)
defer HandlePanic(log, goroutineName, stackTrace)
spawnedFunction()
}