More detailed logging

core/services/ocr2/plugins/ccip/commit_reporting_plugin.go

@@ -700,6 +700,7 @@ func (r *CommitReportingPlugin) buildReport(ctx context.Context, lggr logger.Log
 
 	// Logs are guaranteed to be in order of seq num, since these are finalized logs only
 	// and the contract's seq num is auto-incrementing.
+	start := time.Now()
 	sendRequests, err := r.onRampReader.GetSendRequestsBetweenSeqNums(
 		ctx,
 		interval.Min,
@@ -716,6 +717,15 @@ func (r *CommitReportingPlugin) buildReport(ctx context.Context, lggr logger.Log
 		return ccipdata.CommitStoreReport{}, fmt.Errorf("tried building a tree without leaves")
 	}
 
+	lggr.Infow(
+		"SelectLogsDataWordRange",
+		"type", "commit_build_report",
+		"sendRequests", len(sendRequests),
+		"minSeqNr", interval.Min,
+		"maxSeqNr", interval.Max,
+		"duration", time.Since(start).Milliseconds(),
+	)
+
 	leaves := make([][32]byte, 0, len(sendRequests))
 	var seqNrs []uint64
 	for _, req := range sendRequests {

core/services/ocr2/plugins/ccip/execution_batch_building.go

@@ -2,21 +2,20 @@ package ccip
 
 import (
 	"context"
+	"time"
 
 	"github.com/pkg/errors"
 
+	"github.com/smartcontractkit/chainlink/v2/core/logger"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/abihelpers"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal/ccipdata"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal/hashlib"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal/merklemulti"
 )
 
-func getProofData(
-	ctx context.Context,
-	sourceReader ccipdata.OnRampReader,
-	interval ccipdata.CommitStoreInterval,
-) (sendReqsInRoot []ccipdata.Event[internal.EVM2EVMMessage], leaves [][32]byte, tree *merklemulti.Tree[[32]byte], err error) {
+func getProofData(ctx context.Context, sourceReader ccipdata.OnRampReader, interval ccipdata.CommitStoreInterval, lggr logger.Logger) (sendReqsInRoot []ccipdata.Event[internal.EVM2EVMMessage], leaves [][32]byte, tree *merklemulti.Tree[[32]byte], err error) {
+	start := time.Now()
 	sendReqs, err := sourceReader.GetSendRequestsBetweenSeqNums(
 		ctx,
 		interval.Min,
@@ -26,6 +25,16 @@ func getProofData(
 	if err != nil {
 		return nil, nil, nil, err
 	}
+
+	lggr.Infow(
+		"SelectLogsDataWordRange",
+		"type", "exec_proof_data",
+		"sendRequests", len(sendReqs),
+		"minSeqNr", interval.Min,
+		"maxSeqNr", interval.Max,
+		"duration", time.Since(start).Milliseconds(),
+	)
+
 	leaves = make([][32]byte, 0, len(sendReqs))
 	for _, req := range sendReqs {
 		leaves = append(leaves, req.Data.Hash)

core/services/ocr2/plugins/ccip/execution_reporting_plugin.go

@@ -424,6 +424,7 @@ func (r *ExecutionReportingPlugin) sourceDestinationTokens(ctx context.Context)
 // before. It doesn't matter if the executed succeeded, since we don't retry previous
 // attempts even if they failed. Value in the map indicates whether the log is finalized or not.
 func (r *ExecutionReportingPlugin) getExecutedSeqNrsInRange(ctx context.Context, min, max uint64, latestBlock int64) (map[uint64]bool, error) {
+	start := time.Now()
 	stateChanges, err := r.config.offRampReader.GetExecutionStateChangesBetweenSeqNums(
 		ctx,
 		min,
@@ -433,6 +434,16 @@ func (r *ExecutionReportingPlugin) getExecutedSeqNrsInRange(ctx context.Context,
 	if err != nil {
 		return nil, err
 	}
+
+	r.lggr.Infow(
+		"SelectIndexedLogsTopicRange",
+		"type", "exec",
+		"sendRequests", len(stateChanges),
+		"minSeqNr", min,
+		"maxSeqNr", max,
+		"duration", time.Since(start).Milliseconds(),
+	)
+
 	executedMp := make(map[uint64]bool, len(stateChanges))
 	for _, stateChange := range stateChanges {
 		finalized := (latestBlock - stateChange.BlockNumber) >= int64(r.offchainConfig.DestFinalityDepth)
@@ -755,6 +766,7 @@ func (r *ExecutionReportingPlugin) getReportsWithSendRequests(
 
 	var sendRequests []ccipdata.Event[internal.EVM2EVMMessage]
 	eg.Go(func() error {
+		start := time.Now()
 		sendReqs, err := r.config.onRampReader.GetSendRequestsBetweenSeqNums(
 			ctx,
 			intervalMin,
@@ -764,6 +776,16 @@ func (r *ExecutionReportingPlugin) getReportsWithSendRequests(
 		if err != nil {
 			return err
 		}
+
+		r.lggr.Infow(
+			"SelectLogsDataWordRange",
+			"type", "exec_get_report",
+			"sendRequests", len(sendReqs),
+			"minSeqNr", intervalMin,
+			"maxSeqNr", intervalMax,
+			"duration", time.Since(start).Milliseconds(),
+		)
+
 		sendRequests = sendReqs
 		return nil
 	})
@@ -845,7 +867,7 @@ func (r *ExecutionReportingPlugin) buildReport(ctx context.Context, lggr logger.
 	}
 	lggr.Infow("Building execution report", "observations", observedMessages, "merkleRoot", hexutil.Encode(commitReport.MerkleRoot[:]), "report", commitReport)
 
-	sendReqsInRoot, leaves, tree, err := getProofData(ctx, r.config.onRampReader, commitReport.Interval)
+	sendReqsInRoot, leaves, tree, err := getProofData(ctx, r.config.onRampReader, commitReport.Interval, r.lggr)
 	if err != nil {
 		return nil, err
 	}