diff --git a/pkg/appfile/parser.go b/pkg/appfile/parser.go index 6a1e8122d..26305a691 100644 --- a/pkg/appfile/parser.go +++ b/pkg/appfile/parser.go @@ -94,7 +94,7 @@ func NewDryRunApplicationParser(cli client.Client, dm discoverymapper.DiscoveryM func (p *Parser) GenerateAppFile(ctx context.Context, app *v1beta1.Application) (*Appfile, error) { if ctx, ok := ctx.(monitorContext.Context); ok { subCtx := ctx.Fork("generate-app-file", monitorContext.DurationMetric(func(v float64) { - metrics.ParseAppFileDurationHistogram.WithLabelValues("application").Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("generate-appfile").Observe(v) })) defer subCtx.Commit("finish generate appFile") } diff --git a/pkg/controller/core.oam.dev/v1alpha2/application/application_controller.go b/pkg/controller/core.oam.dev/v1alpha2/application/application_controller.go index 60a55950d..08437f40b 100644 --- a/pkg/controller/core.oam.dev/v1alpha2/application/application_controller.go +++ b/pkg/controller/core.oam.dev/v1alpha2/application/application_controller.go @@ -206,7 +206,9 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Resu authCtx := logCtx.Fork("execute application workflow") defer authCtx.Commit("finish execute application workflow") authCtx = auth.MonitorContextWithUserInfo(authCtx, app) + tBeginWorkflowExecution := time.Now() workflowState, err := executor.ExecuteRunners(authCtx, runners) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("execute-workflow").Observe(time.Since(tBeginWorkflowExecution).Seconds()) if err != nil { logCtx.Error(err, "[handle workflow]") r.Recorder.Event(app, event.Warning(velatypes.ReasonFailedWorkflow, err)) @@ -287,6 +289,8 @@ func (r *Reconciler) stateKeep(logCtx monitorContext.Context, handler *AppHandle if feature.DefaultMutableFeatureGate.Enabled(features.ApplyOnce) { return } + t := time.Now() + defer metrics.AppReconcileStageDurationHistogram.WithLabelValues("state-keep").Observe(time.Since(t).Seconds()) if err := handler.resourceKeeper.StateKeep(logCtx); err != nil { logCtx.Error(err, "Failed to run prevent-configuration-drift") r.Recorder.Event(app, event.Warning(velatypes.ReasonFailedStateKeep, err)) @@ -296,7 +300,7 @@ func (r *Reconciler) stateKeep(logCtx monitorContext.Context, handler *AppHandle func (r *Reconciler) gcResourceTrackers(logCtx monitorContext.Context, handler *AppHandler, phase common.ApplicationPhase, gcOutdated bool, isUpdate bool) (ctrl.Result, error) { subCtx := logCtx.Fork("gc_resourceTrackers", monitorContext.DurationMetric(func(v float64) { - metrics.GCResourceTrackersDurationHistogram.WithLabelValues("-").Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("gc-rt").Observe(v) })) defer subCtx.Commit("finish gc resourceTrackers") @@ -365,7 +369,7 @@ func (r *Reconciler) handleFinalizers(ctx monitorContext.Context, app *v1beta1.A if app.ObjectMeta.DeletionTimestamp.IsZero() { if !meta.FinalizerExists(app, oam.FinalizerResourceTracker) { subCtx := ctx.Fork("handle-finalizers", monitorContext.DurationMetric(func(v float64) { - metrics.HandleFinalizersDurationHistogram.WithLabelValues("application", "add").Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("add-finalizer").Observe(v) })) defer subCtx.Commit("finish add finalizers") meta.AddFinalizer(app, oam.FinalizerResourceTracker) @@ -376,7 +380,7 @@ func (r *Reconciler) handleFinalizers(ctx monitorContext.Context, app *v1beta1.A } else { if slices.Contains(app.GetFinalizers(), oam.FinalizerResourceTracker) { subCtx := ctx.Fork("handle-finalizers", monitorContext.DurationMetric(func(v float64) { - metrics.HandleFinalizersDurationHistogram.WithLabelValues("application", "remove").Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("remove-finalizer").Observe(v) })) defer subCtx.Commit("finish remove finalizers") rootRT, currentRT, historyRTs, cvRT, err := resourcetracker.ListApplicationResourceTrackers(ctx, r.Client, app) @@ -443,6 +447,10 @@ func (r *Reconciler) updateStatus(ctx context.Context, app *v1beta1.Application, } func (r *Reconciler) doWorkflowFinish(logCtx monitorContext.Context, app *v1beta1.Application, handler *AppHandler, state workflowv1alpha1.WorkflowRunPhase) { + logCtx = logCtx.Fork("do-workflow-finish", monitorContext.DurationMetric(func(v float64) { + metrics.AppReconcileStageDurationHistogram.WithLabelValues("do-workflow-finish").Observe(v) + })) + defer logCtx.Commit("do-workflow-finish") app.Status.Workflow.Finished = true app.Status.Workflow.EndTime = metav1.Now() executor.StepStatusCache.Delete(fmt.Sprintf("%s-%s", app.Name, app.Namespace)) diff --git a/pkg/controller/core.oam.dev/v1alpha2/application/apply.go b/pkg/controller/core.oam.dev/v1alpha2/application/apply.go index b1a4a8e8f..fbcf2ea84 100644 --- a/pkg/controller/core.oam.dev/v1alpha2/application/apply.go +++ b/pkg/controller/core.oam.dev/v1alpha2/application/apply.go @@ -19,6 +19,7 @@ package application import ( "context" "sync" + "time" "github.com/pkg/errors" corev1 "k8s.io/api/core/v1" @@ -67,7 +68,7 @@ type AppHandler struct { func NewAppHandler(ctx context.Context, r *Reconciler, app *v1beta1.Application, parser *appfile.Parser) (*AppHandler, error) { if ctx, ok := ctx.(monitorContext.Context); ok { subCtx := ctx.Fork("create-app-handler", monitorContext.DurationMetric(func(v float64) { - metrics.CreateAppHandlerDurationHistogram.WithLabelValues("application").Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("create-app-handler").Observe(v) })) defer subCtx.Commit("finish create appHandler") } @@ -411,6 +412,8 @@ type garbageCollectFunc func(ctx context.Context, h *AppHandler) error // - clean up legacy app revisions // - clean up legacy component revisions func garbageCollection(ctx context.Context, h *AppHandler) error { + t := time.Now() + defer metrics.AppReconcileStageDurationHistogram.WithLabelValues("gc-rev").Observe(time.Since(t).Seconds()) collectFuncs := []garbageCollectFunc{ garbageCollectFunc(cleanUpApplicationRevision), garbageCollectFunc(cleanUpWorkflowComponentRevision), @@ -427,7 +430,7 @@ func garbageCollection(ctx context.Context, h *AppHandler) error { func (h *AppHandler) ApplyPolicies(ctx context.Context, af *appfile.Appfile) error { if ctx, ok := ctx.(monitorContext.Context); ok { subCtx := ctx.Fork("apply-policies", monitorContext.DurationMetric(func(v float64) { - metrics.ApplyPoliciesDurationHistogram.WithLabelValues("application").Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("apply-policies").Observe(v) })) defer subCtx.Commit("finish apply policies") } diff --git a/pkg/controller/core.oam.dev/v1alpha2/application/generator.go b/pkg/controller/core.oam.dev/v1alpha2/application/generator.go index b8bf1a7a7..8e2d392d2 100644 --- a/pkg/controller/core.oam.dev/v1alpha2/application/generator.go +++ b/pkg/controller/core.oam.dev/v1alpha2/application/generator.go @@ -88,6 +88,9 @@ func (h *AppHandler) GenerateApplicationSteps(ctx monitorContext.Context, af *appfile.Appfile, appRev *v1beta1.ApplicationRevision) (*wfTypes.WorkflowInstance, []wfTypes.TaskRunner, error) { + t := time.Now() + defer metrics.AppReconcileStageDurationHistogram.WithLabelValues("generate-app-steps").Observe(time.Since(t).Seconds()) + appLabels := map[string]string{ oam.LabelAppName: app.Name, oam.LabelAppNamespace: app.Namespace, diff --git a/pkg/controller/core.oam.dev/v1alpha2/application/revision.go b/pkg/controller/core.oam.dev/v1alpha2/application/revision.go index abf3ac452..c46864755 100644 --- a/pkg/controller/core.oam.dev/v1alpha2/application/revision.go +++ b/pkg/controller/core.oam.dev/v1alpha2/application/revision.go @@ -22,6 +22,7 @@ import ( "reflect" "sort" "strings" + "time" "github.com/hashicorp/go-version" "github.com/kubevela/pkg/util/k8s" @@ -207,7 +208,7 @@ func SprintComponentManifest(cm *types.ComponentManifest) string { func (h *AppHandler) PrepareCurrentAppRevision(ctx context.Context, af *appfile.Appfile) error { if ctx, ok := ctx.(monitorContext.Context); ok { subCtx := ctx.Fork("prepare-current-appRevision", monitorContext.DurationMetric(func(v float64) { - metrics.PrepareCurrentAppRevisionDurationHistogram.WithLabelValues("application").Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("prepare-current-apprev").Observe(v) })) defer subCtx.Commit("finish prepare current appRevision") } @@ -823,7 +824,7 @@ func (h *AppHandler) FinalizeAndApplyAppRevision(ctx context.Context) error { if ctx, ok := ctx.(monitorContext.Context); ok { subCtx := ctx.Fork("apply-app-revision", monitorContext.DurationMetric(func(v float64) { - metrics.ApplyAppRevisionDurationHistogram.WithLabelValues("application").Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("apply-apprev").Observe(v) })) defer subCtx.Commit("finish apply app revision") } @@ -878,6 +879,12 @@ func (h *AppHandler) UpdateAppLatestRevisionStatus(ctx context.Context) error { // skip update if app revision is not changed return nil } + if ctx, ok := ctx.(monitorContext.Context); ok { + subCtx := ctx.Fork("update-apprev-status", monitorContext.DurationMetric(func(v float64) { + metrics.AppReconcileStageDurationHistogram.WithLabelValues("update-apprev-status").Observe(v) + })) + defer subCtx.Commit("application revision status updated") + } revName := h.currentAppRev.Name revNum, _ := util.ExtractRevisionNum(revName, "-") h.app.Status.LatestRevision = &common.Revision{ @@ -900,6 +907,8 @@ func cleanUpApplicationRevision(ctx context.Context, h *AppHandler) error { if DisableAllApplicationRevision { return nil } + t := time.Now() + defer metrics.AppReconcileStageDurationHistogram.WithLabelValues("gc-rev.apprev").Observe(time.Since(t).Seconds()) sortedRevision, err := GetSortedAppRevisions(ctx, h.r.Client, h.app.Name, h.app.Namespace) if err != nil { return err @@ -952,6 +961,8 @@ func cleanUpWorkflowComponentRevision(ctx context.Context, h *AppHandler) error if DisableAllComponentRevision { return nil } + t := time.Now() + defer metrics.AppReconcileStageDurationHistogram.WithLabelValues("gc-rev.comprev").Observe(time.Since(t).Seconds()) // collect component revision in use compRevisionInUse := map[string]map[string]struct{}{} ctx = auth.ContextWithUserInfo(ctx, h.app) diff --git a/pkg/monitor/metrics/application.go b/pkg/monitor/metrics/application.go index c2d2b95b0..0dbd2d619 100644 --- a/pkg/monitor/metrics/application.go +++ b/pkg/monitor/metrics/application.go @@ -23,58 +23,10 @@ import ( ) var ( - // CreateAppHandlerDurationHistogram report the create appHandler execution duration. - CreateAppHandlerDurationHistogram = prometheus.NewHistogramVec(prometheus.HistogramOpts{ - Name: "create_app_handler_time_seconds", - Help: "create appHandler duration distributions, this operate will list ResourceTrackers.", - Buckets: velametrics.FineGrainedBuckets, - ConstLabels: prometheus.Labels{}, - }, []string{"controller"}) - - // HandleFinalizersDurationHistogram report the handle finalizers execution duration. - HandleFinalizersDurationHistogram = prometheus.NewHistogramVec(prometheus.HistogramOpts{ - Name: "handle_finalizers_time_seconds", - Help: "handle finalizers duration distributions.", - Buckets: velametrics.FineGrainedBuckets, - ConstLabels: prometheus.Labels{}, - }, []string{"controller", "type"}) - - // ParseAppFileDurationHistogram report the parse appFile execution duration. - ParseAppFileDurationHistogram = prometheus.NewHistogramVec(prometheus.HistogramOpts{ - Name: "parse_appFile_time_seconds", - Help: "parse appFile duration distributions.", - Buckets: velametrics.FineGrainedBuckets, - ConstLabels: prometheus.Labels{}, - }, []string{"controller"}) - - // PrepareCurrentAppRevisionDurationHistogram report the parse current appRevision execution duration. - PrepareCurrentAppRevisionDurationHistogram = prometheus.NewHistogramVec(prometheus.HistogramOpts{ - Name: "prepare_current_appRevision_time_seconds", - Help: "parse current appRevision duration distributions.", - Buckets: velametrics.FineGrainedBuckets, - ConstLabels: prometheus.Labels{}, - }, []string{"controller"}) - - // ApplyAppRevisionDurationHistogram report the apply appRevision execution duration. - ApplyAppRevisionDurationHistogram = prometheus.NewHistogramVec(prometheus.HistogramOpts{ - Name: "apply_appRevision_time_seconds", - Help: "apply appRevision duration distributions.", - Buckets: velametrics.FineGrainedBuckets, - ConstLabels: prometheus.Labels{}, - }, []string{"controller"}) - - // ApplyPoliciesDurationHistogram report execution duration for applying policies - ApplyPoliciesDurationHistogram = prometheus.NewHistogramVec(prometheus.HistogramOpts{ - Name: "apply_policies", - Help: "render and dispatch policy duration distributions.", - Buckets: velametrics.FineGrainedBuckets, - ConstLabels: prometheus.Labels{}, - }, []string{"controller"}) - - // GCResourceTrackersDurationHistogram report the gc resourceTrackers execution duration. - GCResourceTrackersDurationHistogram = prometheus.NewHistogramVec(prometheus.HistogramOpts{ - Name: "gc_resourceTrackers_time_seconds", - Help: "gc resourceTrackers duration distributions.", + // AppReconcileStageDurationHistogram report staged reconcile time for application + AppReconcileStageDurationHistogram = prometheus.NewHistogramVec(prometheus.HistogramOpts{ + Name: "kubevela_app_reconcile_time_seconds", + Help: "application reconcile time costs.", Buckets: velametrics.FineGrainedBuckets, ConstLabels: prometheus.Labels{}, }, []string{"stage"}) diff --git a/pkg/monitor/metrics/workflow.go b/pkg/monitor/metrics/workflow.go index af0c50b42..e133568be 100644 --- a/pkg/monitor/metrics/workflow.go +++ b/pkg/monitor/metrics/workflow.go @@ -32,14 +32,8 @@ var ( ) var collectorGroup = []prometheus.Collector{ - CreateAppHandlerDurationHistogram, - HandleFinalizersDurationHistogram, - ParseAppFileDurationHistogram, - PrepareCurrentAppRevisionDurationHistogram, - ApplyAppRevisionDurationHistogram, - ApplyPoliciesDurationHistogram, + AppReconcileStageDurationHistogram, StepDurationHistogram, - GCResourceTrackersDurationHistogram, ListResourceTrackerCounter, ApplicationReconcileTimeHistogram, ApplyComponentTimeHistogram, diff --git a/pkg/resourcekeeper/gc.go b/pkg/resourcekeeper/gc.go index ac8160fb0..42159119d 100644 --- a/pkg/resourcekeeper/gc.go +++ b/pkg/resourcekeeper/gc.go @@ -164,7 +164,7 @@ func (h *gcHandler) monitor(stage string) func() { begin := time.Now() return func() { v := time.Since(begin).Seconds() - metrics.GCResourceTrackersDurationHistogram.WithLabelValues(stage).Observe(v) + metrics.AppReconcileStageDurationHistogram.WithLabelValues("gc-rt." + stage).Observe(v) } }