From 97be133cee6615d7e67b413d9008a79643262621 Mon Sep 17 00:00:00 2001 From: stasatdaglabs <39559713+stasatdaglabs@users.noreply.github.com> Date: Mon, 1 Feb 2021 19:15:50 +0200 Subject: [PATCH] Add logs to help debug long virtual parent selection. (#1470) Co-authored-by: Ori Newman --- .../calculate_past_utxo.go | 12 ++++++++++-- .../pick_virtual_parents.go | 17 +++++++++++------ .../consensusstatemanager/update_virtual.go | 10 +++++++++- 3 files changed, 30 insertions(+), 9 deletions(-) diff --git a/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go b/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go index 6c6ba244a..3bf0328cf 100644 --- a/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go +++ b/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 diff --git a/domain/consensus/processes/consensusstatemanager/pick_virtual_parents.go b/domain/consensus/processes/consensusstatemanager/pick_virtual_parents.go index 459c313dd..84d835a83 100644 --- a/domain/consensus/processes/consensusstatemanager/pick_virtual_parents.go +++ b/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) diff --git a/domain/consensus/processes/consensusstatemanager/update_virtual.go b/domain/consensus/processes/consensusstatemanager/update_virtual.go index c1f3eb13a..2a20d96fe 100644 --- a/domain/consensus/processes/consensusstatemanager/update_virtual.go +++ b/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