Track evaluation times in executor (#3882)

internal/engine/executor.go

@@ -17,6 +17,7 @@ package engine
 import (
 	"context"
 	"fmt"
+	"time"
 
 	"github.com/google/uuid"
 	"github.com/open-feature/go-sdk/openfeature"
@@ -82,6 +83,10 @@ func (e *executor) EvalEntityEvent(ctx context.Context, inf *entities.EntityInfo
 		Str("project_id", inf.ProjectID.String())
 	logger.Msg("entity evaluation - started")
 
+	// track the time taken to evaluate each entity
+	entityStartTime := time.Now()
+	defer e.metrics.TimeProfileEvaluation(ctx, entityStartTime)
+
 	provider, err := e.providerManager.InstantiateFromID(ctx, inf.ProviderID)
 	if err != nil {
 		return fmt.Errorf("could not instantiate provider: %w", err)
@@ -104,6 +109,8 @@ func (e *executor) EvalEntityEvent(ctx context.Context, inf *entities.EntityInfo
 
 	err = e.forProjectsInHierarchy(
 		ctx, inf, func(ctx context.Context, profile *pb.Profile, hierarchy []uuid.UUID) error {
+			profileStartTime := time.Now()
+			defer e.metrics.TimeProfileEvaluation(ctx, profileStartTime)
 			// Get only these rules that are relevant for this entity type
 			relevant, err := profiles.GetRulesForEntity(profile, inf.Type)
 			if err != nil {

internal/engine/metrics.go

@@ -17,6 +17,7 @@ package engine
 import (
 	"context"
 	"fmt"
+	"time"
 
 	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/metric"
@@ -30,6 +31,8 @@ type ExecutorMetrics struct {
 	evalCounter        metric.Int64Counter
 	remediationCounter metric.Int64Counter
 	alertCounter       metric.Int64Counter
+	entityDuration     metric.Int64Histogram
+	profileDuration    metric.Int64Histogram
 }
 
 // NewExecutorMetrics instantiates the ExecutorMetrics struct.
@@ -56,10 +59,26 @@ func NewExecutorMetrics(meterFactory meters.MeterFactory) (*ExecutorMetrics, err
 		return nil, fmt.Errorf("failed to create alert counter: %w", err)
 	}
 
+	profileDuration, err := meter.Int64Histogram("eval.entity-eval-duration",
+		metric.WithDescription("Time taken to evaluate all profiles against an entity"),
+		metric.WithUnit("milliseconds"))
+	if err != nil {
+		return nil, fmt.Errorf("failed to create profile histogram: %w", err)
+	}
+
+	entityDuration, err := meter.Int64Histogram("eval.profile-eval-duration",
+		metric.WithDescription("Time taken to evaluate a single profile against an entity"),
+		metric.WithUnit("milliseconds"))
+	if err != nil {
+		return nil, fmt.Errorf("failed to create entity histogram: %w", err)
+	}
+
 	return &ExecutorMetrics{
 		evalCounter:        evalCounter,
 		remediationCounter: remediationCounter,
 		alertCounter:       alertCounter,
+		profileDuration:    profileDuration,
+		entityDuration:     entityDuration,
 	}, nil
 }
 
@@ -94,3 +113,13 @@ func (e *ExecutorMetrics) CountAlertStatus(
 		attribute.String("status", string(status)),
 	))
 }
+
+// TimeEntityEvaluation records how long it took to evaluate a profile.
+func (e *ExecutorMetrics) TimeEntityEvaluation(ctx context.Context, startTime time.Time) {
+	e.entityDuration.Record(ctx, time.Since(startTime).Milliseconds())
+}
+
+// TimeProfileEvaluation records how long it took to evaluate a profile.
+func (e *ExecutorMetrics) TimeProfileEvaluation(ctx context.Context, startTime time.Time) {
+	e.profileDuration.Record(ctx, time.Since(startTime).Milliseconds())
+}