[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

@@ -128,6 +128,9 @@ func NewOperator(ctx context.Context, kubeconfigPath string, clock utilclock.Clo
 	// Create an OperatorLister
 	lister := operatorlister.NewLister()
 
+	res := resolver.NewOperatorsV1alpha1Resolver(lister, crClient, opClient.KubernetesInterface())
+	success := metrics.RegisterDependencyResolutionSuccess
+	failure := metrics.RegisterDependencyResolutionFailure
 	// Allocate the new instance of an Operator.
 	op := &Operator{
 		Operator:                 queueOperator,
@@ -138,7 +141,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(res, success, failure),
 		catsrcQueueSet:           queueinformer.NewEmptyResourceQueueSet(),
 		subQueueSet:              queueinformer.NewEmptyResourceQueueSet(),
 		ipQueueSet:               queueinformer.NewEmptyResourceQueueSet(),

pkg/controller/registry/resolver/instrumented_resolver.go

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

pkg/controller/registry/resolver/instrumented_resolver_test.go

@@ -0,0 +1,55 @@
+package resolver
+
+import (
+	"errors"
+	"testing"
+
+	"github.com/operator-framework/api/pkg/operators/v1alpha1"
+	"github.com/stretchr/testify/require"
+)
+
+var result float64
+
+const (
+	failure = 0.0
+	success = 1.0
+)
+
+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 changeToFailure(num *float64) {
+	*num = failure
+	result = *num
+}
+
+func changeToSuccess(num *float64) {
+	*num = success
+	result = *num
+}
+
+func TestInstrumentedResolver(t *testing.T) {
+	instrumentedResolver := NewInstrumentedResolver(NewFakeResolverWithError(), changeToSuccess, changeToFailure)
+	instrumentedResolver.ResolveSteps("", nil)
+	require.Equal(t, result, failure)
+
+	instrumentedResolver = NewInstrumentedResolver(NewFakeResolverWithoutError(), changeToSuccess, changeToFailure)
+	instrumentedResolver.ResolveSteps("", nil)
+	require.Equal(t, result, success)
+}

pkg/controller/registry/resolver/resolver.go

@@ -51,6 +51,7 @@ func NewOperatorsV1alpha1Resolver(lister operatorlister.OperatorLister, client v
 }
 
 func (r *OperatorsV1alpha1Resolver) ResolveSteps(namespace string, sourceQuerier SourceQuerier) ([]*v1alpha1.Step, []v1alpha1.BundleLookup, []*v1alpha1.Subscription, error) {
+
 	if err := sourceQuerier.Queryable(); err != nil {
 		return nil, nil, nil, err
 	}

pkg/metrics/metrics.go

@@ -170,6 +170,21 @@ var (
 		[]string{NAMESPACE_LABEL, NAME_LABEL, VERSION_LABEL, PHASE_LABEL, REASON_LABEL},
 	)
 
+	dependencyResolutionSucceeded = prometheus.NewSummary(
+		prometheus.SummaryOpts{
+			Name:       "dependency_resolution_succeeded",
+			Help:       "The duration for a dependency to get resolved successfully",
+			Objectives: map[float64]float64{0.95: 0.05, 0.9: 0.01, 0.99: 0.001},
+		},
+	)
+
+	dependencyResolutionFailed = prometheus.NewSummary(
+		prometheus.SummaryOpts{
+			Name:       "dependency_resolution_failed",
+			Help:       "The duration of an unsuccessful dependency resolution",
+			Objectives: map[float64]float64{0.95: 0.05, 0.9: 0.01, 0.99: 0.001},
+		},
+	)
 	// 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
@@ -194,6 +209,8 @@ func RegisterCatalog() {
 	prometheus.MustRegister(subscriptionCount)
 	prometheus.MustRegister(catalogSourceCount)
 	prometheus.MustRegister(SubscriptionSyncCount)
+	prometheus.MustRegister(dependencyResolutionSucceeded)
+	prometheus.MustRegister(dependencyResolutionFailed)
 }
 
 func CounterForSubscription(name, installedCSV, channelName, packageName string) prometheus.Counter {
@@ -269,3 +286,11 @@ func UpdateSubsSyncCounterStorage(sub *olmv1alpha1.Subscription) {
 		counterValues.channel = sub.Spec.Channel
 	}
 }
+
+func RegisterDependencyResolutionSuccess(time *float64) {
+	dependencyResolutionSucceeded.Observe(*time)
+}
+
+func RegisterDependencyResolutionFailure(time *float64) {
+	dependencyResolutionFailed.Observe(*time)
+}

test/e2e/like_metric_matcher_test.go

@@ -56,6 +56,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() {
+	FContext("Metrics emitted by objects during operator installation", func() {
 		var (
 			subscriptionCleanup cleanupFunc
 			subscription        *v1alpha1.Subscription
@@ -138,6 +138,19 @@ var _ = Describe("Metrics are generated for OLM managed resources", func() {
 					WithLabel("package", 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("dependency_resolution_failed"),
+						WithValueGreaterThan(0),
+					)))
+				})
+			})
 		})
 
 		When("A subscription object is updated after emitting metrics", func() {