record time of app processing procedure

tkestack · Jul 29, 2024 · 8e3942d · 8e3942d
1 parent 9679f83
commit 8e3942d
Show file tree

Hide file tree

Showing 5 changed files with 81 additions and 10 deletions.
diff --git a/pkg/application/controller/app/action/install.go b/pkg/application/controller/app/action/install.go
@@ -22,6 +22,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"time"
 
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	applicationv1 "tkestack.io/tke/api/application/v1"
@@ -46,7 +47,28 @@ func Install(ctx context.Context,
 	updateStatusFunc applicationprovider.UpdateStatusFunc) (*applicationv1.App, error) {
 	hooks := getHooks(app)
 
+	var beginInstallTime, preInstallTime, pullChartTime, installTime, postInstallTime time.Time
+	defer func() {
+		var preInstallCost, pullChartCost, installCost, postInstallCost int
+		if !preInstallTime.IsZero() {
+			preInstallCost = int(preInstallTime.Sub(beginInstallTime).Seconds())
+			if !pullChartTime.IsZero() {
+				pullChartCost = int(pullChartTime.Sub(preInstallTime).Seconds())
+				if !installTime.IsZero() {
+					installCost = int(installTime.Sub(pullChartTime).Seconds())
+					if !postInstallTime.IsZero() {
+						postInstallCost = int(postInstallTime.Sub(installTime).Milliseconds())
+					}
+				}
+			}
+		}
+		log.Infof("handle for %s/%s cost: %d %d %d %d",
+			app.Namespace, app.Name, preInstallCost, pullChartCost, installCost, postInstallCost)
+	}()
+
+	beginInstallTime = time.Now()
 	err := hooks.PreInstall(ctx, applicationClient, platformClient, app, repo, updateStatusFunc)
+	preInstallTime = time.Now()
 	if err != nil {
 		if updateStatusFunc != nil {
 			newStatus := app.Status.DeepCopy()
@@ -65,6 +87,7 @@ func Install(ctx context.Context,
 	}
 
 	destfile, err := Pull(ctx, applicationClient, platformClient, app, repo, updateStatusFunc)
+	pullChartTime = time.Now()
 	if err != nil {
 		newStatus := app.Status.DeepCopy()
 		if updateStatusFunc != nil {
@@ -131,7 +154,7 @@ func Install(ctx context.Context,
 		Wait:             app.Spec.Chart.InstallPara.Wait,
 		WaitForJobs:      app.Spec.Chart.InstallPara.WaitForJobs,
 	})
-
+	installTime = time.Now()
 	if err != nil {
 		if errors.Is(err, errors.New("chart manifest is empty")) {
 			log.Errorf(fmt.Sprintf("ERROR: install cluster %s app %s manifest is empty, file %s", app.Spec.TargetCluster, app.Name, destfile))
@@ -158,6 +181,7 @@ func Install(ctx context.Context,
 	}
 
 	err = hooks.PostInstall(ctx, applicationClient, platformClient, app, repo, updateStatusFunc)
+	postInstallTime = time.Now()
 	// 先走完hook，在更新app状态为succeed
 	if err != nil {
 		if updateStatusFunc != nil {

diff --git a/pkg/application/controller/app/action/uninstall.go b/pkg/application/controller/app/action/uninstall.go
@@ -21,6 +21,7 @@ package action
 import (
 	"context"
 	"errors"
+	"time"
 
 	"helm.sh/helm/v3/pkg/release"
 	"helm.sh/helm/v3/pkg/storage/driver"
@@ -30,6 +31,7 @@ import (
 	appconfig "tkestack.io/tke/pkg/application/config"
 	helmaction "tkestack.io/tke/pkg/application/helm/action"
 	"tkestack.io/tke/pkg/application/util"
+	"tkestack.io/tke/pkg/util/log"
 )
 
 // Uninstall provides the implementation of 'helm uninstall'.
@@ -39,7 +41,25 @@ func Uninstall(ctx context.Context,
 	app *applicationv1.App,
 	repo appconfig.RepoConfiguration) (*release.UninstallReleaseResponse, error) {
 	hooks := getHooks(app)
+
+	var beginUninstallTime, preUninstallTime, uninstallTime, postUninstallTime time.Time
+	defer func() {
+		var preUninstallCost, uninstallCost, postUninstallCost int
+		if !preUninstallTime.IsZero() {
+			preUninstallCost = int(preUninstallTime.Sub(beginUninstallTime).Seconds())
+			if !uninstallTime.IsZero() {
+				uninstallCost = int(uninstallTime.Sub(preUninstallTime).Seconds())
+				if !postUninstallTime.IsZero() {
+					postUninstallCost = int(postUninstallTime.Sub(uninstallTime).Seconds())
+				}
+			}
+		}
+		log.Infof("handle for %s/%s cost: %d %d %d",
+			app.Namespace, app.Name, preUninstallCost, uninstallCost, postUninstallCost)
+	}()
+	beginUninstallTime = time.Now()
 	err := hooks.PreUninstall(ctx, applicationClient, platformClient, app, repo)
+	preUninstallTime = time.Now()
 	if err != nil {
 		return nil, err
 	}
@@ -52,11 +72,13 @@ func Uninstall(ctx context.Context,
 		ReleaseName: app.Spec.Name,
 		Timeout:     defaultTimeout,
 	})
+	uninstallTime = time.Now()
 
 	if err != nil && !errors.Is(err, driver.ErrReleaseNotFound) {
 		return resp, err
 	}
 
 	err = hooks.PostUninstall(ctx, applicationClient, platformClient, app, repo)
+	postUninstallTime = time.Now()
 	return resp, err
 }
diff --git a/pkg/application/controller/app/action/upgrade.go b/pkg/application/controller/app/action/upgrade.go
@@ -22,6 +22,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"time"
 
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	applicationv1 "tkestack.io/tke/api/application/v1"
@@ -46,7 +47,28 @@ func Upgrade(ctx context.Context,
 	updateStatusFunc applicationprovider.UpdateStatusFunc) (*applicationv1.App, error) {
 	hooks := getHooks(app)
 
+	var beginUpgradeTime, preUpgradeTime, pullChartTime, upgradeTime, postupgradeTime time.Time
+	defer func() {
+		var preUpgradeCost, pullChartCost, upgradeCost, postUpgradeCost int
+		if !preUpgradeTime.IsZero() {
+			preUpgradeCost = int(preUpgradeTime.Sub(beginUpgradeTime).Seconds())
+			if !pullChartTime.IsZero() {
+				pullChartCost = int(pullChartTime.Sub(preUpgradeTime).Seconds())
+				if !upgradeTime.IsZero() {
+					upgradeCost = int(upgradeTime.Sub(pullChartTime).Seconds())
+					if !postupgradeTime.IsZero() {
+						postUpgradeCost = int(postupgradeTime.Sub(upgradeTime).Milliseconds())
+					}
+				}
+			}
+		}
+		log.Infof("handle for %s/%s cost: %d %d %d %d",
+			app.Namespace, app.Name, preUpgradeCost, pullChartCost, upgradeCost, postUpgradeCost)
+	}()
+
+	beginUpgradeTime = time.Now()
 	err := hooks.PreUpgrade(ctx, applicationClient, platformClient, app, repo, updateStatusFunc)
+	preUpgradeTime = time.Now()
 	if err != nil {
 		if updateStatusFunc != nil {
 			newStatus := app.Status.DeepCopy()
@@ -65,6 +87,7 @@ func Upgrade(ctx context.Context,
 	}
 
 	destfile, err := Pull(ctx, applicationClient, platformClient, app, repo, updateStatusFunc)
+	pullChartTime = time.Now()
 	if err != nil {
 		newStatus := app.Status.DeepCopy()
 		if updateStatusFunc != nil {
@@ -124,6 +147,7 @@ func Upgrade(ctx context.Context,
 		Wait:             app.Spec.Chart.UpgradePara.Wait,
 		WaitForJobs:      app.Spec.Chart.UpgradePara.WaitForJobs,
 	})
+	upgradeTime = time.Now()
 	if err != nil {
 		if errors.Is(err, errors.New("chart manifest is empty")) {
 			log.Errorf(fmt.Sprintf("ERROR: upgrade cluster %s app %s manifest is empty, file %s", app.Spec.TargetCluster, app.Name, destfile))
@@ -191,6 +215,7 @@ func Upgrade(ctx context.Context,
 	}
 
 	err = hooks.PostUpgrade(ctx, applicationClient, platformClient, app, repo, updateStatusFunc)
+	postupgradeTime = time.Now()
 	// 先走完hook，在更新app状态为succeed
 	if err != nil {
 		if updateStatusFunc != nil {

diff --git a/pkg/application/helm/action/install.go b/pkg/application/helm/action/install.go
@@ -111,11 +111,11 @@ func (c *Client) InstallWithLocal(ctx context.Context, options *InstallOptions,
 		for _, rel := range rels {
 			if rel.Info.Status == release.StatusDeployed {
 				// release 记录已存在，状态为deployed，不再进行重复安装
-				log.Infof("Release %s is already exist. igonre it now.", options.ReleaseName)
+				log.Infof("Release %s for %s is already exist. igonre it now.", options.ReleaseName, options.Namespace)
 				return nil, nil
 			}
 			// release 记录已存在，状态为其他，删除重试
-			log.Infof("install release %s is already exist, status is %s. delete it now.", options.ReleaseName, rel.Info.Status)
+			log.Infof("install release %s for %s is already exist, status is %s. delete it now.", options.ReleaseName, options.Namespace, rel.Info.Status)
 			actionConfig.Releases.Delete(rel.Name, rel.Version)
 		}
 	}
@@ -184,7 +184,7 @@ func (c *Client) InstallWithLocal(ctx context.Context, options *InstallOptions,
 	}
 
 	if chartRequested.Metadata.Deprecated {
-		log.Warnf("This chart %s/%s is deprecated", options.ChartRepo, options.Chart)
+		log.Warnf("This chart %s/%s for %s is deprecated", options.ChartRepo, options.Chart, options.Namespace)
 	}
 
 	if req := chartRequested.Metadata.Dependencies; req != nil {

diff --git a/pkg/application/helm/action/upgrade.go b/pkg/application/helm/action/upgrade.go
@@ -80,7 +80,7 @@ func (c *Client) Upgrade(ctx context.Context, options *UpgradeOptions) (*release
 		histClient.Max = 1
 		rels, err := histClient.Run(options.ReleaseName)
 		if errors.Is(err, driver.ErrReleaseNotFound) {
-			log.Infof("Release %d does not exist. Installing it now.", options.ReleaseName)
+			log.Infof("Release %d for %s does not exist. Installing it now.", options.ReleaseName, options.Namespace)
 			return c.Install(ctx, &InstallOptions{
 				DryRun:           options.DryRun,
 				DependencyUpdate: options.DependencyUpdate,
@@ -100,7 +100,7 @@ func (c *Client) Upgrade(ctx context.Context, options *UpgradeOptions) (*release
 		for _, rel := range rels {
 			if rel.Info.Status == release.StatusPendingInstall || rel.Info.Status == release.StatusPendingUpgrade || rel.Info.Status == release.StatusPendingRollback {
 				// if release is pending, delete it.
-				log.Infof("upgrade release %s is already exist, status is %s. delete it now.", options.ReleaseName, rel.Info.Status)
+				log.Infof("upgrade release %s for %s is already exist, status is %s. delete it now.", options.ReleaseName, options.Namespace, rel.Info.Status)
 				actionConfig.Releases.Delete(rel.Name, rel.Version)
 			}
 		}
@@ -171,27 +171,27 @@ func (c *Client) Upgrade(ctx context.Context, options *UpgradeOptions) (*release
 	}
 
 	if chartRequested.Metadata.Deprecated {
-		log.Warnf("This chart %s/%s is deprecated", options.ChartRepo, options.Chart)
+		log.Warnf("This chart %s/%s for %s is deprecated", options.ChartRepo, options.Chart, options.Namespace)
 	}
 	rel, err := client.RunWithContext(ctx, options.ReleaseName, chartRequested, options.Values)
 	// if current release resource is deprecated, delete it.
 	if err != nil {
-		log.Infof("upgrade %s RunWithContext failed,err:%s.", options.ReleaseName, err.Error())
+		log.Infof("upgrade %s for %s RunWithContext failed,err:%s.", options.ReleaseName, options.Namespace, err.Error())
 	}
 	if err != nil && strings.Contains(err.Error(), "unable to build kubernetes objects from current release manifest") {
 		histClient := action.NewHistory(actionConfig)
 		histClient.Max = 1
 		rels, err := histClient.Run(options.ReleaseName)
 		if err != nil {
-			log.Infof("upgrade get release %s history failed. err:%s.", options.ReleaseName, err.Error())
+			log.Infof("upgrade get release %s history for %s failed. err:%s.", options.ReleaseName, options.Namespace, err.Error())
 			return nil, err
 		}
 		if len(rels) == 0 {
 			return nil, errors.Errorf("no revision for release %q", options.ReleaseName)
 		}
 		for _, rel := range rels {
 			// if release is deprecated, delete it.
-			log.Infof("upgrade release %s resource is deprecated. delete it now. rel name:%s, rel version:%d.", options.ReleaseName, rel.Name, rel.Version)
+			log.Infof("upgrade release %s resource for %s is deprecated. delete it now. rel name:%s, rel version:%d.", options.ReleaseName, options.Namespace, rel.Name, rel.Version)
 			actionConfig.Releases.Delete(rel.Name, rel.Version)
 		}
 	}