More Preccomit logs (#216)

internal/consensus/state.go

@@ -6,7 +6,6 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
-	"github.com/tendermint/tendermint/debugutil"
 	"io"
 	"os"
 	"runtime/debug"
@@ -15,6 +14,8 @@ import (
 	"sync"
 	"time"
 
+	"github.com/tendermint/tendermint/debugutil"
+
 	"github.com/gogo/protobuf/proto"
 	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/sdk/trace"
@@ -1884,55 +1885,70 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32,
 	}()
 
 	// check for a polka
+	t = debugutil.NewTimer("checkPolka")
 	blockID, ok := cs.roundState.Votes().Prevotes(round).TwoThirdsMajority()
+	t.Stop()
 
 	// If we don't have a polka, we must precommit nil.
 	if !ok {
+		t = debugutil.NewTimer("noPolkaPreccomitNil")
 		if cs.roundState.LockedBlock() != nil {
 			logger.Info("precommit step; no +2/3 prevotes during enterPrecommit while we are locked; precommitting nil")
 		} else {
 			logger.Info("precommit step; no +2/3 prevotes during enterPrecommit; precommitting nil")
 		}
 
 		cs.signAddVote(ctx, tmproto.PrecommitType, nil, types.PartSetHeader{})
+		t.Stop()
 		return
 	}
 
 	// At this point +2/3 prevoted for a particular block or nil.
+	t = debugutil.NewTimer("publishEventPolka")
 	if err := cs.eventBus.PublishEventPolka(cs.roundState.RoundStateEvent()); err != nil {
 		logger.Error("failed publishing polka", "err", err)
 	}
+	t.Stop()
 
 	// the latest POLRound should be this round.
+	t = debugutil.NewTimer("polInfo")
 	polRound, _ := cs.roundState.Votes().POLInfo()
 	if polRound < round {
 		panic(fmt.Sprintf("this POLRound should be %v but got %v", round, polRound))
 	}
+	t.Stop()
 
 	// +2/3 prevoted nil. Precommit nil.
 	if blockID.IsNil() {
+		t = debugutil.NewTimer("prevoteNilPreccomitNil")
 		logger.Info("precommit step: +2/3 prevoted for nil; precommitting nil")
 		cs.signAddVote(ctx, tmproto.PrecommitType, nil, types.PartSetHeader{})
+		t.Stop()
 		return
 	}
 	// At this point, +2/3 prevoted for a particular block.
 
 	// If we never received a proposal for this block, we must precommit nil
 	if cs.roundState.Proposal() == nil || cs.roundState.ProposalBlock() == nil {
+		t = debugutil.NewTimer("noBlockProposalPreccomitNil")
 		logger.Info("precommit step; did not receive proposal, precommitting nil")
 		cs.signAddVote(ctx, tmproto.PrecommitType, nil, types.PartSetHeader{})
+		t.Stop()
 		return
 	}
 
 	// If the proposal time does not match the block time, precommit nil.
 	if !cs.roundState.Proposal().Timestamp.Equal(cs.roundState.ProposalBlock().Header.Time) {
 		logger.Info("precommit step: proposal timestamp not equal; precommitting nil")
+		t = debugutil.NewTimer("proposalNotMatchBlockTimePreccomitNil")
 		cs.signAddVote(ctx, tmproto.PrecommitType, nil, types.PartSetHeader{})
+		t.Stop()
 		return
 	}
 
 	// If we're already locked on that block, precommit it, and update the LockedRound
 	if cs.roundState.LockedBlock().HashesTo(blockID.Hash) {
+		t = debugutil.NewTimer("lockedBlockPreccomit")
 		logger.Info("precommit step: +2/3 prevoted locked block; relocking")
 		cs.roundState.SetLockedRound(round)
 
@@ -1941,13 +1957,15 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32,
 		}
 
 		cs.signAddVote(ctx, tmproto.PrecommitType, blockID.Hash, blockID.PartSetHeader)
+		t.Stop()
 		return
 	}
 
 	// If greater than 2/3 of the voting power on the network prevoted for
 	// the proposed block, update our locked block to this block and issue a
 	// precommit vote for it.
 	if cs.roundState.ProposalBlock().HashesTo(blockID.Hash) {
+		t = debugutil.NewTimer("updatedLockedBlockPreccomit")
 		logger.Info("precommit step: +2/3 prevoted proposal block; locking", "hash", blockID.Hash)
 
 		// Validate the block.
@@ -1964,20 +1982,23 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32,
 		}
 
 		cs.signAddVote(ctx, tmproto.PrecommitType, blockID.Hash, blockID.PartSetHeader)
+		t.Stop()
 		return
 	}
 
 	// There was a polka in this round for a block we don't have.
 	// Fetch that block, and precommit nil.
 	logger.Info("precommit step: +2/3 prevotes for a block we do not have; voting nil", "block_id", blockID)
 
+	t = debugutil.NewTimer("polkaNotHavePreccomitNil")
 	if !cs.roundState.ProposalBlockParts().HasHeader(blockID.PartSetHeader) {
 		cs.roundState.SetProposalBlock(nil)
 		cs.metrics.MarkBlockGossipStarted()
 		cs.roundState.SetProposalBlockParts(types.NewPartSetFromHeader(blockID.PartSetHeader))
 	}
 
 	cs.signAddVote(ctx, tmproto.PrecommitType, nil, types.PartSetHeader{})
+	t.Stop()
 }
 
 // Enter: any +2/3 precommits for next round.