From 42961277e1efd3686c1561a8a0e8802a42ff6f77 Mon Sep 17 00:00:00 2001
From: terence tsao <terence@prysmaticlabs.com>
Date: Fri, 1 May 2020 19:35:15 -0700
Subject: [PATCH] Add histogram metrics for block arrival time (#5708)

* Add metrics to track block propogation delay

* Grammar

* Grammar

* Metrics for block sent

* Refactor into own function

* Removed sent

* Lint

* Use histogram. Thanks Preston for the suggestion!

* s/total/histogram

* Update name to `block_arrival_latency_milliseconds`

* Use milliseconds

* Use unix nano

* Use SlotToTime

* Preston's feedback

* Handle err
---
 beacon-chain/sync/metrics.go                |  7 +++++++
 beacon-chain/sync/validate_beacon_blocks.go | 20 ++++++++++++++++++++
 2 files changed, 27 insertions(+)

diff --git a/beacon-chain/sync/metrics.go b/beacon-chain/sync/metrics.go
index 8b1276510847..2962fdae65cc 100644
--- a/beacon-chain/sync/metrics.go
+++ b/beacon-chain/sync/metrics.go
@@ -69,6 +69,13 @@ var (
 			Help: "Count the number of times attestation not recovered and pruned because of missing block",
 		},
 	)
+	arrivalBlockPropagationHistogram = promauto.NewHistogram(
+		prometheus.HistogramOpts{
+			Name:    "block_arrival_latency_milliseconds",
+			Help:    "Captures blocks propagation time. Blocks arrival in milliseconds distribution",
+			Buckets: []float64{1000, 2000, 3000, 4000, 5000, 6000},
+		},
+	)
 )
 
 func (r *Service) updateMetrics() {
diff --git a/beacon-chain/sync/validate_beacon_blocks.go b/beacon-chain/sync/validate_beacon_blocks.go
index aa333661c0e5..0b3347bad2de 100644
--- a/beacon-chain/sync/validate_beacon_blocks.go
+++ b/beacon-chain/sync/validate_beacon_blocks.go
@@ -2,6 +2,7 @@ package sync
 
 import (
 	"context"
+	"time"
 
 	"github.com/libp2p/go-libp2p-core/peer"
 	pubsub "github.com/libp2p/go-libp2p-pubsub"
@@ -11,6 +12,7 @@ import (
 	"github.com/prysmaticlabs/prysm/beacon-chain/core/helpers"
 	"github.com/prysmaticlabs/prysm/shared/bytesutil"
 	"github.com/prysmaticlabs/prysm/shared/featureconfig"
+	"github.com/prysmaticlabs/prysm/shared/roughtime"
 	"github.com/prysmaticlabs/prysm/shared/traceutil"
 	"go.opencensus.io/trace"
 )
@@ -51,6 +53,7 @@ func (r *Service) validateBeaconBlockPubSub(ctx context.Context, pid peer.ID, ms
 	if blk.Block == nil {
 		return false
 	}
+
 	// Verify the block is the first block received for the proposer for the slot.
 	if r.hasSeenBlockIndexSlot(blk.Block.Slot, blk.Block.ProposerIndex) {
 		return false
@@ -71,6 +74,11 @@ func (r *Service) validateBeaconBlockPubSub(ctx context.Context, pid peer.ID, ms
 	}
 	r.pendingQueueLock.RUnlock()
 
+	// Add metrics for block arrival time subtracts slot start time.
+	if captureArrivalTimeMetric(uint64(r.chain.GenesisTime().Unix()), blk.Block.Slot) != nil {
+		return false
+	}
+
 	if err := helpers.VerifySlotTime(uint64(r.chain.GenesisTime().Unix()), blk.Block.Slot, maximumGossipClockDisparity); err != nil {
 		log.WithError(err).WithField("blockSlot", blk.Block.Slot).Warn("Rejecting incoming block.")
 		return false
@@ -144,3 +152,15 @@ func (r *Service) setSeenBlockIndexSlot(slot uint64, proposerIdx uint64) {
 	b := append(bytesutil.Bytes32(slot), bytesutil.Bytes32(proposerIdx)...)
 	r.seenBlockCache.Add(string(b), true)
 }
+
+// This captures metrics for block arrival time by subtracts slot start time.
+func captureArrivalTimeMetric(genesisTime uint64, currentSlot uint64) error {
+	startTime, err := helpers.SlotToTime(genesisTime, currentSlot)
+	if err != nil {
+		return err
+	}
+	diffMs := roughtime.Now().Sub(startTime) / time.Millisecond
+	arrivalBlockPropagationHistogram.Observe(float64(diffMs))
+
+	return nil
+}