diff --git a/internal/consensus/metrics.go b/internal/consensus/metrics.go index dbefb9a5b..b10cebdb5 100644 --- a/internal/consensus/metrics.go +++ b/internal/consensus/metrics.go @@ -80,6 +80,11 @@ type Metrics struct { // timestamp and the timestamp of the latest prevote in a round where 100% // of the voting power on the network issued prevotes. FullPrevoteMessageDelay metrics.Gauge + + // ProposalTimestampDifference is the difference between the timestamp in + // the proposal message and the local time of the validator at the time + // that the validator received the message. + ProposalTimestampDifference metrics.Histogram } // PrometheusMetrics returns Metrics build using Prometheus client library. @@ -226,6 +231,15 @@ func PrometheusMetrics(namespace string, labelsAndValues ...string) *Metrics { Help: "Difference in seconds between the proposal timestamp and the timestamp " + "of the latest prevote that achieved 100% of the voting power in the prevote step.", }, labels).With(labelsAndValues...), + ProposalTimestampDifference: prometheus.NewHistogramFrom(stdprometheus.HistogramOpts{ + Namespace: namespace, + Subsystem: MetricsSubsystem, + Name: "proposal_timestamp_difference", + Help: "Difference in seconds between the timestamp in the proposal " + + "message and the local time when the message was received. " + + "Only calculated when a new block is proposed.", + Buckets: []float64{-10, -.5, -.025, 0, .1, .5, 1, 1.5, 2, 10}, + }, append(labels, "is_timely")).With(labelsAndValues...), } } @@ -249,15 +263,16 @@ func NopMetrics() *Metrics { BlockIntervalSeconds: discard.NewHistogram(), - NumTxs: discard.NewGauge(), - BlockSizeBytes: discard.NewHistogram(), - TotalTxs: discard.NewGauge(), - CommittedHeight: discard.NewGauge(), - BlockSyncing: discard.NewGauge(), - StateSyncing: discard.NewGauge(), - BlockParts: discard.NewCounter(), - QuorumPrevoteMessageDelay: discard.NewGauge(), - FullPrevoteMessageDelay: discard.NewGauge(), + NumTxs: discard.NewGauge(), + BlockSizeBytes: discard.NewHistogram(), + TotalTxs: discard.NewGauge(), + CommittedHeight: discard.NewGauge(), + BlockSyncing: discard.NewGauge(), + StateSyncing: discard.NewGauge(), + BlockParts: discard.NewCounter(), + QuorumPrevoteMessageDelay: discard.NewGauge(), + FullPrevoteMessageDelay: discard.NewGauge(), + ProposalTimestampDifference: discard.NewHistogram(), } } diff --git a/internal/consensus/state.go b/internal/consensus/state.go index f4b4edf8e..f4af758df 100644 --- a/internal/consensus/state.go +++ b/internal/consensus/state.go @@ -2017,6 +2017,7 @@ func (cs *State) defaultSetProposal(proposal *types.Proposal, recvTime time.Time proposal.Signature = p.Signature cs.Proposal = proposal cs.ProposalReceiveTime = recvTime + cs.calculateProposalTimestampDifferenceMetric() // We don't update cs.ProposalBlockParts if it is already set. // This happens if we're already in cstypes.RoundStepCommit or if there is a valid block in the current round. // TODO: We can check if Proposal is for a different block as this is a sign of misbehavior! @@ -2562,6 +2563,19 @@ func repairWalFile(src, dst string) error { return nil } +func (cs *State) calculateProposalTimestampDifferenceMetric() { + if cs.Proposal != nil && cs.Proposal.POLRound == -1 { + tp := types.SynchronyParams{ + Precision: cs.state.ConsensusParams.Synchrony.Precision, + MessageDelay: cs.state.ConsensusParams.Synchrony.MessageDelay, + } + + isTimely := cs.Proposal.IsTimely(cs.ProposalReceiveTime, tp, cs.state.InitialHeight) + cs.metrics.ProposalTimestampDifference.With("is_timely", fmt.Sprintf("%t", isTimely)). + Observe(cs.ProposalReceiveTime.Sub(cs.Proposal.Timestamp).Seconds()) + } +} + // proposerWaitTime determines how long the proposer should wait to propose its next block. // If the result is zero, a block can be proposed immediately. //