From 3f1daf5b370a4733091348aabc13bc0845d4f35d Mon Sep 17 00:00:00 2001
From: Lazar <12626340+Lazar955@users.noreply.github.com>
Date: Tue, 19 Nov 2024 13:21:50 +0100
Subject: [PATCH] chore(sew): measure latency (#105) (#107)

Measure the latency of certain functions. We need more context about fcn
execution.

Related to debugging
[issue](https://github.com/babylonlabs-io/vigilante/issues/101)
---
 CHANGELOG.md                                      |  3 +++
 .../stakingeventwatcher/stakingeventwatcher.go    | 15 +++++++++++++++
 metrics/btcstaking_tracker.go                     |  6 ++++++
 3 files changed, 24 insertions(+)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index bc12aa7..f16e334 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -37,6 +37,9 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/)
 
 ## Unreleased
 
+### Improvements
+* [#105](https://github.com/babylonlabs-io/vigilante/pull/105) Measure latency
+
 ## v0.16.0
 
 * [#94](https://github.com/babylonlabs-io/vigilante/pull/94) adds gosec and fixes gosec issues
diff --git a/btcstaking-tracker/stakingeventwatcher/stakingeventwatcher.go b/btcstaking-tracker/stakingeventwatcher/stakingeventwatcher.go
index b33fb81..2a873e1 100644
--- a/btcstaking-tracker/stakingeventwatcher/stakingeventwatcher.go
+++ b/btcstaking-tracker/stakingeventwatcher/stakingeventwatcher.go
@@ -175,6 +175,8 @@ func (sew *StakingEventWatcher) handleNewBlocks(blockNotifier *notifier.BlockEpo
 // checkBabylonDelegations iterates over all active babylon delegations, and reports not already
 // tracked delegations to the unbondingDelegationChan
 func (sew *StakingEventWatcher) checkBabylonDelegations(status btcstakingtypes.BTCDelegationStatus, addDel func(del Delegation)) error {
+	defer sew.latency(fmt.Sprintf("checkBabylonDelegations: %s", status))()
+
 	var i = uint64(0)
 	for {
 		delegations, err := sew.babylonNodeAdapter.DelegationsByStatus(status, i, sew.cfg.NewDelegationsBatchSize)
@@ -610,6 +612,8 @@ func (sew *StakingEventWatcher) activateBtcDelegation(
 	ctx, cancel := sew.quitContext()
 	defer cancel()
 
+	defer sew.latency("activateBtcDelegation")()
+
 	if err := sew.pendingTracker.UpdateActivation(stakingTxHash, true); err != nil {
 		sew.logger.Debugf("skipping tx %s is not in pending tracker, err: %v", stakingTxHash, err)
 	}
@@ -647,3 +651,14 @@ func (sew *StakingEventWatcher) activateBtcDelegation(
 		}),
 	)
 }
+
+func (sew *StakingEventWatcher) latency(method string) func() {
+	startTime := time.Now()
+	return func() {
+		duration := time.Since(startTime)
+		sew.logger.Debug("execution time",
+			zap.String("method", method),
+			zap.Duration("latency", duration))
+		sew.metrics.MethodExecutionLatency.WithLabelValues(method).Observe(duration.Seconds())
+	}
+}
diff --git a/metrics/btcstaking_tracker.go b/metrics/btcstaking_tracker.go
index 3a977d2..cf32a64 100644
--- a/metrics/btcstaking_tracker.go
+++ b/metrics/btcstaking_tracker.go
@@ -31,6 +31,7 @@ type UnbondingWatcherMetrics struct {
 	DetectedNonUnbondingTransactionsCounter prometheus.Counter
 	FailedReportedActivateDelegations       prometheus.Counter
 	ReportedActivateDelegationsCounter      prometheus.Counter
+	MethodExecutionLatency                  *prometheus.HistogramVec
 }
 
 func newUnbondingWatcherMetrics(registry *prometheus.Registry) *UnbondingWatcherMetrics {
@@ -66,6 +67,11 @@ func newUnbondingWatcherMetrics(registry *prometheus.Registry) *UnbondingWatcher
 			Name: "unbonding_watcher_reported_activate_delegations",
 			Help: "The total number of unbonding transactions successfully reported to Babylon node",
 		}),
+		MethodExecutionLatency: registerer.NewHistogramVec(prometheus.HistogramOpts{
+			Name:    "unbonding_watcher_method_latency_seconds",
+			Help:    "Latency in seconds",
+			Buckets: []float64{.001, .002, .005, .01, .025, .05, .1},
+		}, []string{"method"}),
 	}
 
 	return uwMetrics