Add logs for elapsed time for block processing; Add bls agg sig benchmark test code. (#3824)

* Add timing log and agg sig tests

* fix build

* add more logs

api/service/legacysync/syncing.go

@@ -836,9 +836,12 @@ func (ss *StateSync) UpdateBlockAndStatus(block *types.Block, bc *core.BlockChai
 			if err != nil {
 				return errors.Wrap(err, "parse commitSigAndBitmap")
 			}
+
+			startTime := time.Now()
 			if err := bc.Engine().VerifyHeaderSignature(bc, block.Header(), sig, bitmap); err != nil {
 				return errors.Wrapf(err, "verify header signature %v", block.Hash().String())
 			}
+			utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("[Sync] VerifyHeaderSignature")
 		}
 		err := bc.Engine().VerifyHeader(bc, block.Header(), verifySeal)
 		if err == engine.ErrUnknownAncestor {

core/state_processor.go

@@ -18,6 +18,7 @@ package core
 
 import (
 	"math/big"
+	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/crypto"
@@ -85,6 +86,7 @@ func (p *StateProcessor) Process(
 		return nil, nil, nil, 0, nil, err
 	}
 
+	startTime := time.Now()
 	// Iterate over and process the individual transactions
 	for i, tx := range block.Transactions() {
 		statedb.Prepare(tx.Hash(), block.Hash(), i)
@@ -100,6 +102,9 @@ func (p *StateProcessor) Process(
 		}
 		allLogs = append(allLogs, receipt.Logs...)
 	}
+	utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("Process Normal Txns")
+
+	startTime = time.Now()
 	// Iterate over and process the staking transactions
 	L := len(block.Transactions())
 	for i, tx := range block.StakingTransactions() {
@@ -113,6 +118,7 @@ func (p *StateProcessor) Process(
 		receipts = append(receipts, receipt)
 		allLogs = append(allLogs, receipt.Logs...)
 	}
+	utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("Process Staking Txns")
 
 	// incomingReceipts should always be processed
 	// after transactions (to be consistent with the block proposal)

internal/chain/engine.go

@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"math/big"
 	"sort"
+	"time"
 
 	"github.com/harmony-one/harmony/internal/params"
 
@@ -286,20 +287,26 @@ func (e *engineImpl) Finalize(
 	// Process Undelegations, set LastEpochInCommittee and set EPoS status
 	// Needs to be before AccumulateRewardsAndCountSigs
 	if IsCommitteeSelectionBlock(chain, header) {
+		startTime := time.Now()
 		if err := payoutUndelegations(chain, header, state); err != nil {
 			return nil, nil, err
 		}
+		utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("PayoutUndelegations")
 
 		// Needs to be after payoutUndelegations because payoutUndelegations
 		// depends on the old LastEpochInCommittee
+
+		startTime = time.Now()
 		if err := setElectionEpochAndMinFee(header, state, chain.Config()); err != nil {
 			return nil, nil, err
 		}
+		utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("SetElectionEpochAndMinFee")
 
 		curShardState, err := chain.ReadShardState(chain.CurrentBlock().Epoch())
 		if err != nil {
 			return nil, nil, err
 		}
+		startTime = time.Now()
 		// Needs to be before AccumulateRewardsAndCountSigs because
 		// ComputeAndMutateEPOSStatus depends on the signing counts that's
 		// consistent with the counts when the new shardState was proposed.
@@ -311,6 +318,7 @@ func (e *engineImpl) Finalize(
 				return nil, nil, err
 			}
 		}
+		utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("ComputeAndMutateEPOSStatus")
 	}
 
 	// Accumulate block rewards and commit the final state root

internal/chain/reward.go

@@ -127,8 +127,6 @@ func AccumulateRewardsAndCountSigs(
 	header *block.Header, beaconChain engine.ChainReader, sigsReady chan bool,
 ) (reward.Reader, error) {
 	blockNum := header.Number().Uint64()
-	currentHeader := beaconChain.CurrentHeader()
-	nowEpoch, blockNow := currentHeader.Epoch(), currentHeader.Number()
 
 	if blockNum == 0 || (bc.Config().IsStaking(header.Epoch()) &&
 		bc.CurrentHeader().ShardID() != shard.BeaconChainShardID) {
@@ -199,11 +197,12 @@ func AccumulateRewardsAndCountSigs(
 
 		// Handle rewards for shardchain
 		if cxLinks := header.CrossLinks(); len(cxLinks) > 0 {
-			utils.AnalysisStart("accumulateRewardShardchainPayout", nowEpoch, blockNow)
+			startTime := time.Now()
 			crossLinks := types.CrossLinks{}
 			if err := rlp.DecodeBytes(cxLinks, &crossLinks); err != nil {
 				return network.EmptyPayout, err
 			}
+			utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("Decode Cross Links")
 
 			type slotPayable struct {
 				shard.Slot
@@ -221,14 +220,16 @@ func AccumulateRewardsAndCountSigs(
 
 			allPayables, allMissing := []slotPayable{}, []slotMissing{}
 
+			startTime = time.Now()
 			for i := range crossLinks {
-
 				cxLink := crossLinks[i]
 				epoch, shardID := cxLink.Epoch(), cxLink.ShardID()
 				if !bc.Config().IsStaking(epoch) {
 					continue
 				}
+				startTimeLocal := time.Now()
 				shardState, err := bc.ReadShardState(epoch)
+				utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTimeLocal).Milliseconds()).Msg("Shard Chain Reward (ReadShardState)")
 
 				if err != nil {
 					return network.EmptyPayout, err
@@ -239,23 +240,30 @@ func AccumulateRewardsAndCountSigs(
 					return network.EmptyPayout, err
 				}
 
+				startTimeLocal = time.Now()
 				payableSigners, missing, err := availability.BlockSigners(
 					cxLink.Bitmap(), subComm,
 				)
+				utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTimeLocal).Milliseconds()).Msg("Shard Chain Reward (BlockSigners)")
+
 				if err != nil {
 					return network.EmptyPayout, errors.Wrapf(err, "shard %d block %d reward error with bitmap %x", shardID, cxLink.BlockNum(), cxLink.Bitmap())
 				}
 
 				staked := subComm.StakedValidators()
+				startTimeLocal = time.Now()
 				if err := availability.IncrementValidatorSigningCounts(
 					beaconChain, staked, state, payableSigners, missing,
 				); err != nil {
 					return network.EmptyPayout, err
 				}
+				utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTimeLocal).Milliseconds()).Msg("Shard Chain Reward (IncrementValidatorSigningCounts)")
 
+				startTimeLocal = time.Now()
 				votingPower, err := lookupVotingPower(
 					epoch, subComm,
 				)
+				utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTimeLocal).Milliseconds()).Msg("Shard Chain Reward (lookupVotingPower)")
 
 				if err != nil {
 					return network.EmptyPayout, err
@@ -270,6 +278,7 @@ func AccumulateRewardsAndCountSigs(
 					}
 				}
 
+				startTimeLocal = time.Now()
 				for j := range payableSigners {
 					voter := votingPower.Voters[payableSigners[j].BLSPublicKey]
 					if !voter.IsHarmonyNode && !voter.OverallPercent.IsZero() {
@@ -285,6 +294,7 @@ func AccumulateRewardsAndCountSigs(
 						})
 					}
 				}
+				utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTimeLocal).Milliseconds()).Msg("Shard Chain Reward (allPayables)")
 
 				for j := range missing {
 					allMissing = append(allMissing, slotMissing{
@@ -315,6 +325,7 @@ func AccumulateRewardsAndCountSigs(
 			}
 
 			// Finally do the pay
+			startTimeLocal := time.Now()
 			for bucket := range resultsHandle {
 				for payThem := range resultsHandle[bucket] {
 					payable := resultsHandle[bucket][payThem]
@@ -342,7 +353,8 @@ func AccumulateRewardsAndCountSigs(
 					})
 				}
 			}
-			utils.AnalysisEnd("accumulateRewardShardchainPayout", nowEpoch, blockNow)
+			utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTimeLocal).Milliseconds()).Msg("Shard Chain Reward (AddReward)")
+			utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("Shard Chain Reward")
 		}
 
 		// Block here until the commit sigs are ready or timeout.
