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

@@ -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
 }
 

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()
 		},
 	}
 }

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()
 		},
 	}
 }

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=

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
 }
 

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: <x>m<yy>s
+// If there are multiple stages, it prints the following:
+// Time elapsed for each section
+// Stage1: <x>m<yy>s
+// Stage2: <x>m<yy>s
+// .
+// .
+// .
+// StageN: <x>m<yy>s
+// Time elapsed: <x>m<yy>s
+// 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])
+}

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