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)) + } +}