From 1ce6fe135574bd52d1d20d4c681b8665c9483ded Mon Sep 17 00:00:00 2001 From: Rongjian Lan Date: Tue, 13 Jul 2021 16:00:33 -0700 Subject: [PATCH] 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 | 3 ++ core/state_processor.go | 6 ++++ internal/chain/engine.go | 8 +++++ internal/chain/reward.go | 26 ++++++++++---- test/chain/vrf/main.go | 58 ++++++++++++++++++++++++++----- 5 files changed, 85 insertions(+), 16 deletions(-) diff --git a/api/service/legacysync/syncing.go b/api/service/legacysync/syncing.go index dce1a855a..8ed4c04d2 100644 --- a/api/service/legacysync/syncing.go +++ b/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 { diff --git a/core/state_processor.go b/core/state_processor.go index 1e2cee828..d89e8ce21 100644 --- a/core/state_processor.go +++ b/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) diff --git a/internal/chain/engine.go b/internal/chain/engine.go index 051ad1554..319fd8aad 100644 --- a/internal/chain/engine.go +++ b/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 diff --git a/internal/chain/reward.go b/internal/chain/reward.go index d4f6b2122..896be7455 100644 --- a/internal/chain/reward.go +++ b/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, diff --git a/test/chain/vrf/main.go b/test/chain/vrf/main.go index bbe3caffd..d55247815 100644 --- a/test/chain/vrf/main.go +++ b/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++ { - sig.VerifyHash(pubKeyWrapper.Object, blockHash[:]) + for i := 0; i < size; i++ { + 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