@@ -351,7 +363,7 @@ func AccumulateRewardsAndCountSigs(
 			return network.EmptyPayout, err
 		}
 
-		utils.AnalysisStart("accumulateRewardBeaconchainSelfPayout", nowEpoch, blockNow)
+		startTime := time.Now()
 		// Take care of my own beacon chain committee, _ is missing, for slashing
 		parentE, members, payable, missing, err := ballotResultBeaconchain(beaconChain, header)
 		if err != nil {
@@ -413,7 +425,7 @@ func AccumulateRewardsAndCountSigs(
 				})
 			}
 		}
-		utils.AnalysisEnd("accumulateRewardBeaconchainSelfPayout", nowEpoch, blockNow)
+		utils.Logger().Debug().Int64("elapsed time", time.Now().Sub(startTime).Milliseconds()).Msg("Beacon Chain Reward")
 
 		return network.NewStakingEraRewardForRound(
 			newRewards, missing, beaconP, shardP,

test/chain/vrf/main.go

@@ -23,20 +23,24 @@ func main() {
 
 	blockHash := hash.Keccak256([]byte{1, 2, 3, 4, 5})
 
+	size := 250
+
 	sig := &bls_core.Sign{}
 	startTime := time.Now()
-	for i := 0; i < 1000; i++ {
+	for i := 0; i < size; i++ {
 		sig = blsPriKey.SignHash(blockHash[:])
 	}
 	endTime := time.Now()
-	fmt.Printf("Time required to sign 1000 times: %f seconds\n", endTime.Sub(startTime).Seconds())
+	fmt.Printf("Time required to sign %d times: %f seconds\n", size, endTime.Sub(startTime).Seconds())
 
 	startTime = time.Now()
-	for i := 0; i < 1000; i++ {
+	for i := 0; i < size; i++ {
-		sig.VerifyHash(pubKeyWrapper.Object, blockHash[:])
+		if !sig.VerifyHash(pubKeyWrapper.Object, blockHash[:]) {
+			fmt.Errorf("failed to verify sig")
+		}
 	}
 	endTime = time.Now()
-	fmt.Printf("Time required to verify sig 1000 times: %f seconds\n", endTime.Sub(startTime).Seconds())
+	fmt.Printf("Time required to verify sig %d times: %f seconds\n", size, endTime.Sub(startTime).Seconds())
 
 	sk := vrf_bls.NewVRFSigner(blsPriKey)
 
@@ -44,27 +48,63 @@ func main() {
 	proof := []byte{}
 
 	startTime = time.Now()
-	for i := 0; i < 1000; i++ {
+	for i := 0; i < size; i++ {
 		vrf, proof = sk.Evaluate(blockHash[:])
 	}
 	endTime = time.Now()
-	fmt.Printf("Time required to generate vrf 1000 times: %f seconds\n", endTime.Sub(startTime).Seconds())
+	fmt.Printf("Time required to generate vrf %d times: %f seconds\n", size, endTime.Sub(startTime).Seconds())
 
 	pk := vrf_bls.NewVRFVerifier(blsPriKey.GetPublicKey())
 
 	resultVrf := [32]byte{}
 	startTime = time.Now()
-	for i := 0; i < 1000; i++ {
+	for i := 0; i < size; i++ {
 		resultVrf, _ = pk.ProofToHash(blockHash, proof)
 	}
 	endTime = time.Now()
-	fmt.Printf("Time required to verify vrf 1000 times: %f seconds\n", endTime.Sub(startTime).Seconds())
+	fmt.Printf("Time required to verify vrf %d times: %f seconds\n", size, endTime.Sub(startTime).Seconds())
 
 	if bytes.Compare(vrf[:], resultVrf[:]) != 0 {
 		fmt.Printf("Failed to verify VRF")
 
 	}
 
+	allPubs := []bls.PublicKeyWrapper{}
+	allSigs := []*bls_core.Sign{}
+	aggPub := &bls_core.PublicKey{}
+	aggSig := &bls_core.Sign{}
+	for i := 0; i < size; i++ {
+		blsPriKey := bls.RandPrivateKey()
+		pubKeyWrapper := bls.PublicKeyWrapper{Object: blsPriKey.GetPublicKey()}
+		pubKeyWrapper.Bytes.FromLibBLSPublicKey(pubKeyWrapper.Object)
+		allPubs = append(allPubs, pubKeyWrapper)
+
+		sig := blsPriKey.SignHash(blockHash[:])
+		allSigs = append(allSigs, sig)
+	}
+
+	startTime = time.Now()
+	for i := 0; i < size; i++ {
+		aggPub.Add(allPubs[i].Object)
+	}
+	endTime = time.Now()
+	fmt.Printf("Time required to aggregate %d pubKeys: %f seconds\n", size, endTime.Sub(startTime).Seconds())
+
+	startTime = time.Now()
+	for i := 0; i < size; i++ {
+		aggSig.Add(allSigs[i])
+	}
+	endTime = time.Now()
+	fmt.Printf("Time required to aggregate %d sigs: %f seconds\n", size, endTime.Sub(startTime).Seconds())
+
+	startTime = time.Now()
+	if !aggSig.VerifyHash(aggPub, blockHash[:]) {
+		fmt.Errorf("failed to verify sig")
+	}
+
+	endTime = time.Now()
+	fmt.Printf("Time required to verify a %d aggregated sig: %f seconds\n", size, endTime.Sub(startTime).Seconds())
+
 	// A example result of a single run:
 	//Time required to sign 1000 times: 0.542673 seconds
 	//Time required to verify sig 1000 times: 1.499797 seconds