From 99ce1c67bec70b50b4d86e01aecd89286ac11731 Mon Sep 17 00:00:00 2001
From: William Banfield <wbanfield@gmail.com>
Date: Thu, 17 Feb 2022 15:41:30 -0500
Subject: [PATCH] initial block gossip time metric

---
 internal/consensus/metrics.go | 27 ++++++++++++++++++---------
 internal/consensus/state.go   |  5 +++++
 2 files changed, 23 insertions(+), 9 deletions(-)

diff --git a/internal/consensus/metrics.go b/internal/consensus/metrics.go
index 2cdf9e275..4bcf252db 100644
--- a/internal/consensus/metrics.go
+++ b/internal/consensus/metrics.go
@@ -1,6 +1,8 @@
 package consensus
 
 import (
+	"time"
+
 	"github.com/go-kit/kit/metrics"
 	"github.com/go-kit/kit/metrics/discard"
 
@@ -66,9 +68,10 @@ type Metrics struct {
 	// Histogram of time taken per step annotated with reason that the step proceeded.
 	StepTime metrics.Histogram
 
-	// Histogram of time taken to receive a block, measured between receiving the first piece of the
-	// the block and receiving the final piece of the block.
-	BlockGossipReceiveTime metrics.Histogram
+	// Time taken to receive a block in seconds, measured between when a new block is first
+	// discovered to when the block is completed.
+	BlockGossipReceiveTime metrics.Gauge
+	blockGossipStart       time.Time
 
 	// QuroumPrevoteMessageDelay is the interval in seconds between the proposal
 	// timestamp and the timestamp of the earliest prevote that achieved a quorum
@@ -216,14 +219,12 @@ func PrometheusMetrics(namespace string, labelsAndValues ...string) *Metrics {
 			Name:      "block_parts",
 			Help:      "Number of blockparts transmitted by peer.",
 		}, append(labels, "peer_id")).With(labelsAndValues...),
-		BlockGossipReceiveTime: prometheus.NewHistogramFrom(stdprometheus.HistogramOpts{
+		BlockGossipReceiveTime: prometheus.NewGaugeFrom(stdprometheus.GaugeOpts{
 			Namespace: namespace,
 			Subsystem: MetricsSubsystem,
 			Name:      "block_gossip_receive_time",
-			Help: "Difference in seconds between when the validator receives the" +
-				"first piece of a block and when the validator receives the last" +
-				" piece of a block.",
-			Buckets: stdprometheus.ExponentialBucketsRange(0, 100, 8),
+			Help: "Difference in seconds between when the validator learns of a new block" +
+				"and when the validator receives the last piece of the block.",
 		}, labels).With(labelsAndValues...),
 		StepTime: prometheus.NewHistogramFrom(stdprometheus.HistogramOpts{
 			Namespace: namespace,
@@ -284,7 +285,7 @@ func NopMetrics() *Metrics {
 		BlockSyncing:                discard.NewGauge(),
 		StateSyncing:                discard.NewGauge(),
 		BlockParts:                  discard.NewCounter(),
-		BlockGossipReceiveTime:      discard.NewHistogram(),
+		BlockGossipReceiveTime:      discard.NewGauge(),
 		QuorumPrevoteMessageDelay:   discard.NewGauge(),
 		FullPrevoteMessageDelay:     discard.NewGauge(),
 		ProposalTimestampDifference: discard.NewHistogram(),
@@ -298,3 +299,11 @@ func (m *Metrics) RecordConsMetrics(block *types.Block) {
 	m.BlockSizeBytes.Observe(float64(block.Size()))
 	m.CommittedHeight.Set(float64(block.Height))
 }
+
+func (m *Metrics) MarkBlockGossipStarted() {
+	m.blockGossipStart = time.Now()
+}
+
+func (m *Metrics) MarkBlockGossipComplete() {
+	m.BlockGossipReceiveTime.Set(float64(time.Now().Sub(m.blockGossipStart).Seconds()))
+}
diff --git a/internal/consensus/state.go b/internal/consensus/state.go
index f8f832381..5fca68a5a 100644
--- a/internal/consensus/state.go
+++ b/internal/consensus/state.go
@@ -1668,6 +1668,7 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32)
 
 	if !cs.ProposalBlockParts.HasHeader(blockID.PartSetHeader) {
 		cs.ProposalBlock = nil
+		cs.metrics.MarkBlockGossipStarted()
 		cs.ProposalBlockParts = types.NewPartSetFromHeader(blockID.PartSetHeader)
 	}
 
@@ -1758,6 +1759,7 @@ func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int3
 			// We're getting the wrong block.
 			// Set up ProposalBlockParts and keep waiting.
 			cs.ProposalBlock = nil
+			cs.metrics.MarkBlockGossipStarted()
 			cs.ProposalBlockParts = types.NewPartSetFromHeader(blockID.PartSetHeader)
 
 			if err := cs.eventBus.PublishEventValidBlock(ctx, cs.RoundStateEvent()); err != nil {
@@ -2034,6 +2036,7 @@ func (cs *State) defaultSetProposal(proposal *types.Proposal, recvTime time.Time
 	// 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!
 	if cs.ProposalBlockParts == nil {
+		cs.metrics.MarkBlockGossipStarted()
 		cs.ProposalBlockParts = types.NewPartSetFromHeader(proposal.BlockID.PartSetHeader)
 	}
 
@@ -2081,6 +2084,7 @@ func (cs *State) addProposalBlockPart(
 		)
 	}
 	if added && cs.ProposalBlockParts.IsComplete() {
+		cs.metrics.MarkBlockGossipComplete()
 		bz, err := io.ReadAll(cs.ProposalBlockParts.GetReader())
 		if err != nil {
 			return added, err
@@ -2293,6 +2297,7 @@ func (cs *State) addVote(
 				}
 
 				if !cs.ProposalBlockParts.HasHeader(blockID.PartSetHeader) {
+					cs.metrics.MarkBlockGossipStarted()
 					cs.ProposalBlockParts = types.NewPartSetFromHeader(blockID.PartSetHeader)
 				}