From b54a17c2e46b16d275565ed7295057cd7886054a Mon Sep 17 00:00:00 2001 From: Edgar Aroutiounian Date: Wed, 18 Mar 2020 19:42:24 -0700 Subject: [PATCH] [log] Add dedicated data science logger (#2527) --- internal/chain/engine.go | 3 +++ internal/chain/reward.go | 5 +++- internal/utils/singleton.go | 45 +++++++++++++++++++++++++++++++++++ node/node_newblock.go | 11 ++++++++- shard/committee/assignment.go | 3 +++ 5 files changed, 65 insertions(+), 2 deletions(-) diff --git a/internal/chain/engine.go b/internal/chain/engine.go index 1d2c0ef8e..3793753f5 100644 --- a/internal/chain/engine.go +++ b/internal/chain/engine.go @@ -309,6 +309,9 @@ func (e *engineImpl) Finalize( func payoutUndelegations( chain engine.ChainReader, header *block.Header, state *state.DB, ) error { + utils.AnalysisStart("payoutUndelegations") + defer utils.AnalysisEnd("payoutUndelegations") + validators, err := chain.ReadValidatorList() countTrack := map[common.Address]int{} if err != nil { diff --git a/internal/chain/reward.go b/internal/chain/reward.go index 9fe567193..1b33125b1 100644 --- a/internal/chain/reward.go +++ b/internal/chain/reward.go @@ -98,6 +98,7 @@ func AccumulateRewards( // After staking if bc.Config().IsStaking(header.Epoch()) && bc.CurrentHeader().ShardID() == shard.BeaconChainShardID { + utils.AnalysisStart("accumulateRewardBeaconchainSelfPayout") defaultReward := network.BaseStakedReward beaconCurrentEpoch := beaconChain.CurrentHeader().Epoch() // TODO Use cached result in off-chain db instead of full computation @@ -165,7 +166,9 @@ func AccumulateRewards( } } } + utils.AnalysisEnd("accumulateRewardBeaconchainSelfPayout") + utils.AnalysisStart("accumulateRewardShardchainPayout") // Handle rewards for shardchain if cxLinks := header.CrossLinks(); len(cxLinks) > 0 { crossLinks := types.CrossLinks{} @@ -288,7 +291,7 @@ func AccumulateRewards( } } } - + utils.AnalysisEnd("accumulateRewardShardchainPayout") return network.NewStakingEraRewardForRound(newRewards, missing), nil } return network.EmptyPayout, nil diff --git a/internal/utils/singleton.go b/internal/utils/singleton.go index a71c84a69..b874ef710 100644 --- a/internal/utils/singleton.go +++ b/internal/utils/singleton.go @@ -13,6 +13,7 @@ import ( "github.com/natefinch/lumberjack" "github.com/rs/zerolog" "github.com/rs/zerolog/diode" + "golang.org/x/sync/singleflight" ) var ( @@ -117,6 +118,50 @@ func setZeroLoggerFileOutput(filepath string, maxSize int) error { return nil } +const ( + dataScienceTopic = "ds" +) + +var ( + loggersByTopic singleflight.Group +) + +func lookupLogger(key string) (*zerolog.Logger, error) { + results, err, _ := loggersByTopic.Do( + key, func() (interface{}, error) { + log := Logger().With(). + Str("log-topic", dataScienceTopic). + Timestamp(). + Logger() + return &log, nil + }, + ) + + if err != nil { + return nil, err + } + + return results.(*zerolog.Logger), nil +} + +func ds() *zerolog.Logger { + logger, err := lookupLogger(dataScienceTopic) + if err != nil { + return Logger() + } + return logger +} + +// AnalysisStart .. +func AnalysisStart(name string, more ...interface{}) { + ds().Debug().Msgf("ds-%s-start %s", name, fmt.Sprint(more...)) +} + +// AnalysisEnd .. +func AnalysisEnd(name string, more ...interface{}) { + ds().Debug().Msgf("ds-%s-end %s", name, fmt.Sprint(more...)) +} + // Logger returns a zerolog.Logger singleton func Logger() *zerolog.Logger { if zeroLogger == nil { diff --git a/node/node_newblock.go b/node/node_newblock.go index d3eb12b86..e6c9acced 100644 --- a/node/node_newblock.go +++ b/node/node_newblock.go @@ -84,9 +84,13 @@ func (node *Node) WaitForConsensusReadyV2(readySignal chan struct{}, stopChan ch } func (node *Node) proposeNewBlock() (*types.Block, error) { + utils.AnalysisStart("proposeNewBlock") + defer utils.AnalysisEnd("proposeNewBlock") + node.Worker.UpdateCurrent() - // Update worker's current header and state data in preparation to propose/process new transactions + // Update worker's current header and + // state data in preparation to propose/process new transactions var ( coinbase = node.Consensus.SelfAddresses[node.Consensus.LeaderPubKey.SerializeToHexStr()] beneficiary = coinbase @@ -117,6 +121,8 @@ func (node *Node) proposeNewBlock() (*types.Block, error) { } // Prepare normal and staking transactions retrieved from transaction pool + utils.AnalysisStart("proposeNewBlockChooseFromTxnPool") + pendingPoolTxs, err := node.TxPool.Pending() if err != nil { utils.Logger().Err(err).Msg("Failed to fetch pending transactions") @@ -144,6 +150,7 @@ func (node *Node) proposeNewBlock() (*types.Block, error) { pendingPlainTxs[addr] = plainTxsPerAcc } } + utils.AnalysisEnd("proposeNewBlockChooseFromTxnPool") // Try commit normal and staking transactions based on the current state // The successfully committed transactions will be put in the proposed block @@ -168,6 +175,7 @@ func (node *Node) proposeNewBlock() (*types.Block, error) { isBeaconchainInStakingEra := node.NodeConfig.ShardID == shard.BeaconChainShardID && node.Blockchain().Config().IsStaking(node.Worker.GetCurrentHeader().Epoch()) + utils.AnalysisStart("proposeNewBlockVerifyCrossLinks") // Prepare cross links and slashing messages var crossLinksToPropose types.CrossLinks if isBeaconchainInCrossLinkEra { @@ -202,6 +210,7 @@ func (node *Node) proposeNewBlock() (*types.Block, error) { } node.Blockchain().DeleteFromPendingCrossLinks(invalidToDelete) } + utils.AnalysisEnd("proposeNewBlockVerifyCrossLinks") if isBeaconchainInStakingEra { // this will set a meaningful w.current.slashes diff --git a/shard/committee/assignment.go b/shard/committee/assignment.go index cae3278de..6c31aafee 100644 --- a/shard/committee/assignment.go +++ b/shard/committee/assignment.go @@ -344,11 +344,14 @@ func (def partialStakingEnabled) Compute( Msg("Tried to compute committee for epoch in past") return nil, ErrComputeForEpochInPast } + utils.AnalysisStart("computeEPoSStakedCommittee") shardState, err := eposStakedCommittee(instance, stakerReader) + utils.AnalysisEnd("computeEPoSStakedCommittee") if err != nil { return nil, err } + // Set the epoch of shard state shardState.Epoch = big.NewInt(0).Set(epoch) utils.Logger().Info().