metrics: add metric for proposal timestamp difference (#7550)

internal/consensus/metrics.go

@@ -64,6 +64,11 @@ type Metrics struct {
 
 	// Histogram of time taken per step annotated with reason that the step proceeded.
 	StepTime metrics.Histogram
+
+	// 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.
@@ -196,6 +201,15 @@ func PrometheusMetrics(namespace string, labelsAndValues ...string) *Metrics {
 			Name:      "step_time",
 			Help:      "Time spent per step.",
 		}, append(labels, "step", "reason")).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...),
 	}
 }
 
@@ -219,13 +233,14 @@ 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(),
+		NumTxs:                      discard.NewGauge(),
+		BlockSizeBytes:              discard.NewHistogram(),
+		TotalTxs:                    discard.NewGauge(),
+		CommittedHeight:             discard.NewGauge(),
+		BlockSyncing:                discard.NewGauge(),
+		StateSyncing:                discard.NewGauge(),
+		BlockParts:                  discard.NewCounter(),
+		ProposalTimestampDifference: discard.NewHistogram(),
 	}
 }
 

internal/consensus/state.go

@@ -1946,6 +1946,7 @@ func (cs *State) defaultSetProposal(proposal *types.Proposal) error {
 	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!
@@ -2457,6 +2458,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.
 //