Add a lot more timing data. (#518)

cmd/executor/cmd/root.go

@@ -24,6 +24,8 @@ import (
 	"strings"
 	"time"
 
+	"github.com/GoogleContainerTools/kaniko/pkg/timing"
+
 	"github.com/GoogleContainerTools/kaniko/pkg/buildcontext"
 	"github.com/GoogleContainerTools/kaniko/pkg/config"
 	"github.com/GoogleContainerTools/kaniko/pkg/constants"
@@ -87,6 +89,21 @@ var RootCmd = &cobra.Command{
 		if err := executor.DoPush(image, opts); err != nil {
 			exit(errors.Wrap(err, "error pushing image"))
 		}
+
+		benchmarkFile := os.Getenv("BENCHMARK_FILE")
+		// false is a keyword for integration tests to turn off benchmarking
+		if benchmarkFile != "" && benchmarkFile != "false" {
+			f, err := os.Create(benchmarkFile)
+			if err != nil {
+				logrus.Warnf("Unable to create benchmarking file %s: %s", benchmarkFile, err)
+			}
+			defer f.Close()
+			s, err := timing.JSON()
+			if err != nil {
+				logrus.Warnf("Unable to write benchmark file: %s", err)
+			}
+			f.WriteString(s)
+		}
 	},
 }
 

pkg/executor/build.go

@@ -382,20 +382,6 @@ func DoBuild(opts *config.KanikoOptions) (v1.Image, error) {
 				}
 			}
 			timing.DefaultRun.Stop(t)
-			benchmarkFile := os.Getenv("BENCHMARK_FILE")
-			// false is a keyword for integration tests to turn off benchmarking
-			if benchmarkFile != "" && benchmarkFile != "false" {
-				f, err := os.Create(benchmarkFile)
-				if err != nil {
-					logrus.Warnf("Unable to create benchmarking file %s: %s", benchmarkFile, err)
-				}
-				defer f.Close()
-				s, err := timing.JSON()
-				if err != nil {
-					logrus.Warnf("Unable to write benchmark file: %s", err)
-				}
-				f.WriteString(s)
-			}
 			return sourceImage, nil
 		}
 		if stage.SaveStage {

pkg/executor/push.go

@@ -25,6 +25,7 @@ import (
 	"github.com/GoogleContainerTools/kaniko/pkg/cache"
 	"github.com/GoogleContainerTools/kaniko/pkg/config"
 	"github.com/GoogleContainerTools/kaniko/pkg/constants"
+	"github.com/GoogleContainerTools/kaniko/pkg/timing"
 	"github.com/GoogleContainerTools/kaniko/pkg/version"
 	"github.com/google/go-containerregistry/pkg/authn"
 	"github.com/google/go-containerregistry/pkg/authn/k8schain"
@@ -53,6 +54,7 @@ func DoPush(image v1.Image, opts *config.KanikoOptions) error {
 		logrus.Info("Skipping push to container registry due to --no-push flag")
 		return nil
 	}
+	t := timing.Start("Total Push Time")
 	destRefs := []name.Tag{}
 	for _, destination := range opts.Destinations {
 		destRef, err := name.NewTag(destination, name.WeakValidation)
@@ -103,6 +105,7 @@ func DoPush(image v1.Image, opts *config.KanikoOptions) error {
 			return errors.Wrap(err, fmt.Sprintf("failed to push to destination %s", destRef))
 		}
 	}
+	timing.DefaultRun.Stop(t)
 	return nil
 }
 

pkg/snapshot/layered_map.go

@@ -23,6 +23,7 @@ import (
 	"path/filepath"
 	"strings"
 
+	"github.com/GoogleContainerTools/kaniko/pkg/timing"
 	"github.com/GoogleContainerTools/kaniko/pkg/util"
 )
 
@@ -124,6 +125,8 @@ func (l *LayeredMap) Add(s string) error {
 // was added.
 func (l *LayeredMap) MaybeAdd(s string) (bool, error) {
 	oldV, ok := l.Get(s)
+	t := timing.Start("Hashing files")
+	defer timing.DefaultRun.Stop(t)
 	newV, err := l.hasher(s)
 	if err != nil {
 		return false, err

pkg/snapshot/snapshot.go

@@ -22,6 +22,8 @@ import (
 	"path/filepath"
 	"syscall"
 
+	"github.com/GoogleContainerTools/kaniko/pkg/timing"
+
 	"github.com/karrick/godirwalk"
 
 	"github.com/GoogleContainerTools/kaniko/pkg/constants"
@@ -141,6 +143,7 @@ func (s *Snapshotter) TakeSnapshotFS() (string, error) {
 	t := util.NewTar(f)
 	defer t.Close()
 
+	timer := timing.Start("Walking filesystem")
 	// Save the fs state in a map to iterate over later.
 	memFs := map[string]*godirwalk.Dirent{}
 	godirwalk.Walk(s.directory, &godirwalk.Options{
@@ -158,6 +161,7 @@ func (s *Snapshotter) TakeSnapshotFS() (string, error) {
 		Unsorted: true,
 	},
 	)
+	timing.DefaultRun.Stop(timer)
 
 	// First handle whiteouts
 	for p := range memFs {
@@ -176,6 +180,7 @@ func (s *Snapshotter) TakeSnapshotFS() (string, error) {
 		}
 	}
 
+	timer = timing.Start("Writing tar file")
 	// Now create the tar.
 	for path := range memFs {
 		whitelisted, err := util.CheckWhitelist(path)
@@ -198,6 +203,7 @@ func (s *Snapshotter) TakeSnapshotFS() (string, error) {
 			}
 		}
 	}
+	timing.DefaultRun.Stop(timer)
 
 	return f.Name(), nil
 }

pkg/timing/timing.go

@@ -39,11 +39,11 @@ type TimedRun struct {
 // Stop stops the specified timer and increments the time spent in that category.
 func (tr *TimedRun) Stop(t *Timer) {
 	stop := currentTimeFunc()
+	tr.cl.Lock()
+	defer tr.cl.Unlock()
 	if _, ok := tr.categories[t.category]; !ok {
 		tr.categories[t.category] = 0
 	}
-	tr.cl.Lock()
-	defer tr.cl.Unlock()
 	tr.categories[t.category] += stop.Sub(t.startTime)
 }