chore(sew): measure latency (#105) (#107)

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

Related to debugging
[issue](#101)

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

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())
+	}
+}

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