[log] Add dedicated data science logger (#2527)

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 {

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

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 {

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

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().