[metrics] Dependency resolution metrics

This PR introduces two histogram metrics to help in analysing the
time taken by dependency resolution requests.

pkg/controller/operators/catalog/operator.go

@@ -132,6 +132,9 @@ func NewOperator(ctx context.Context, kubeconfigPath string, clock utilclock.Clo
 	// Create an OperatorLister
 	lister := operatorlister.NewLister()
 
+	operatorV1alpha1Resolver := resolver.NewOperatorsV1alpha1Resolver(lister, crClient, opClient.KubernetesInterface())
+	successMetricsEmitter := metrics.RegisterDependencyResolutionSuccess
+	failureMetricsEmitter := metrics.RegisterDependencyResolutionFailure
 	// Allocate the new instance of an Operator.
 	op := &Operator{
 		Operator:                 queueOperator,
@@ -142,7 +145,7 @@ func NewOperator(ctx context.Context, kubeconfigPath string, clock utilclock.Clo
 		client:                   crClient,
 		lister:                   lister,
 		namespace:                operatorNamespace,
-		resolver:                 resolver.NewOperatorsV1alpha1Resolver(lister, crClient, opClient.KubernetesInterface()),
+		resolver:                 resolver.NewInstrumentedResolver(operatorV1alpha1Resolver, successMetricsEmitter, failureMetricsEmitter),
 		catsrcQueueSet:           queueinformer.NewEmptyResourceQueueSet(),
 		subQueueSet:              queueinformer.NewEmptyResourceQueueSet(),
 		ipQueueSet:               queueinformer.NewEmptyResourceQueueSet(),

pkg/controller/registry/resolver/instrumented_resolver.go

@@ -0,0 +1,34 @@
+package resolver
+
+import (
+	"time"
+
+	"github.com/operator-framework/api/pkg/operators/v1alpha1"
+)
+
+type InstrumentedResolver struct {
+	operatorsV1alpha1Resolver Resolver
+	successMetricsEmitter     func(time.Duration)
+	failureMetricsEmitter     func(time.Duration)
+}
+
+var _ Resolver = &OperatorsV1alpha1Resolver{}
+
+func NewInstrumentedResolver(resolver Resolver, successMetricsEmitter, failureMetricsEmitter func(time.Duration)) *InstrumentedResolver {
+	return &InstrumentedResolver{
+		operatorsV1alpha1Resolver: resolver,
+		successMetricsEmitter:     successMetricsEmitter,
+		failureMetricsEmitter:     failureMetricsEmitter,
+	}
+}
+
+func (ir *InstrumentedResolver) ResolveSteps(namespace string, sourceQuerier SourceQuerier) ([]*v1alpha1.Step, []v1alpha1.BundleLookup, []*v1alpha1.Subscription, error) {
+	start := time.Now()
+	steps, lookups, subs, err := ir.operatorsV1alpha1Resolver.ResolveSteps(namespace, sourceQuerier)
+	if err != nil {
+		ir.failureMetricsEmitter(time.Now().Sub(start))
+	} else {
+		ir.successMetricsEmitter(time.Now().Sub(start))
+	}
+	return steps, lookups, subs, err
+}

pkg/controller/registry/resolver/instrumented_resolver_test.go

@@ -0,0 +1,69 @@
+package resolver
+
+import (
+	"errors"
+	"testing"
+	"time"
+
+	"github.com/operator-framework/api/pkg/operators/v1alpha1"
+	"github.com/stretchr/testify/require"
+)
+
+const (
+	failure = time.Duration(0)
+	success = time.Duration(1)
+	reset   = time.Duration(99999)
+)
+
+type fakeResolverWithError struct{}
+type fakeResolverWithoutError struct{}
+
+func (r *fakeResolverWithError) ResolveSteps(namespace string, sourceQuerier SourceQuerier) ([]*v1alpha1.Step, []v1alpha1.BundleLookup, []*v1alpha1.Subscription, error) {
+	return nil, nil, nil, errors.New("Fake error")
+}
+
+func (r *fakeResolverWithoutError) ResolveSteps(namespace string, sourceQuerier SourceQuerier) ([]*v1alpha1.Step, []v1alpha1.BundleLookup, []*v1alpha1.Subscription, error) {
+	return nil, nil, nil, nil
+}
+
+func newFakeResolverWithError() *fakeResolverWithError {
+	return &fakeResolverWithError{}
+}
+
+func newFakeResolverWithoutError() *fakeResolverWithoutError {
+	return &fakeResolverWithoutError{}
+}
+
+func TestInstrumentedResolverFailure(t *testing.T) {
+	result := []time.Duration{}
+
+	changeToFailure := func(num time.Duration) {
+		result = append(result, failure)
+	}
+
+	changeToSuccess := func(num time.Duration) {
+		result = append(result, success)
+	}
+
+	instrumentedResolver := NewInstrumentedResolver(newFakeResolverWithError(), changeToSuccess, changeToFailure)
+	instrumentedResolver.ResolveSteps("", nil)
+	require.Equal(t, len(result), 1)     // check that only one call was made to a change function
+	require.Equal(t, result[0], failure) // check that the call was made to changeToFailure function
+}
+
+func TestInstrumentedResolverSuccess(t *testing.T) {
+	result := []time.Duration{}
+
+	changeToFailure := func(num time.Duration) {
+		result = append(result, failure)
+	}
+
+	changeToSuccess := func(num time.Duration) {
+		result = append(result, success)
+	}
+
+	instrumentedResolver := NewInstrumentedResolver(newFakeResolverWithoutError(), changeToSuccess, changeToFailure)
+	instrumentedResolver.ResolveSteps("", nil)
+	require.Equal(t, len(result), 1)     // check that only one call was made to a change function
+	require.Equal(t, result[0], success) // check that the call was made to changeToSuccess function
+}

pkg/metrics/metrics.go

@@ -1,6 +1,8 @@
 package metrics
 
 import (
+	"time"
+
 	"github.com/prometheus/client_golang/prometheus"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/labels"
@@ -18,6 +20,9 @@ const (
 	PHASE_LABEL     = "phase"
 	REASON_LABEL    = "reason"
 	PACKAGE_LABEL   = "package"
+	Outcome         = "outcome"
+	Succeeded       = "succeeded"
+	Failed          = "failed"
 )
 
 type MetricsProvider interface {
@@ -59,7 +64,7 @@ func (m *metricsInstallPlan) HandleMetrics() error {
 }
 
 type metricsSubscription struct {
-	 lister v1alpha1.SubscriptionLister
+	lister v1alpha1.SubscriptionLister
 }
 
 func NewMetricsSubscription(lister v1alpha1.SubscriptionLister) MetricsProvider {
@@ -167,6 +172,15 @@ var (
 		[]string{NAMESPACE_LABEL, NAME_LABEL, VERSION_LABEL, PHASE_LABEL, REASON_LABEL},
 	)
 
+	dependencyResolutionSummary = prometheus.NewSummaryVec(
+		prometheus.SummaryOpts{
+			Name:       "olm_resolution_duration_seconds",
+			Help:       "The duration of a dependency resolution attempt",
+			Objectives: map[float64]float64{0.95: 0.05, 0.9: 0.01, 0.99: 0.001},
+		},
+		[]string{Outcome},
+	)
+
 	// subscriptionSyncCounters keeps a record of the promethues counters emitted by
 	// Subscription objects. The key of a record is the Subscription name, while the value
 	//  is struct containing label values used in the counter
@@ -191,6 +205,7 @@ func RegisterCatalog() {
 	prometheus.MustRegister(subscriptionCount)
 	prometheus.MustRegister(catalogSourceCount)
 	prometheus.MustRegister(SubscriptionSyncCount)
+	prometheus.MustRegister(dependencyResolutionSummary)
 }
 
 func CounterForSubscription(name, installedCSV, channelName, packageName string) prometheus.Counter {
@@ -268,3 +283,11 @@ func UpdateSubsSyncCounterStorage(sub *olmv1alpha1.Subscription) {
 		subscriptionSyncCounters[sub.GetName()] = counterValues
 	}
 }
+
+func RegisterDependencyResolutionSuccess(duration time.Duration) {
+	dependencyResolutionSummary.WithLabelValues(Succeeded).Observe(duration.Seconds())
+}
+
+func RegisterDependencyResolutionFailure(duration time.Duration) {
+	dependencyResolutionSummary.WithLabelValues(Failed).Observe(duration.Seconds())
+}

test/e2e/like_metric_matcher_test.go

@@ -80,6 +80,15 @@ func WithValue(v float64) MetricPredicate {
 	}
 }
 
+func WithValueGreaterThan(v float64) MetricPredicate {
+	return MetricPredicate{
+		name: fmt.Sprintf("WithValueGreaterThan(%g)", v),
+		f: func(m Metric) bool {
+			return m.Value > v
+		},
+	}
+}
+
 type LikeMetricMatcher struct {
 	Predicates []MetricPredicate
 }

test/e2e/metrics_e2e_test.go

@@ -109,7 +109,7 @@ var _ = Describe("Metrics are generated for OLM managed resources", func() {
 		})
 	})
 
-	Context("Subscription Metric", func() {
+	Context("Metrics emitted by objects during operator installation", func() {
 		var (
 			subscriptionCleanup cleanupFunc
 			subscription        *v1alpha1.Subscription
@@ -138,6 +138,20 @@ var _ = Describe("Metrics are generated for OLM managed resources", func() {
 					WithPackage(testPackageName),
 				)))
 			})
+
+			It("generates dependency_resolution metric", func() {
+
+				// Verify metrics have been emitted for dependency resolution
+				Eventually(func() bool {
+					return Eventually(func() []Metric {
+						return getMetricsFromPod(c, getPodWithLabel(c, "app=catalog-operator"), "8081")
+					}).Should(ContainElement(LikeMetric(
+						WithFamily("olm_resolution_duration_seconds"),
+						WithLabel("outcome", "failed"),
+						WithValueGreaterThan(0),
+					)))
+				})
+			})
 		})
 
 		When("A subscription object is updated after emitting metrics", func() {