From dab7ec7a29c98ac1531876853952ec60017739b2 Mon Sep 17 00:00:00 2001
From: Fergal Gribben <fergal.gribben@smartcontract.com>
Date: Tue, 9 Jul 2024 16:35:05 +0100
Subject: [PATCH] Time recovery calls

Add logs

Timestamp recover
---
 .../evmregistry/v21/logprovider/recoverer.go  | 40 +++++++++++++++++++
 1 file changed, 40 insertions(+)

diff --git a/core/services/ocr2/plugins/ocr2keeper/evmregistry/v21/logprovider/recoverer.go b/core/services/ocr2/plugins/ocr2keeper/evmregistry/v21/logprovider/recoverer.go
index 9e41008ed83..4a8ee2e9b0c 100644
--- a/core/services/ocr2/plugins/ocr2keeper/evmregistry/v21/logprovider/recoverer.go
+++ b/core/services/ocr2/plugins/ocr2keeper/evmregistry/v21/logprovider/recoverer.go
@@ -285,6 +285,11 @@ func (r *logRecoverer) getLogTriggerCheckData(ctx context.Context, proposal ocr2
 }
 
 func (r *logRecoverer) GetRecoveryProposals(ctx context.Context) ([]ocr2keepers.UpkeepPayload, error) {
+	start := time.Now()
+	defer func() {
+		r.lggr.Debugw("GetRecoveryProposals finished", "time", time.Since(start))
+	}()
+
 	latestBlock, err := r.poller.LatestBlock(ctx)
 	if err != nil {
 		return nil, fmt.Errorf("%w: %s", ErrHeadNotAvailable, err)
@@ -329,6 +334,11 @@ func (r *logRecoverer) GetRecoveryProposals(ctx context.Context) ([]ocr2keepers.
 }
 
 func (r *logRecoverer) recover(ctx context.Context) error {
+	startTime := time.Now()
+	defer func() {
+		r.lggr.Debugw("recover finished", "time", time.Since(startTime))
+	}()
+
 	latest, err := r.poller.LatestBlock(ctx)
 	if err != nil {
 		return fmt.Errorf("%w: %s", ErrHeadNotAvailable, err)
@@ -367,6 +377,11 @@ func (r *logRecoverer) recover(ctx context.Context) error {
 
 // recoverFilter recovers logs for a single upkeep filter.
 func (r *logRecoverer) recoverFilter(ctx context.Context, f upkeepFilter, startBlock, offsetBlock int64) error {
+	startTime := time.Now()
+	defer func() {
+		r.lggr.Debugw("recoverFilter finished", "time", time.Since(startTime))
+	}()
+
 	start := f.lastRePollBlock + 1 // NOTE: we expect f.lastRePollBlock + 1 <= offsetBlock, as others would have been filtered out
 	// ensure we don't recover logs from before the filter was created
 	if configUpdateBlock := int64(f.configUpdateBlock); start < configUpdateBlock {
@@ -437,6 +452,11 @@ func (r *logRecoverer) recoverFilter(ctx context.Context, f upkeepFilter, startB
 // returns the number of logs added, the number of logs that were already pending,
 // and a flag that indicates whether some errors happened while we are trying to add to pending q.
 func (r *logRecoverer) populatePending(f upkeepFilter, filteredLogs []logpoller.Log) (int, int, bool) {
+	start := time.Now()
+	defer func() {
+		r.lggr.Debugw("populatePending finished", "time", time.Since(start))
+	}()
+
 	r.lock.Lock()
 	defer r.lock.Unlock()
 
@@ -584,6 +604,11 @@ func logToTrigger(log logpoller.Log) ocr2keepers.Trigger {
 }
 
 func (r *logRecoverer) clean(ctx context.Context) {
+	start := time.Now()
+	defer func() {
+		r.lggr.Debugw("clean finished", "time", time.Since(start))
+	}()
+
 	r.lock.RLock()
 	var expired []string
 	for id, t := range r.visited {
@@ -659,6 +684,11 @@ func (r *logRecoverer) tryExpire(ctx context.Context, ids ...string) error {
 // addPending adds a payload to the pending list if it's not already there.
 // NOTE: the lock must be held before calling this function.
 func (r *logRecoverer) addPending(payload ocr2keepers.UpkeepPayload) error {
+	start := time.Now()
+	defer func() {
+		r.lggr.Debugw("addPending finished", "time", time.Since(start))
+	}()
+
 	var exist bool
 	pending := r.pending
 	upkeepPayloads := 0
@@ -683,6 +713,11 @@ func (r *logRecoverer) addPending(payload ocr2keepers.UpkeepPayload) error {
 // removePending removes a payload from the pending list.
 // NOTE: the lock must be held before calling this function.
 func (r *logRecoverer) removePending(workID string) {
+	start := time.Now()
+	defer func() {
+		r.lggr.Debugw("removePending finished", "time", time.Since(start))
+	}()
+
 	updated := make([]ocr2keepers.UpkeepPayload, 0, len(r.pending))
 	for _, p := range r.pending {
 		if p.WorkID != workID {
@@ -698,6 +733,11 @@ func (r *logRecoverer) removePending(workID string) {
 // Divided by 10 to ensure that nodes with similar block numbers won't end up with different order.
 // NOTE: the lock must be held before calling this function.
 func (r *logRecoverer) sortPending(latestBlock uint64) {
+	start := time.Now()
+	defer func() {
+		r.lggr.Debugw("sortPending finished", "time", time.Since(start))
+	}()
+
 	normalized := latestBlock / 100
 	if normalized == 0 {
 		normalized = 1