From fcbdfea75010bbaba2e67668168656ebf86032cb Mon Sep 17 00:00:00 2001 From: Aditya Narayanaswamy Date: Mon, 9 Mar 2020 13:28:24 -0400 Subject: [PATCH] script: Printing time in console. Adds a new feature which prints a summary of the time it took in each stage of the installer after the stage has been completed. Summary is currently supported for the create, wait-for and the delete command. The summary is printed at the completion of the command and will show the time elapsed for each of the stages of the execution. Create command has the following stages:- . Infrastructure . API . Bootstrap Complete . Destroy bootstrap complete. . Cluster Operator Complete. Destroy command has the following stages:- . Cluster . Bootstrap The wait-for command has the following stages:- - Bootstrap-complete command . Bootstrap . API - Install-complete command . Cluster . Console --- cmd/openshift-install/create.go | 16 ++++ cmd/openshift-install/destroy.go | 7 ++ cmd/openshift-install/waitfor.go | 10 ++- go.sum | 2 + pkg/asset/cluster/cluster.go | 4 + pkg/metrics/timer/timer.go | 100 +++++++++++++++++++++++ pkg/metrics/timer/timer_test.go | 131 +++++++++++++++++++++++++++++++ 7 files changed, 269 insertions(+), 1 deletion(-) create mode 100644 pkg/metrics/timer/timer.go create mode 100644 pkg/metrics/timer/timer_test.go diff --git a/cmd/openshift-install/create.go b/cmd/openshift-install/create.go index 70a8201a8d..ebb1ed48fb 100644 --- a/cmd/openshift-install/create.go +++ b/cmd/openshift-install/create.go @@ -33,6 +33,7 @@ import ( assetstore "github.com/openshift/installer/pkg/asset/store" targetassets "github.com/openshift/installer/pkg/asset/targets" destroybootstrap "github.com/openshift/installer/pkg/destroy/bootstrap" + timer "github.com/openshift/installer/pkg/metrics/timer" "github.com/openshift/installer/pkg/types/baremetal" cov1helpers "github.com/openshift/library-go/pkg/config/clusteroperator/v1helpers" ) @@ -97,6 +98,7 @@ var ( logrus.Fatal(errors.Wrap(err, "loading kubeconfig")) } + timer.StartTimer("Bootstrap Complete") err = waitForBootstrapComplete(ctx, config, rootOpts.dir) if err != nil { if err2 := logClusterOperatorConditions(ctx, config); err2 != nil { @@ -107,6 +109,8 @@ var ( } logrus.Fatal("Bootstrap failed to complete: ", err) } + timer.StopTimer("Bootstrap Complete") + timer.StartTimer("Bootstrap Destroy") if oi, ok := os.LookupEnv("OPENSHIFT_INSTALL_PRESERVE_BOOTSTRAP"); ok && oi != "" { logrus.Warn("OPENSHIFT_INSTALL_PRESERVE_BOOTSTRAP is set, not destroying bootstrap resources. " + @@ -118,6 +122,7 @@ var ( logrus.Fatal(err) } } + timer.StopTimer("Bootstrap Destroy") err = waitForInstallComplete(ctx, config, rootOpts.dir) if err != nil { @@ -126,6 +131,8 @@ var ( } logrus.Fatal(err) } + timer.StopTimer(timer.TotalTimeElapsed) + timer.LogSummary() }, }, assets: targetassets.Cluster, @@ -182,6 +189,8 @@ func runTargetCmd(targets ...asset.WritableAsset) func(cmd *cobra.Command, args } return func(cmd *cobra.Command, args []string) { + timer.StartTimer(timer.TotalTimeElapsed) + cleanup := setupFileHook(rootOpts.dir) defer cleanup() @@ -254,6 +263,7 @@ func waitForBootstrapComplete(ctx context.Context, config *rest.Config, director apiTimeout := 20 * time.Minute logrus.Infof("Waiting up to %v for the Kubernetes API at %s...", apiTimeout, config.Host) + apiContext, cancel := context.WithTimeout(ctx, apiTimeout) defer cancel() // Poll quickly so we notice changes, but only log when the response @@ -262,10 +272,12 @@ func waitForBootstrapComplete(ctx context.Context, config *rest.Config, director logDownsample := 15 silenceRemaining := logDownsample previousErrorSuffix := "" + timer.StartTimer("API") wait.Until(func() { version, err := discovery.ServerVersion() if err == nil { logrus.Infof("API %s up", version) + timer.StopTimer("API") cancel() } else { silenceRemaining-- @@ -352,6 +364,7 @@ func waitForInitializedCluster(ctx context.Context, config *rest.Config) error { defer cancel() failing := configv1.ClusterStatusConditionType("Failing") + timer.StartTimer("Cluster Operators") var lastError string _, err = clientwatch.UntilWithSync( clusterVersionContext, @@ -367,6 +380,7 @@ func waitForInitializedCluster(ctx context.Context, config *rest.Config) error { return false, nil } if cov1helpers.IsStatusConditionTrue(cv.Status.Conditions, configv1.OperatorAvailable) { + timer.StopTimer("Cluster Operators") return true, nil } if cov1helpers.IsStatusConditionTrue(cv.Status.Conditions, failing) { @@ -418,6 +432,7 @@ func waitForConsole(ctx context.Context, config *rest.Config, directory string) // no route in a row (to show we're still alive). logDownsample := 15 silenceRemaining := logDownsample + timer.StartTimer("Console") wait.Until(func() { consoleRoutes, err := rc.RouteV1().Routes(consoleNamespace).List(metav1.ListOptions{}) if err == nil && len(consoleRoutes.Items) > 0 { @@ -450,6 +465,7 @@ func waitForConsole(ctx context.Context, config *rest.Config, directory string) if url == "" { return url, errors.New("could not get openshift-console URL") } + timer.StopTimer("Console") return url, nil } diff --git a/cmd/openshift-install/destroy.go b/cmd/openshift-install/destroy.go index 616d363140..e813e095a3 100644 --- a/cmd/openshift-install/destroy.go +++ b/cmd/openshift-install/destroy.go @@ -19,6 +19,7 @@ import ( _ "github.com/openshift/installer/pkg/destroy/openstack" _ "github.com/openshift/installer/pkg/destroy/ovirt" _ "github.com/openshift/installer/pkg/destroy/vsphere" + timer "github.com/openshift/installer/pkg/metrics/timer" "github.com/openshift/installer/pkg/terraform" ) @@ -54,6 +55,7 @@ func newDestroyClusterCmd() *cobra.Command { } func runDestroyCmd(directory string) error { + timer.StartTimer(timer.TotalTimeElapsed) destroyer, err := destroy.New(logrus.StandardLogger(), directory) if err != nil { return errors.Wrap(err, "Failed while preparing to destroy cluster") @@ -82,6 +84,8 @@ func runDestroyCmd(directory string) error { if err != nil && !os.IsNotExist(err) { return errors.Wrap(err, "failed to remove Terraform state") } + timer.StopTimer(timer.TotalTimeElapsed) + timer.LogSummary() return nil } @@ -95,10 +99,13 @@ func newDestroyBootstrapCmd() *cobra.Command { cleanup := setupFileHook(rootOpts.dir) defer cleanup() + timer.StartTimer(timer.TotalTimeElapsed) err := bootstrap.Destroy(rootOpts.dir) if err != nil { logrus.Fatal(err) } + timer.StopTimer(timer.TotalTimeElapsed) + timer.LogSummary() }, } } diff --git a/cmd/openshift-install/waitfor.go b/cmd/openshift-install/waitfor.go index a33a6b1d10..9a7628570a 100644 --- a/cmd/openshift-install/waitfor.go +++ b/cmd/openshift-install/waitfor.go @@ -4,6 +4,7 @@ import ( "context" "path/filepath" + timer "github.com/openshift/installer/pkg/metrics/timer" "github.com/pkg/errors" "github.com/sirupsen/logrus" "github.com/spf13/cobra" @@ -34,6 +35,7 @@ func newWaitForBootstrapCompleteCmd() *cobra.Command { Short: "Wait until cluster bootstrapping has completed", Args: cobra.ExactArgs(0), Run: func(_ *cobra.Command, _ []string) { + timer.StartTimer(timer.TotalTimeElapsed) ctx := context.Background() cleanup := setupFileHook(rootOpts.dir) @@ -43,7 +45,7 @@ func newWaitForBootstrapCompleteCmd() *cobra.Command { if err != nil { logrus.Fatal(errors.Wrap(err, "loading kubeconfig")) } - + timer.StartTimer("Bootstrap Complete") err = waitForBootstrapComplete(ctx, config, rootOpts.dir) if err != nil { if err2 := logClusterOperatorConditions(ctx, config); err2 != nil { @@ -56,6 +58,9 @@ func newWaitForBootstrapCompleteCmd() *cobra.Command { } logrus.Info("It is now safe to remove the bootstrap resources") + timer.StopTimer("Bootstrap Complete") + timer.StopTimer(timer.TotalTimeElapsed) + timer.LogSummary() }, } } @@ -66,6 +71,7 @@ func newWaitForInstallCompleteCmd() *cobra.Command { Short: "Wait until the cluster is ready", Args: cobra.ExactArgs(0), Run: func(cmd *cobra.Command, args []string) { + timer.StartTimer(timer.TotalTimeElapsed) ctx := context.Background() cleanup := setupFileHook(rootOpts.dir) @@ -84,6 +90,8 @@ func newWaitForInstallCompleteCmd() *cobra.Command { logrus.Fatal(err) } + timer.StopTimer(timer.TotalTimeElapsed) + timer.LogSummary() }, } } diff --git a/go.sum b/go.sum index 651e3d5e0f..5825a40711 100644 --- a/go.sum +++ b/go.sum @@ -553,6 +553,7 @@ github.com/go-errors/errors v1.0.1/go.mod h1:f4zRHt4oKfwPJE5k8C9vpYG+aDHdBFUsgrm github.com/go-gl/glfw v0.0.0-20190409004039-e6da0acd62b1/go.mod h1:vR7hzQXu2zJy9AVAgeJqvqgH9Q5CA+iKCZ2gyEVpxRU= github.com/go-gl/glfw/v3.3/glfw v0.0.0-20191125211704-12ad95a8df72/go.mod h1:tQ2UAYgL5IevRw8kRxooKSPJfGvJ9fJQFa0TUsXzTg8= github.com/go-kit/kit v0.8.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as= +github.com/go-kit/kit v0.9.0 h1:wDJmvq38kDhkVxi50ni9ykkdUr1PKgqKOoi01fa0Mdk= github.com/go-kit/kit v0.9.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as= github.com/go-ldap/ldap v3.0.2+incompatible/go.mod h1:qfd9rJvER9Q0/D/Sqn1DfHRoBp40uXYvFoEVrNEPqRc= github.com/go-ldap/ldap/v3 v3.1.3/go.mod h1:3rbOH3jRS2u6jg2rJnKAMLE/xQyCKIveG2Sa/Cohzb8= @@ -560,6 +561,7 @@ github.com/go-lintpack/lintpack v0.5.2 h1:DI5mA3+eKdWeJ40nU4d6Wc26qmdG8RCi/btYq0 github.com/go-lintpack/lintpack v0.5.2/go.mod h1:NwZuYi2nUHho8XEIZ6SIxihrnPoqBTDqfpXvXAN0sXM= github.com/go-log/log v0.1.1-0.20181211034820-a514cf01a3eb/go.mod h1:4mBwpdRMFLiuXZDCwU2lKQFsoSCo72j3HqBK9d81N2M= github.com/go-logfmt/logfmt v0.3.0/go.mod h1:Qt1PoO58o5twSAckw1HlFXLmHsOX5/0LbT9GBnD5lWE= +github.com/go-logfmt/logfmt v0.4.0 h1:MP4Eh7ZCb31lleYCFuwm0oe4/YGak+5l1vA2NOE80nA= github.com/go-logfmt/logfmt v0.4.0/go.mod h1:3RMwSq7FuexP4Kalkev3ejPJsZTpXXBr9+V4qmtdjCk= github.com/go-logr/logr v0.1.0 h1:M1Tv3VzNlEHg6uyACnRdtrploV2P7wZqH8BoQMtz0cg= github.com/go-logr/logr v0.1.0/go.mod h1:ixOQHD9gLJUVQQ2ZOR7zLEifBX6tGkNJF4QyIY7sIas= diff --git a/pkg/asset/cluster/cluster.go b/pkg/asset/cluster/cluster.go index d3e04580f0..0cbe5545f4 100644 --- a/pkg/asset/cluster/cluster.go +++ b/pkg/asset/cluster/cluster.go @@ -14,6 +14,7 @@ import ( "github.com/openshift/installer/pkg/asset/cluster/aws" "github.com/openshift/installer/pkg/asset/installconfig" "github.com/openshift/installer/pkg/asset/password" + "github.com/openshift/installer/pkg/metrics/timer" "github.com/openshift/installer/pkg/terraform" ) @@ -80,6 +81,8 @@ func (c *Cluster) Generate(parents asset.Parents) (err error) { } } + timer.StartTimer("Infrastructure") + stateFile, err := terraform.Apply(tmpDir, installConfig.Config.Platform.Name(), extraArgs...) if err != nil { err = errors.Wrap(err, "failed to create cluster") @@ -103,6 +106,7 @@ func (c *Cluster) Generate(parents asset.Parents) (err error) { logrus.Errorf("Failed to read tfstate: %v", err2) } + timer.StopTimer("Infrastructure") return err } diff --git a/pkg/metrics/timer/timer.go b/pkg/metrics/timer/timer.go new file mode 100644 index 0000000000..54f4bb8bd4 --- /dev/null +++ b/pkg/metrics/timer/timer.go @@ -0,0 +1,100 @@ +package timer + +import ( + "fmt" + "time" + + "github.com/sirupsen/logrus" +) + +// Timer is the struct that keeps track of each of the sections. +type Timer struct { + listOfStages []string + stageTimes map[string]time.Duration + startTimes map[string]time.Time +} + +const ( + + // TotalTimeElapsed is a constant string value to denote total time elapsed. + TotalTimeElapsed = "Total" +) + +var timer = NewTimer() + +// StartTimer initiailzes the timer object with the current timestamp information. +func StartTimer(key string) { + timer.StartTimer(key) +} + +// StopTimer records the duration for the current stage sent as the key parameter and stores the information. +func StopTimer(key string) { + timer.StopTimer(key) +} + +// LogSummary prints the summary of all the times collected so far into the INFO section. +func LogSummary() { + timer.LogSummary(logrus.StandardLogger()) +} + +// NewTimer returns a new timer that can be used to track sections and +func NewTimer() Timer { + return Timer{ + listOfStages: []string{}, + stageTimes: make(map[string]time.Duration), + startTimes: make(map[string]time.Time), + } +} + +// StartTimer initializes the timer object with the current timestamp information. +func (t *Timer) StartTimer(key string) { + t.listOfStages = append(t.listOfStages, key) + t.startTimes[key] = time.Now().Round(time.Second) +} + +// StopTimer records the duration for the current stage sent as the key parameter and stores the information. +func (t *Timer) StopTimer(key string) time.Duration { + if item, found := t.startTimes[key]; found { + duration := time.Since(item).Round(time.Second) + t.stageTimes[key] = duration + } + return time.Since(time.Now()) +} + +// LogSummary prints the summary of all the times collected so far into the INFO section. +// The format of printing will be the following: +// If there are no stages except the total time stage, then it only prints the following +// Time elapsed: ms +// If there are multiple stages, it prints the following: +// Time elapsed for each section +// Stage1: ms +// Stage2: ms +// . +// . +// . +// StageN: ms +// Time elapsed: ms +// All durations printed are rounded up to the next second value and printed in the format mentioned above. +func (t *Timer) LogSummary(logger *logrus.Logger) { + maxLen := 0 + count := 0 + for _, item := range t.listOfStages { + if len(item) > maxLen && item != TotalTimeElapsed { + maxLen = len(item) + } + if t.stageTimes[item] > 0 { + count++ + } + } + + if maxLen != 0 && count > 0 { + logger.Debugf("Time elapsed per stage:") + } + + for _, item := range t.listOfStages { + if item != TotalTimeElapsed && t.stageTimes[item] > 0 { + logger.Debugf(fmt.Sprintf("%*s: %s", maxLen, item, t.stageTimes[item])) + } + } + logger.Infof("Time elapsed: %s", t.stageTimes[TotalTimeElapsed]) +} diff --git a/pkg/metrics/timer/timer_test.go b/pkg/metrics/timer/timer_test.go new file mode 100644 index 0000000000..34c561a478 --- /dev/null +++ b/pkg/metrics/timer/timer_test.go @@ -0,0 +1,131 @@ +package timer + +import ( + "bytes" + "encoding/json" + "fmt" + "strings" + "testing" + "time" + + "github.com/sirupsen/logrus" +) + +func convertToFormat(buf bytes.Buffer) string { + output := buf.String() + + outputText := "" + + for _, item := range strings.Split(output, "\n") { + var dat map[string]interface{} + + if err := json.Unmarshal([]byte(item), &dat); err != nil { + continue + } + outputText += dat["msg"].(string) + "\n" + } + + return outputText +} + +func TestBasicLogSummaryMultipleStages(t *testing.T) { + timer := NewTimer() + + timer.StartTimer(TotalTimeElapsed) + timer.StartTimer("testStage1") + timer.StartTimer("testStage2") + timer.StartTimer("testStage3") + timer.StartTimer("testStage4") + + time.Sleep(5 * time.Second) + + timer.StopTimer("testStage1") + timer.StopTimer("testStage2") + timer.StopTimer("testStage3") + timer.StopTimer("testStage4") + timer.StopTimer(TotalTimeElapsed) + + timeElapsed := fmt.Sprintf("Time elapsed per stage:\n") + time1 := fmt.Sprintf("testStage1: %s\n", timer.stageTimes["testStage1"]) + time2 := fmt.Sprintf("testStage2: %s\n", timer.stageTimes["testStage2"]) + time3 := fmt.Sprintf("testStage3: %s\n", timer.stageTimes["testStage3"]) + time4 := fmt.Sprintf("testStage4: %s\n", timer.stageTimes["testStage4"]) + timeStageElapsed := fmt.Sprintf("Time elapsed: %s\n", timer.stageTimes[TotalTimeElapsed]) + + text := timeElapsed + time1 + time2 + time3 + time4 + timeStageElapsed + + textOutput := bytes.Buffer{} + + logger := logrus.New() + logger.Out = &textOutput + logger.Level = logrus.DebugLevel + logger.Formatter = &logrus.JSONFormatter{} + + timer.LogSummary(logger) + + outputText := convertToFormat(textOutput) + + if text != outputText { + t.Fatalf("expected message summary printed to be %s, but got %s", text, outputText) + } +} + +func TestTotalOnlyLogSummary(t *testing.T) { + timer := NewTimer() + + timer.StartTimer(TotalTimeElapsed) + time.Sleep(5 * time.Second) + timer.StopTimer(TotalTimeElapsed) + + timeStageElapsed := fmt.Sprintf("Time elapsed: %s\n", timer.stageTimes[TotalTimeElapsed]) + + textOutput := bytes.Buffer{} + + logger := logrus.New() + logger.Out = &textOutput + logger.Level = logrus.DebugLevel + logger.Formatter = &logrus.JSONFormatter{} + + timer.LogSummary(logger) + + outputText := convertToFormat(textOutput) + + if timeStageElapsed != outputText { + t.Fatalf("expected message summary printed to be %s, but got %s", timeStageElapsed, outputText) + } +} + +func TestStartAndStopTimer(t *testing.T) { + timerTotal := NewTimer() + + timerTotal.StartTimer(TotalTimeElapsed) + time.Sleep(5 * time.Second) + + duration := time.Since(timerTotal.startTimes[TotalTimeElapsed]).Round(time.Second) + t.Logf("%s", duration) + if duration < 5*time.Second { + t.Fatalf("Slept for 5 seconds, expected start time to be 5 seconds old, got %s", duration) + } else if duration > 10*time.Second { + t.Fatalf("Slept for 5 seconds, expected start time to be close to 5 seconds old, got %s", duration) + } + timerTotal.StopTimer(TotalTimeElapsed) + + if timerTotal.stageTimes[TotalTimeElapsed] < 5*time.Second || timerTotal.stageTimes[TotalTimeElapsed] > 10*time.Second { + t.Fatalf("Slept for 5 seconds, expected duration to be close to 5 seconds old, got %s", timerTotal.stageTimes[TotalTimeElapsed]) + } +} + +func TestNewTimer(t *testing.T) { + timer := NewTimer() + if len(timer.listOfStages) != 0 { + t.Fatalf("Expected empty list of stages property in the new timer created, got %d", len(timer.listOfStages)) + } + + if len(timer.startTimes) != 0 { + t.Fatalf("Expected empty list of startTimes property in the new timer created, got %d", len(timer.startTimes)) + } + + if len(timer.stageTimes) != 0 { + t.Fatalf("Expected empty list of startTimes property in the new timer created, got %d", len(timer.stageTimes)) + } +}