Repository: Azure/ARO-RP
Pull request #2210 (2022-06-27 22:52:43)

Added cluster install time metrics
### Which issue this PR addresses:

https://dev.azure.com/msazure/AzureRedHatOpenShift/_workitems/edit/6470470

### What this PR does / why we need it:

Enable SRE to view how long ARO cluster creations are taking across the fleet, together with the time consumption of each install step.

### Test plan for issue:

Unit tested

### Is there any documentation that needs to be updated for this PR?

N/A


Patch:
diff --git a/pkg/backend/openshiftcluster.go b/pkg/backend/openshiftcluster.go
index d6122b143..44a1970b2 100644
--- a/pkg/backend/openshiftcluster.go
+++ b/pkg/backend/openshiftcluster.go
@@ -19,6 +19,7 @@ import (
 	"github.com/Azure/ARO-RP/pkg/cluster"
 	"github.com/Azure/ARO-RP/pkg/database"
 	"github.com/Azure/ARO-RP/pkg/env"
+	"github.com/Azure/ARO-RP/pkg/metrics"
 	"github.com/Azure/ARO-RP/pkg/util/billing"
 	"github.com/Azure/ARO-RP/pkg/util/encryption"
 	utillog "github.com/Azure/ARO-RP/pkg/util/log"
@@ -28,7 +29,7 @@ import (
 type openShiftClusterBackend struct {
 	*backend
 
-	newManager func(context.Context, *logrus.Entry, env.Interface, database.OpenShiftClusters, database.Gateway, encryption.AEAD, billing.Manager, *api.OpenShiftClusterDocument, *api.SubscriptionDocument, *rest.Config) (cluster.Interface, error)
+	newManager func(context.Context, *logrus.Entry, env.Interface, database.OpenShiftClusters, database.Gateway, encryption.AEAD, billing.Manager, *api.OpenShiftClusterDocument, *api.SubscriptionDocument, *rest.Config, metrics.Emitter) (cluster.Interface, error)
 }
 
 func newOpenShiftClusterBackend(b *backend) *openShiftClusterBackend {
@@ -106,7 +107,7 @@ func (ocb *openShiftClusterBackend) handle(ctx context.Context, log *logrus.Entr
 		log.Info(err) // TODO(hive): Update to fail once we have Hive everywhere in prod and dev
 	}
 
-	m, err := ocb.newManager(ctx, log, ocb.env, ocb.dbOpenShiftClusters, ocb.dbGateway, ocb.aead, ocb.billing, doc, subscriptionDoc, hiveRestConfig)
+	m, err := ocb.newManager(ctx, log, ocb.env, ocb.dbOpenShiftClusters, ocb.dbGateway, ocb.aead, ocb.billing, doc, subscriptionDoc, hiveRestConfig, ocb.m)
 	if err != nil {
 		return ocb.endLease(ctx, log, stop, doc, api.ProvisioningStateFailed, err)
 	}
diff --git a/pkg/cluster/cluster.go b/pkg/cluster/cluster.go
index 97a23ea1e..df9299d5e 100644
--- a/pkg/cluster/cluster.go
+++ b/pkg/cluster/cluster.go
@@ -5,6 +5,7 @@ package cluster
 
 import (
 	"context"
+	"time"
 
 	"github.com/Azure/go-autorest/autorest/azure"
 	configclient "github.com/openshift/client-go/config/clientset/versioned"
@@ -24,6 +25,7 @@ import (
 	"github.com/Azure/ARO-RP/pkg/database"
 	"github.com/Azure/ARO-RP/pkg/env"
 	"github.com/Azure/ARO-RP/pkg/hive"
+	"github.com/Azure/ARO-RP/pkg/metrics"
 	aroclient "github.com/Azure/ARO-RP/pkg/operator/clientset/versioned"
 	"github.com/Azure/ARO-RP/pkg/operator/deploy"
 	"github.com/Azure/ARO-RP/pkg/util/azureclient/graphrbac"
@@ -58,6 +60,7 @@ type manager struct {
 	subscriptionDoc   *api.SubscriptionDocument
 	fpAuthorizer      refreshable.Authorizer
 	localFpAuthorizer refreshable.Authorizer
+	metricsEmitter    metrics.Emitter
 
 	spApplications        graphrbac.ApplicationsClient
 	disks                 compute.DisksClient
@@ -98,11 +101,13 @@ type manager struct {
 	hiveClusterManager hive.ClusterManager
 
 	aroOperatorDeployer deploy.Operator
+
+	now func() time.Time
 }
 
 // New returns a cluster manager
 func New(ctx context.Context, log *logrus.Entry, _env env.Interface, db database.OpenShiftClusters, dbGateway database.Gateway, aead encryption.AEAD,
-	billing billing.Manager, doc *api.OpenShiftClusterDocument, subscriptionDoc *api.SubscriptionDocument, hiveRestConfig *rest.Config) (Interface, error) {
+	billing billing.Manager, doc *api.OpenShiftClusterDocument, subscriptionDoc *api.SubscriptionDocument, hiveRestConfig *rest.Config, metricsEmitter metrics.Emitter) (Interface, error) {
 	r, err := azure.ParseResourceID(doc.OpenShiftCluster.ID)
 	if err != nil {
 		return nil, err
@@ -140,16 +145,16 @@ func New(ctx context.Context, log *logrus.Entry, _env env.Interface, db database
 	}
 
 	return &manager{
-		log:               log,
-		env:               _env,
-		db:                db,
-		dbGateway:         dbGateway,
-		billing:           billing,
-		doc:               doc,
-		subscriptionDoc:   subscriptionDoc,
-		fpAuthorizer:      fpAuthorizer,
-		localFpAuthorizer: localFPAuthorizer,
-
+		log:                   log,
+		env:                   _env,
+		db:                    db,
+		dbGateway:             dbGateway,
+		billing:               billing,
+		doc:                   doc,
+		subscriptionDoc:       subscriptionDoc,
+		fpAuthorizer:          fpAuthorizer,
+		localFpAuthorizer:     localFPAuthorizer,
+		metricsEmitter:        metricsEmitter,
 		disks:                 compute.NewDisksClient(_env.Environment(), r.SubscriptionID, fpAuthorizer),
 		virtualMachines:       compute.NewVirtualMachinesClient(_env.Environment(), r.SubscriptionID, fpAuthorizer),
 		interfaces:            network.NewInterfacesClient(_env.Environment(), r.SubscriptionID, fpAuthorizer),
@@ -175,5 +180,6 @@ func New(ctx context.Context, log *logrus.Entry, _env env.Interface, db database
 
 		installViaHive:     installViaHive,
 		hiveClusterManager: hr,
+		now:                func() time.Time { return time.Now() },
 	}, nil
 }
diff --git a/pkg/cluster/install.go b/pkg/cluster/install.go
index 73476232c..5aa309c9f 100644
--- a/pkg/cluster/install.go
+++ b/pkg/cluster/install.go
@@ -31,7 +31,7 @@ import (
 // AdminUpdate performs an admin update of an ARO cluster
 func (m *manager) AdminUpdate(ctx context.Context) error {
 	toRun := m.adminUpdate()
-	return m.runSteps(ctx, toRun)
+	return m.runSteps(ctx, toRun, false)
 }
 
 func (m *manager) adminUpdate() []steps.Step {
@@ -139,7 +139,7 @@ func (m *manager) Update(ctx context.Context) error {
 		steps.Action(m.hiveResetCorrelationData),
 	}
 
-	return m.runSteps(ctx, steps)
+	return m.runSteps(ctx, steps, false)
 }
 
 func (m *manager) runIntegratedInstaller(ctx context.Context) error {
@@ -269,11 +269,25 @@ func (m *manager) Install(ctx context.Context) error {
 		return fmt.Errorf("unrecognised phase %s", m.doc.OpenShiftCluster.Properties.Install.Phase)
 	}
 	m.log.Printf("starting phase %s", m.doc.OpenShiftCluster.Properties.Install.Phase)
-	return m.runSteps(ctx, steps[m.doc.OpenShiftCluster.Properties.Install.Phase])
+	return m.runSteps(ctx, steps[m.doc.OpenShiftCluster.Properties.Install.Phase], true)
 }
 
-func (m *manager) runSteps(ctx context.Context, s []steps.Step) error {
-	err := steps.Run(ctx, m.log, 10*time.Second, s)
+func (m *manager) runSteps(ctx context.Context, s []steps.Step, emitMetrics bool) error {
+	var err error
+	if emitMetrics {
+		var stepsTimeRun map[string]int64
+		stepsTimeRun, err = steps.Run(ctx, m.log, 10*time.Second, s, m.now)
+		if err == nil {
+			var totalInstallTime int64
+			for topic, duration := range stepsTimeRun {
+				m.metricsEmitter.EmitGauge(fmt.Sprintf("backend.openshiftcluster.installtime.%s", topic), duration, nil)
+				totalInstallTime += duration
+			}
+			m.metricsEmitter.EmitGauge("backend.openshiftcluster.installtime.total", totalInstallTime, nil)
+		}
+	} else {
+		_, err = steps.Run(ctx, m.log, 10*time.Second, s, nil)
+	}
 	if err != nil {
 		m.gatherFailureLogs(ctx)
 	}
diff --git a/pkg/installer/install.go b/pkg/installer/install.go
index d2bf3b808..8203b3909 100644
--- a/pkg/installer/install.go
+++ b/pkg/installer/install.go
@@ -48,7 +48,7 @@ func (m *manager) Install(ctx context.Context) error {
 		steps.Condition(m.bootstrapConfigMapReady, 30*time.Minute, true),
 	}
 
-	err := steps.Run(ctx, m.log, 10*time.Second, s)
+	_, err := steps.Run(ctx, m.log, 10*time.Second, s, nil)
 	return err
 }
 
diff --git a/pkg/util/steps/action.go b/pkg/util/steps/action.go
index e31d83c9d..c9622946b 100644
--- a/pkg/util/steps/action.go
+++ b/pkg/util/steps/action.go
@@ -18,7 +18,9 @@ type actionFunction func(context.Context) error
 // Action returns a Step which will execute the action function `f`. Errors from
 // `f` are returned directly.
 func Action(f actionFunction) Step {
-	return actionStep{f}
+	return actionStep{
+		f: f,
+	}
 }
 
 type actionStep struct {
@@ -28,6 +30,11 @@ type actionStep struct {
 func (s actionStep) run(ctx context.Context, log *logrus.Entry) error {
 	return s.f(ctx)
 }
+
 func (s actionStep) String() string {
 	return fmt.Sprintf("[Action %s]", FriendlyName(s.f))
 }
+
+func (s actionStep) metricsTopic() string {
+	return fmt.Sprintf("action.%s", shortName(FriendlyName(s.f)))
+}
diff --git a/pkg/util/steps/condition.go b/pkg/util/steps/condition.go
index 921d40e8c..3efb1dcc0 100644
--- a/pkg/util/steps/condition.go
+++ b/pkg/util/steps/condition.go
@@ -72,3 +72,7 @@ func (c conditionStep) run(ctx context.Context, log *logrus.Entry) error {
 func (c conditionStep) String() string {
 	return fmt.Sprintf("[Condition %s, timeout %s]", FriendlyName(c.f), c.timeout)
 }
+
+func (c conditionStep) metricsTopic() string {
+	return fmt.Sprintf("condition.%s", shortName(FriendlyName(c.f)))
+}
diff --git a/pkg/util/steps/refreshing.go b/pkg/util/steps/refreshing.go
index 0580b876b..76edcbd32 100644
--- a/pkg/util/steps/refreshing.go
+++ b/pkg/util/steps/refreshing.go
@@ -7,6 +7,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"strings"
 	"time"
 
 	"github.com/sirupsen/logrus"
@@ -84,6 +85,12 @@ func (s authorizationRefreshingActionStep) run(ctx context.Context, log *logrus.
 		return true, err
 	}, timeoutCtx.Done())
 }
+
 func (s authorizationRefreshingActionStep) String() string {
 	return fmt.Sprintf("[AuthorizationRefreshingAction %s]", s.step)
 }
+
+func (s authorizationRefreshingActionStep) metricsTopic() string {
+	trimedName := strings.ReplaceAll(strings.ReplaceAll(s.step.String(), "[", ""), "]", "")
+	return fmt.Sprintf("refreshing.%s", shortName(trimedName))
+}
diff --git a/pkg/util/steps/runner.go b/pkg/util/steps/runner.go
index f3bb6c83c..1071a3d63 100644
--- a/pkg/util/steps/runner.go
+++ b/pkg/util/steps/runner.go
@@ -7,6 +7,7 @@ import (
 	"context"
 	"reflect"
 	"runtime"
+	"strings"
 	"time"
 
 	"github.com/sirupsen/logrus"
@@ -17,23 +18,46 @@ func FriendlyName(f interface{}) string {
 	return runtime.FuncForPC(reflect.ValueOf(f).Pointer()).Name()
 }
 
+func shortName(fullName string) string {
+	sepCheck := func(c rune) bool {
+		return c == '/' || c == '.'
+	}
+
+	fields := strings.FieldsFunc(strings.TrimSpace(fullName), sepCheck)
+
+	if size := len(fields); size > 0 {
+		return fields[size-1]
+	}
+	return fullName
+}
+
 // Step is the interface for steps that Runner can execute.
 type Step interface {
 	run(ctx context.Context, log *logrus.Entry) error
 	String() string
+	metricsTopic() string
 }
 
 // Run executes the provided steps in order until one fails or all steps
 // are completed. Errors from failed steps are returned directly.
-func Run(ctx context.Context, log *logrus.Entry, pollInterval time.Duration, steps []Step) error {
+// time cost for each step run will be recorded for metrics usage
+func Run(ctx context.Context, log *logrus.Entry, pollInterval time.Duration, steps []Step, now func() time.Time) (map[string]int64, error) {
+	stepTimeRun := make(map[string]int64)
 	for _, step := range steps {
 		log.Infof("running step %s", step)
+
+		startTime := time.Now()
 		err := step.run(ctx, log)
 
 		if err != nil {
 			log.Errorf("step %s encountered error: %s", step, err.Error())
-			return err
+			return nil, err
+		}
+
+		if now != nil {
+			currentTime := now()
+			stepTimeRun[step.metricsTopic()] = int64(currentTime.Sub(startTime).Seconds())
 		}
 	}
-	return nil
+	return stepTimeRun, nil
 }


Test patch:
diff --git a/pkg/backend/openshiftcluster_test.go b/pkg/backend/openshiftcluster_test.go
index 5f52271d3..9d74a617b 100644
--- a/pkg/backend/openshiftcluster_test.go
+++ b/pkg/backend/openshiftcluster_test.go
@@ -18,6 +18,7 @@ import (
 	"github.com/Azure/ARO-RP/pkg/cluster"
 	"github.com/Azure/ARO-RP/pkg/database"
 	"github.com/Azure/ARO-RP/pkg/env"
+	"github.com/Azure/ARO-RP/pkg/metrics"
 	"github.com/Azure/ARO-RP/pkg/metrics/noop"
 	"github.com/Azure/ARO-RP/pkg/util/billing"
 	"github.com/Azure/ARO-RP/pkg/util/encryption"
@@ -298,7 +299,7 @@ func TestBackendTry(t *testing.T) {
 				t.Fatal(err)
 			}
 
-			createManager := func(context.Context, *logrus.Entry, env.Interface, database.OpenShiftClusters, database.Gateway, encryption.AEAD, billing.Manager, *api.OpenShiftClusterDocument, *api.SubscriptionDocument, *rest.Config) (cluster.Interface, error) {
+			createManager := func(context.Context, *logrus.Entry, env.Interface, database.OpenShiftClusters, database.Gateway, encryption.AEAD, billing.Manager, *api.OpenShiftClusterDocument, *api.SubscriptionDocument, *rest.Config, metrics.Emitter) (cluster.Interface, error) {
 				return manager, nil
 			}
 
diff --git a/pkg/cluster/install_test.go b/pkg/cluster/install_test.go
index ab070d9b6..ae4a8d729 100644
--- a/pkg/cluster/install_test.go
+++ b/pkg/cluster/install_test.go
@@ -8,6 +8,7 @@ import (
 	"errors"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/golang/mock/gomock"
 	"github.com/onsi/gomega"
@@ -30,6 +31,27 @@ import (
 
 func failingFunc(context.Context) error { return errors.New("oh no!") }
 
+func successfulActionStep(context.Context) error { return nil }
+
+func successfulConditionStep(context.Context) (bool, error) { return true, nil }
+
+type fakeMetricsEmitter struct {
+	Metrics map[string]int64
+}
+
+func newfakeMetricsEmitter() *fakeMetricsEmitter {
+	m := make(map[string]int64)
+	return &fakeMetricsEmitter{
+		Metrics: m,
+	}
+}
+
+func (e *fakeMetricsEmitter) EmitGauge(topic string, value int64, dims map[string]string) {
+	e.Metrics[topic] = value
+}
+
+func (e *fakeMetricsEmitter) EmitFloat(topic string, value float64, dims map[string]string) {}
+
 var clusterOperator = &configv1.ClusterOperator{
 	ObjectMeta: metav1.ObjectMeta{
 		Name: "operator",
@@ -150,9 +172,10 @@ func TestStepRunnerWithInstaller(t *testing.T) {
 				kubernetescli: tt.kubernetescli,
 				configcli:     tt.configcli,
 				operatorcli:   tt.operatorcli,
+				now:           func() time.Time { return time.Now() },
 			}
 
-			err := m.runSteps(ctx, tt.steps)
+			err := m.runSteps(ctx, tt.steps, false)
 			if err != nil && err.Error() != tt.wantErr ||
 				err == nil && tt.wantErr != "" {
 				t.Error(err)
@@ -209,3 +232,64 @@ func TestUpdateProvisionedBy(t *testing.T) {
 		t.Error("version was not added")
 	}
 }
+
+func TestInstallationTimeMetrics(t *testing.T) {
+	_, log := testlog.New()
+	fm := newfakeMetricsEmitter()
+
+	for _, tt := range []struct {
+		name          string
+		steps         []steps.Step
+		wantedMetrics map[string]int64
+	}{
+		{
+			name: "Failed step run will not generate any install time metrics",
+			steps: []steps.Step{
+				steps.Action(successfulActionStep),
+				steps.Action(failingFunc),
+			},
+		},
+		{
+			name: "Succeeded step run will generate a valid install time metrics",
+			steps: []steps.Step{
+				steps.Action(successfulActionStep),
+				steps.Condition(successfulConditionStep, 30*time.Minute, true),
+				steps.AuthorizationRefreshingAction(nil, steps.Action(successfulActionStep)),
+			},
+			wantedMetrics: map[string]int64{
+				"backend.openshiftcluster.installtime.total":                             6,
+				"backend.openshiftcluster.installtime.action.successfulActionStep":       2,
+				"backend.openshiftcluster.installtime.condition.successfulConditionStep": 2,
+				"backend.openshiftcluster.installtime.refreshing.successfulActionStep":   2,
+			},
+		},
+	} {
+		t.Run(tt.name, func(t *testing.T) {
+			ctx := context.Background()
+			m := &manager{
+				log:            log,
+				metricsEmitter: fm,
+				now:            func() time.Time { return time.Now().Add(2 * time.Second) },
+			}
+
+			err := m.runSteps(ctx, tt.steps, true)
+			if err != nil {
+				if len(fm.Metrics) != 0 {
+					t.Error("fake metrics obj should be empty when run steps failed")
+				}
+			} else {
+				if tt.wantedMetrics != nil {
+					for k, v := range tt.wantedMetrics {
+						time, ok := fm.Metrics[k]
+						if !ok {
+							t.Errorf("unexpected metrics topic: %s", k)
+						}
+						if time != v {
+							t.Errorf("incorrect fake metrics obj, want: %d, got: %d", v, time)
+						}
+					}
+				}
+			}
+		})
+	}
+}
diff --git a/pkg/util/steps/runner_test.go b/pkg/util/steps/runner_test.go
index 9968475ab..9fa389571 100644
--- a/pkg/util/steps/runner_test.go
+++ b/pkg/util/steps/runner_test.go
@@ -41,6 +41,10 @@ func timingOutCondition(ctx context.Context) (bool, error) {
 	return false, nil
 }
 
+func currentTimeFunc() time.Time {
+	return time.Now()
+}
+
 func TestStepRunner(t *testing.T) {
 	for _, tt := range []struct {
 		name        string
@@ -328,7 +332,7 @@ func TestStepRunner(t *testing.T) {
 			h, log := testlog.New()
 			steps := tt.steps(controller)
 
-			err := Run(ctx, log, 25*time.Millisecond, steps)
+			_, err := Run(ctx, log, 25*time.Millisecond, steps, currentTimeFunc)
 			if err != nil && err.Error() != tt.wantErr ||
 				err == nil && tt.wantErr != "" {
 				t.Error(err)
@@ -341,3 +345,43 @@ func TestStepRunner(t *testing.T) {
 		})
 	}
 }
+
+func TestStepMetricsTopicNaming(t *testing.T) {
+	for _, tt := range []struct {
+		desc string
+		step Step
+		want string
+	}{
+		{
+			desc: "test action step naming",
+			step: Action(successfulFunc),
+			want: "action.successfulFunc",
+		},
+		{
+			desc: "test condition step naming",
+			step: Condition(alwaysTrueCondition, 1*time.Millisecond, true),
+			want: "condition.alwaysTrueCondition",
+		},
+		{
+			desc: "test refreshing step naming",
+			step: AuthorizationRefreshingAction(nil, Action(successfulFunc)),
+			want: "refreshing.successfulFunc",
+		},
+		{
+			desc: "test anonymous action step naming",
+			step: Action(func(context.Context) error { return nil }),
+			want: "action.func1",
+		},
+		{
+			desc: "test anonymous action step naming",
+			step: AuthorizationRefreshingAction(nil, Action(func(context.Context) error { return nil })),
+			want: "refreshing.func2",
+		},
+	} {
+		t.Run(tt.desc, func(t *testing.T) {
+			if got := tt.step.metricsTopic(); got != tt.want {
+				t.Errorf("incorrect step metrics topic, want: %s, got: %s", tt.want, got)
+			}
+		})
+	}
+}