Added gauge metrics to record reconcile time for app and pkg repo

Signed-off-by: sethiyash <yashsethiya97@gmail.com>

cmd/controller/run.go

@@ -99,6 +99,9 @@ func Run(opts Options, runLog logr.Logger) error {
 	appMetrics := metrics.NewAppMetrics()
 	appMetrics.RegisterAllMetrics()
 
+	reconcileTimeMetrics := metrics.NewReconcileTimeMetrics()
+	reconcileTimeMetrics.RegisterAllMetrics()
+
 	var server *apiserver.APIServer
 	if opts.StartAPIServer {
 		// assign bindPort to env var KAPPCTRL_API_PORT if available
@@ -198,6 +201,7 @@ func Run(opts Options, runLog logr.Logger) error {
 			AppClient:   kcClient,
 			KcConfig:    kcConfig,
 			AppMetrics:  appMetrics,
+			TimeMetrics: reconcileTimeMetrics,
 			CmdRunner:   sidecarCmdExec,
 			Kubeconf:    kubeconf,
 			CompInfo:    compInfo,
@@ -254,6 +258,7 @@ func Run(opts Options, runLog logr.Logger) error {
 			CoreClient:  coreClient,
 			AppClient:   kcClient,
 			KcConfig:    kcConfig,
+			TimeMetrics: reconcileTimeMetrics,
 			CmdRunner:   sidecarCmdExec,
 			Kubeconf:    kubeconf,
 			CacheFolder: cacheFolderPkgRepoApps,

pkg/app/app.go

@@ -55,9 +55,10 @@ type App struct {
 	memoizedKubernetesVersion string
 	memoizedKubernetesAPIs    []string
 
-	log        logr.Logger
-	opts       Opts
-	appMetrics *metrics.AppMetrics
+	log         logr.Logger
+	opts        Opts
+	appMetrics  *metrics.AppMetrics
+	timeMetrics *metrics.ReconcileTimeMetrics
 
 	pendingStatusUpdate   bool
 	flushAllStatusUpdates bool
@@ -66,11 +67,11 @@ type App struct {
 
 func NewApp(app v1alpha1.App, hooks Hooks,
 	fetchFactory fetch.Factory, templateFactory template.Factory,
-	deployFactory deploy.Factory, log logr.Logger, opts Opts, appMetrics *metrics.AppMetrics, compInfo ComponentInfo) *App {
+	deployFactory deploy.Factory, log logr.Logger, opts Opts, appMetrics *metrics.AppMetrics, timeMetrics *metrics.ReconcileTimeMetrics, compInfo ComponentInfo) *App {
 
 	return &App{app: app, appPrev: *(app.DeepCopy()), hooks: hooks,
 		fetchFactory: fetchFactory, templateFactory: templateFactory,
-		deployFactory: deployFactory, log: log, opts: opts, appMetrics: appMetrics, compInfo: compInfo}
+		deployFactory: deployFactory, log: log, opts: opts, appMetrics: appMetrics, timeMetrics: timeMetrics, compInfo: compInfo}
 }
 
 func (a *App) Name() string      { return a.app.Name }

pkg/app/app_deploy.go

@@ -5,6 +5,7 @@ package app
 
 import (
 	"fmt"
+	"time"
 
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/apis/kappctrl/v1alpha1"
 	ctldep "github.com/vmware-tanzu/carvel-kapp-controller/pkg/deploy"
@@ -13,6 +14,11 @@ import (
 )
 
 func (a *App) deploy(tplOutput string, changedFunc func(exec.CmdRunResult)) exec.CmdRunResult {
+	reconcileStartTS := time.Now()
+	defer func() {
+		a.timeMetrics.RegisterDeployTime(a.app.Kind, a.app.Name, a.app.Namespace, "", time.Since(reconcileStartTS))
+	}()
+
 	err := a.blockDeletion()
 	if err != nil {
 		return exec.NewCmdRunResultWithErr(fmt.Errorf("Blocking for deploy: %s", err))

pkg/app/app_factory.go

@@ -27,6 +27,7 @@ type CRDAppFactory struct {
 	AppClient        kcclient.Interface
 	KcConfig         *config.Config
 	AppMetrics       *metrics.AppMetrics
+	TimeMetrics      *metrics.ReconcileTimeMetrics
 	VendirConfigHook func(vendirconf.Config) vendirconf.Config
 	KbldAllowBuild   bool
 	CmdRunner        exec.CmdRunner
@@ -48,7 +49,7 @@ func (f *CRDAppFactory) NewCRDApp(app *kcv1alpha1.App, log logr.Logger) *CRDApp
 	templateFactory := template.NewFactory(f.CoreClient, fetchFactory, f.KbldAllowBuild, f.CmdRunner)
 	deployFactory := deploy.NewFactory(f.CoreClient, f.Kubeconf, f.KcConfig, f.CmdRunner, log)
 
-	return NewCRDApp(app, log, f.AppMetrics, f.AppClient, fetchFactory, templateFactory, deployFactory, f.CompInfo, Opts{
+	return NewCRDApp(app, log, f.AppMetrics, f.TimeMetrics, f.AppClient, fetchFactory, templateFactory, deployFactory, f.CompInfo, Opts{
 		DefaultSyncPeriod: f.KcConfig.AppDefaultSyncPeriod(),
 		MinimumSyncPeriod: f.KcConfig.AppMinimumSyncPeriod(),
 	})

pkg/app/app_fetch.go

@@ -20,6 +20,13 @@ const (
 )
 
 func (a *App) fetch(dstPath string) (string, exec.CmdRunResult) {
+	// update metrics with the total fetch time
+	reconcileStartTS := time.Now()
+	defer func() {
+		a.timeMetrics.RegisterFetchTime(a.app.Kind, a.app.Name, a.app.Namespace, "", time.Since(reconcileStartTS))
+	}()
+
+	// fetch init stage
 	if len(a.app.Spec.Fetch) == 0 {
 		return "", exec.NewCmdRunResultWithErr(fmt.Errorf("Expected at least one fetch option"))
 	}

pkg/app/app_reconcile.go

@@ -103,6 +103,11 @@ func (a *App) reconcileDeploy() error {
 }
 
 func (a *App) reconcileFetchTemplateDeploy() exec.CmdRunResult {
+	reconcileStartTS := time.Now()
+	defer func() {
+		a.timeMetrics.RegisterOverallTime(a.app.Kind, a.app.Name, a.app.Namespace, "", time.Since(reconcileStartTS))
+	}()
+
 	tmpDir := memdir.NewTmpDir("fetch-template-deploy")
 
 	err := tmpDir.Create()

pkg/app/app_reconcile_test.go

@@ -29,7 +29,10 @@ import (
 
 func Test_NoInspectReconcile_IfNoDeployAttempted(t *testing.T) {
 	log := logf.Log.WithName("kc")
-	var appMetrics = metrics.NewAppMetrics()
+	var (
+		appMetrics  = metrics.NewAppMetrics()
+		timeMetrics = metrics.NewReconcileTimeMetrics()
+	)
 
 	// The url under fetch is invalid, which will cause this
 	// app to fail before deploy.
@@ -52,7 +55,7 @@ func Test_NoInspectReconcile_IfNoDeployAttempted(t *testing.T) {
 	tmpFac := template.NewFactory(k8scs, fetchFac, false, exec.NewPlainCmdRunner())
 	deployFac := deploy.NewFactory(k8scs, kubeconfig.NewKubeconfig(k8scs, log), nil, exec.NewPlainCmdRunner(), log)
 
-	crdApp := NewCRDApp(&app, log, appMetrics, kappcs, fetchFac, tmpFac, deployFac, FakeComponentInfo{}, Opts{MinimumSyncPeriod: 30 * time.Second})
+	crdApp := NewCRDApp(&app, log, appMetrics, timeMetrics, kappcs, fetchFac, tmpFac, deployFac, FakeComponentInfo{}, Opts{MinimumSyncPeriod: 30 * time.Second})
 	_, err := crdApp.Reconcile(false)
 	assert.Nil(t, err, "unexpected error with reconciling", err)
 
@@ -86,7 +89,10 @@ func Test_NoInspectReconcile_IfNoDeployAttempted(t *testing.T) {
 
 func Test_NoInspectReconcile_IfInspectNotEnabled(t *testing.T) {
 	log := logf.Log.WithName("kc")
-	var appMetrics = metrics.NewAppMetrics()
+	var (
+		appMetrics  = metrics.NewAppMetrics()
+		timeMetrics = metrics.NewReconcileTimeMetrics()
+	)
 
 	app := v1alpha1.App{
 		ObjectMeta: metav1.ObjectMeta{
@@ -119,7 +125,7 @@ func Test_NoInspectReconcile_IfInspectNotEnabled(t *testing.T) {
 	tmpFac := template.NewFactory(k8scs, fetchFac, false, exec.NewPlainCmdRunner())
 	deployFac := deploy.NewFactory(k8scs, kubeconfig.NewKubeconfig(k8scs, log), nil, exec.NewPlainCmdRunner(), log)
 
-	crdApp := NewCRDApp(&app, log, appMetrics, kappcs, fetchFac, tmpFac, deployFac, FakeComponentInfo{}, Opts{MinimumSyncPeriod: 30 * time.Second})
+	crdApp := NewCRDApp(&app, log, appMetrics, timeMetrics, kappcs, fetchFac, tmpFac, deployFac, FakeComponentInfo{}, Opts{MinimumSyncPeriod: 30 * time.Second})
 	_, err := crdApp.Reconcile(false)
 	assert.Nil(t, err, "unexpected error with reconciling", err)
 
@@ -164,7 +170,10 @@ func Test_NoInspectReconcile_IfInspectNotEnabled(t *testing.T) {
 
 func Test_TemplateError_DisplayedInStatus_UsefulErrorMessageProperty(t *testing.T) {
 	log := logf.Log.WithName("kc")
-	var appMetrics = metrics.NewAppMetrics()
+	var (
+		appMetrics  = metrics.NewAppMetrics()
+		timeMetrics = metrics.NewReconcileTimeMetrics()
+	)
 
 	fetchInline := map[string]string{
 		"file.yml": `foo: #@ data.values.nothere`,
@@ -191,7 +200,7 @@ func Test_TemplateError_DisplayedInStatus_UsefulErrorMessageProperty(t *testing.
 	tmpFac := template.NewFactory(k8scs, fetchFac, false, exec.NewPlainCmdRunner())
 	deployFac := deploy.NewFactory(k8scs, kubeconfig.NewKubeconfig(k8scs, log), nil, exec.NewPlainCmdRunner(), log)
 
-	crdApp := NewCRDApp(&app, log, appMetrics, kappcs, fetchFac, tmpFac, deployFac, FakeComponentInfo{}, Opts{MinimumSyncPeriod: 30 * time.Second})
+	crdApp := NewCRDApp(&app, log, appMetrics, timeMetrics, kappcs, fetchFac, tmpFac, deployFac, FakeComponentInfo{}, Opts{MinimumSyncPeriod: 30 * time.Second})
 	_, err := crdApp.Reconcile(false)
 	assert.Nil(t, err, "Unexpected error with reconciling", err)
 

pkg/app/app_template.go

@@ -6,13 +6,19 @@ package app
 import (
 	"fmt"
 	"strings"
+	"time"
 
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/apis/kappctrl/v1alpha1"
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/exec"
 	ctltpl "github.com/vmware-tanzu/carvel-kapp-controller/pkg/template"
 )
 
 func (a *App) template(dirPath string) exec.CmdRunResult {
+	reconcileStartTS := time.Now()
+	defer func() {
+		a.timeMetrics.RegisterTemplateTime(a.app.Kind, a.app.Name, a.app.Namespace, "", time.Since(reconcileStartTS))
+	}()
+
 	if len(a.app.Spec.Template) == 0 {
 		return exec.NewCmdRunResultWithErr(fmt.Errorf("Expected at least one template option"))
 	}

pkg/app/app_template_test.go

@@ -61,7 +61,7 @@ func Test_BuildAdditionalDownwardAPIValues_MemoizedCallCount(t *testing.T) {
 		K8sAPIsCount:    &k8sAPIsCallCount,
 		KCVersionCount:  &kcVersionCallCount,
 	}
-	app := NewApp(appEmpty, Hooks{}, fetchFac, tmpFac, deployFac, log, Opts{}, metrics.NewAppMetrics(), fakeInfo)
+	app := NewApp(appEmpty, Hooks{}, fetchFac, tmpFac, deployFac, log, Opts{}, metrics.NewAppMetrics(), metrics.NewReconcileTimeMetrics(), fakeInfo)
 
 	dir, err := os.MkdirTemp("", "temp")
 	assert.NoError(t, err)

pkg/app/app_test.go

@@ -64,7 +64,7 @@ func Test_SecretRefs_RetrievesAllSecretRefs(t *testing.T) {
 	tmpFac := template.NewFactory(k8scs, fetchFac, false, exec.NewPlainCmdRunner())
 	deployFac := deploy.NewFactory(k8scs, kubeconfig.NewKubeconfig(k8scs, log), nil, exec.NewPlainCmdRunner(), log)
 
-	app := apppkg.NewApp(appWithRefs, apppkg.Hooks{}, fetchFac, tmpFac, deployFac, log, apppkg.Opts{}, nil, FakeComponentInfo{})
+	app := apppkg.NewApp(appWithRefs, apppkg.Hooks{}, fetchFac, tmpFac, deployFac, log, apppkg.Opts{}, nil, nil, FakeComponentInfo{})
 
 	out := app.SecretRefs()
 	assert.Truef(t, reflect.DeepEqual(out, expected), "Expected: %s\nGot: %s\n", expected, out)
@@ -88,7 +88,7 @@ func Test_SecretRefs_RetrievesNoSecretRefs_WhenNonePresent(t *testing.T) {
 	tmpFac := template.NewFactory(k8scs, fetchFac, false, exec.NewPlainCmdRunner())
 	deployFac := deploy.NewFactory(k8scs, kubeconfig.NewKubeconfig(k8scs, log), nil, exec.NewPlainCmdRunner(), log)
 
-	app := apppkg.NewApp(appEmpty, apppkg.Hooks{}, fetchFac, tmpFac, deployFac, log, apppkg.Opts{}, nil, FakeComponentInfo{})
+	app := apppkg.NewApp(appEmpty, apppkg.Hooks{}, fetchFac, tmpFac, deployFac, log, apppkg.Opts{}, nil, nil, FakeComponentInfo{})
 
 	out := app.SecretRefs()
 	assert.Equal(t, 0, len(out), "No SecretRefs to be returned")
@@ -126,7 +126,7 @@ func Test_ConfigMapRefs_RetrievesAllConfigMapRefs(t *testing.T) {
 	tmpFac := template.NewFactory(k8scs, fetchFac, false, exec.NewPlainCmdRunner())
 	deployFac := deploy.NewFactory(k8scs, kubeconfig.NewKubeconfig(k8scs, log), nil, exec.NewPlainCmdRunner(), log)
 
-	app := apppkg.NewApp(appWithRefs, apppkg.Hooks{}, fetchFac, tmpFac, deployFac, log, apppkg.Opts{}, nil, FakeComponentInfo{})
+	app := apppkg.NewApp(appWithRefs, apppkg.Hooks{}, fetchFac, tmpFac, deployFac, log, apppkg.Opts{}, nil, nil, FakeComponentInfo{})
 
 	out := app.ConfigMapRefs()
 	assert.Truef(t, reflect.DeepEqual(out, expected), "Expected: %s\nGot: %s\n", expected, out)
@@ -150,7 +150,7 @@ func Test_ConfigMapRefs_RetrievesNoConfigMapRefs_WhenNonePresent(t *testing.T) {
 	tmpFac := template.NewFactory(k8scs, fetchFac, false, exec.NewPlainCmdRunner())
 	deployFac := deploy.NewFactory(k8scs, kubeconfig.NewKubeconfig(k8scs, log), nil, exec.NewPlainCmdRunner(), log)
 
-	app := apppkg.NewApp(appEmpty, apppkg.Hooks{}, fetchFac, tmpFac, deployFac, log, apppkg.Opts{}, nil, FakeComponentInfo{})
+	app := apppkg.NewApp(appEmpty, apppkg.Hooks{}, fetchFac, tmpFac, deployFac, log, apppkg.Opts{}, nil, nil, FakeComponentInfo{})
 
 	out := app.ConfigMapRefs()
 	assert.Lenf(t, out, 0, "Expected: %s\nGot: %s\n", "No ConfigMapRefs to be returned", out)

pkg/app/crd_app.go

@@ -30,7 +30,7 @@ type CRDApp struct {
 
 // NewCRDApp creates new CRD app
 func NewCRDApp(appModel *kcv1alpha1.App, log logr.Logger, appMetrics *metrics.AppMetrics,
-	appClient kcclient.Interface, fetchFactory fetch.Factory,
+	timeMetrics *metrics.ReconcileTimeMetrics, appClient kcclient.Interface, fetchFactory fetch.Factory,
 	templateFactory template.Factory, deployFactory deploy.Factory,
 	compInfo ComponentInfo, opts Opts) *CRDApp {
 
@@ -41,7 +41,7 @@ func NewCRDApp(appModel *kcv1alpha1.App, log logr.Logger, appMetrics *metrics.Ap
 		UnblockDeletion: crdApp.unblockDeletion,
 		UpdateStatus:    crdApp.updateStatus,
 		WatchChanges:    crdApp.watchChanges,
-	}, fetchFactory, templateFactory, deployFactory, log, opts, appMetrics, compInfo)
+	}, fetchFactory, templateFactory, deployFactory, log, opts, appMetrics, timeMetrics, compInfo)
 
 	return crdApp
 }

pkg/metrics/reconcile_time_metrics.go

@@ -0,0 +1,85 @@
+package metrics
+
+import (
+	"github.com/prometheus/client_golang/prometheus"
+	"sigs.k8s.io/controller-runtime/pkg/metrics"
+	"time"
+)
+
+type ReconcileTimeMetrics struct {
+	reconcileTimeSeconds         *prometheus.GaugeVec
+	reconcileDeployTimeSeconds   *prometheus.GaugeVec
+	reconcileFetchTimeSeconds    *prometheus.GaugeVec
+	reconcileTemplateTimeSeconds *prometheus.GaugeVec
+}
+
+func NewReconcileTimeMetrics() *ReconcileTimeMetrics {
+	const (
+		metricNamespace     = "kappctrl_reconcile_time_seconds"
+		resourceTypeLabel   = "controller"
+		resourceNameLabel   = "name"
+		firstReconcileLabel = "firstReconcile"
+		namespace           = "namespace"
+	)
+	return &ReconcileTimeMetrics{
+		reconcileTimeSeconds: prometheus.NewGaugeVec(
+			prometheus.GaugeOpts{
+				Namespace: metricNamespace,
+				Name:      "reconcile_time_seconds",
+				Help:      "Overall time taken to reconcile a CR",
+			},
+			[]string{resourceTypeLabel, resourceNameLabel, namespace, firstReconcileLabel},
+		),
+		reconcileFetchTimeSeconds: prometheus.NewGaugeVec(
+			prometheus.GaugeOpts{
+				Namespace: metricNamespace,
+				Name:      "reconcile_fetch_time_seconds",
+				Help:      "Time taken to perform a fetch for a CR",
+			},
+			[]string{resourceTypeLabel, resourceNameLabel, namespace, firstReconcileLabel},
+		),
+		reconcileTemplateTimeSeconds: prometheus.NewGaugeVec(
+			prometheus.GaugeOpts{
+				Namespace: metricNamespace,
+				Name:      "reconcile_template_time_seconds",
+				Help:      "Time taken to perform a templating for a CR",
+			},
+			[]string{resourceTypeLabel, resourceNameLabel, namespace, firstReconcileLabel},
+		),
+		reconcileDeployTimeSeconds: prometheus.NewGaugeVec(
+			prometheus.GaugeOpts{
+				Namespace: metricNamespace,
+				Name:      "reconcile_deploy_time_seconds",
+				Help:      "Time taken to perform a deploy for a CR",
+			},
+			[]string{resourceTypeLabel, resourceNameLabel, namespace, firstReconcileLabel},
+		),
+	}
+}
+
+func (tm *ReconcileTimeMetrics) RegisterAllMetrics() {
+	once.Do(func() {
+		metrics.Registry.MustRegister(
+			tm.reconcileTimeSeconds,
+			tm.reconcileFetchTimeSeconds,
+			tm.reconcileTemplateTimeSeconds,
+			tm.reconcileDeployTimeSeconds,
+		)
+	})
+}
+
+func (tm *ReconcileTimeMetrics) RegisterOverallTime(resourceType, name, namespace, firstReconcile string, time time.Duration) {
+	tm.reconcileTimeSeconds.WithLabelValues(resourceType, name, namespace, firstReconcile).Set(time.Seconds())
+}
+
+func (tm *ReconcileTimeMetrics) RegisterFetchTime(resourceType, name, namespace, firstReconcile string, time time.Duration) {
+	tm.reconcileFetchTimeSeconds.WithLabelValues(resourceType, name, namespace, firstReconcile).Set(time.Seconds())
+}
+
+func (tm *ReconcileTimeMetrics) RegisterTemplateTime(resourceType, name, namespace, firstReconcile string, time time.Duration) {
+	tm.reconcileTemplateTimeSeconds.WithLabelValues(resourceType, name, namespace, firstReconcile).Set(time.Seconds())
+}
+
+func (tm *ReconcileTimeMetrics) RegisterDeployTime(resourceType, name, namespace, firstReconcile string, time time.Duration) {
+	tm.reconcileDeployTimeSeconds.WithLabelValues(resourceType, name, namespace, firstReconcile).Set(time.Seconds())
+}

pkg/pkgrepository/app.go

@@ -8,6 +8,7 @@ import (
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/apis/kappctrl/v1alpha1"
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/deploy"
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/fetch"
+	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/metrics"
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/reftracker"
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/template"
 	types "k8s.io/apimachinery/pkg/types"
@@ -29,17 +30,20 @@ type App struct {
 	templateFactory template.Factory
 	deployFactory   deploy.Factory
 
+	timeMetrics *metrics.ReconcileTimeMetrics
+
 	log logr.Logger
 
 	pendingStatusUpdate   bool
 	flushAllStatusUpdates bool
 }
 
 // NewApp creates a new instance of an App based on v1alpha1.App
-func NewApp(app v1alpha1.App, hooks Hooks, fetchFactory fetch.Factory, templateFactory template.Factory, deployFactory deploy.Factory, log logr.Logger, pkgRepoUID types.UID) *App {
+func NewApp(app v1alpha1.App, hooks Hooks, fetchFactory fetch.Factory, templateFactory template.Factory, deployFactory deploy.Factory,
+	log logr.Logger, timeMetrics *metrics.ReconcileTimeMetrics, pkgRepoUID types.UID) *App {
 	return &App{app: app, appPrev: *(app.DeepCopy()), hooks: hooks,
 		fetchFactory: fetchFactory, templateFactory: templateFactory,
-		deployFactory: deployFactory, log: log, pkgRepoUID: pkgRepoUID}
+		deployFactory: deployFactory, log: log, timeMetrics: timeMetrics, pkgRepoUID: pkgRepoUID}
 }
 
 func (a *App) Name() string      { return a.app.Name }

pkg/pkgrepository/app_deploy.go

@@ -5,6 +5,7 @@ package pkgrepository
 
 import (
 	"fmt"
+	"time"
 
 	"github.com/vmware-tanzu/carvel-kapp-controller/pkg/apis/kappctrl/v1alpha1"
 	ctldep "github.com/vmware-tanzu/carvel-kapp-controller/pkg/deploy"
@@ -13,6 +14,11 @@ import (
 )
 
 func (a *App) deploy(tplOutput string) exec.CmdRunResult {
+	reconcileStartTS := time.Now()
+	defer func() {
+		a.timeMetrics.RegisterDeployTime(a.app.Kind, a.app.Name, a.app.Namespace, "", time.Since(reconcileStartTS))
+	}()
+
 	err := a.blockDeletion()
 	if err != nil {
 		return exec.NewCmdRunResultWithErr(fmt.Errorf("Blocking for deploy: %s", err))