From 7cde036f445eef4dc4569bea212e2b9e617c6013 Mon Sep 17 00:00:00 2001 From: Sharif Elgamal Date: Wed, 28 Nov 2018 11:54:12 -0800 Subject: [PATCH] Add benchmarking code (#448) * adding benchmarking code * enable writing to file * fix build * time more stuff * adding benchmarking to integration tests * compare docker and kaniko times in integration tests * Switch to setting benchmark file with an env var * close file at the right time * fix integration test with environment variables * fix integration tests * Adding benchmarking documentation to DEVELOPEMENT.md * human readable benchmarking steps --- DEVELOPMENT.md | 21 +++++++++++++++ cmd/executor/cmd/root.go | 1 + integration/images.go | 16 +++++++++++- integration/integration_test.go | 11 ++++++++ pkg/executor/build.go | 45 +++++++++++++++++++++++++++------ pkg/timing/timing.go | 2 -- 6 files changed, 85 insertions(+), 11 deletions(-) diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index eb3594940..b9c81f2ea 100644 --- a/DEVELOPMENT.md +++ b/DEVELOPMENT.md @@ -97,6 +97,27 @@ Requirements: These tests will be kicked off by [reviewers](#reviews) for submitted PRs. +### Benchmarking + +The goal is for Kaniko to be at least as fast at building Dockerfiles as Docker is, and to that end, we've built +in benchmarking to check the speed of not only each full run, but also how long each step of each run takes. To turn +on benchmarking, just set the `BENCHMARK_FILE` environment variable, and kaniko will output all the benchmark info +of each run to that file location. + +```shell +docker run -v $(pwd):/workspace -v ~/.config:/root/.config \ +-e BENCHMARK_FILE=/workspace/benchmark_file \ +gcr.io/kaniko-project/executor:latest \ +--dockerfile= --context=/workspace \ +--destination=gcr.io/my-repo/my-image +``` +Additionally, the integration tests can output benchmarking information to a `benchmarks` directory under the +`integration` directory if the `BENCHMARK` environment variable is set to `true.` + +```shell +BENCHMARK=true go test -v --bucket $GCS_BUCKET --repo $IMAGE_REPO +``` + ## Creating a PR When you have changes you would like to propose to kaniko, you will need to: diff --git a/cmd/executor/cmd/root.go b/cmd/executor/cmd/root.go index 0f01d8238..8e22850c6 100644 --- a/cmd/executor/cmd/root.go +++ b/cmd/executor/cmd/root.go @@ -47,6 +47,7 @@ func init() { addHiddenFlags(RootCmd) } +// RootCmd is the kaniko command that is run var RootCmd = &cobra.Command{ Use: "executor", PersistentPreRunE: func(cmd *cobra.Command, args []string) error { diff --git a/integration/images.go b/integration/images.go index f84705ca7..860f5b551 100644 --- a/integration/images.go +++ b/integration/images.go @@ -25,12 +25,15 @@ import ( "runtime" "strconv" "strings" + + "github.com/GoogleContainerTools/kaniko/pkg/timing" ) const ( // ExecutorImage is the name of the kaniko executor image ExecutorImage = "executor-image" - WarmerImage = "warmer-image" + //WarmerImage is the name of the kaniko cache warmer image + WarmerImage = "warmer-image" dockerPrefix = "docker-" kanikoPrefix = "kaniko-" @@ -159,7 +162,9 @@ func (d *DockerFileBuilder) BuildImage(imageRepo, gcsBucket, dockerfilesPath, do additionalFlags...)..., ) + timer := timing.Start(dockerfile + "_docker") _, err := RunCommandWithoutTest(dockerCmd) + timing.DefaultRun.Stop(timer) if err != nil { return fmt.Errorf("Failed to build image %s with docker command \"%s\": %s", dockerImage, dockerCmd.Args, err) } @@ -182,6 +187,12 @@ func (d *DockerFileBuilder) BuildImage(imageRepo, gcsBucket, dockerfilesPath, do } } + benchmarkEnv := "BENCHMARK_FILE=false" + if os.Getenv("BENCHMARK") == "true" { + os.Mkdir("benchmarks", 0755) + benchmarkEnv = "BENCHMARK_FILE=/workspace/benchmarks/" + dockerfile + } + // build kaniko image additionalFlags = append(buildArgs, additionalKanikoFlagsMap[dockerfile]...) kanikoImage := GetKanikoImage(imageRepo, dockerfile) @@ -189,6 +200,7 @@ func (d *DockerFileBuilder) BuildImage(imageRepo, gcsBucket, dockerfilesPath, do append([]string{"run", "-v", os.Getenv("HOME") + "/.config/gcloud:/root/.config/gcloud", "-v", cwd + ":/workspace", + "-e", benchmarkEnv, ExecutorImage, "-f", path.Join(buildContextPath, dockerfilesPath, dockerfile), "-d", kanikoImage, reproducibleFlag, @@ -196,7 +208,9 @@ func (d *DockerFileBuilder) BuildImage(imageRepo, gcsBucket, dockerfilesPath, do additionalFlags...)..., ) + timer = timing.Start(dockerfile + "_kaniko") _, err = RunCommandWithoutTest(kanikoCmd) + timing.DefaultRun.Stop(timer) if err != nil { return fmt.Errorf("Failed to build image %s with kaniko command \"%s\": %s", dockerImage, kanikoCmd.Args, err) } diff --git a/integration/integration_test.go b/integration/integration_test.go index f7867c14b..c1d4dd6b0 100644 --- a/integration/integration_test.go +++ b/integration/integration_test.go @@ -32,6 +32,7 @@ import ( "github.com/google/go-containerregistry/pkg/name" "github.com/google/go-containerregistry/pkg/v1/daemon" + "github.com/GoogleContainerTools/kaniko/pkg/timing" "github.com/GoogleContainerTools/kaniko/pkg/util" "github.com/GoogleContainerTools/kaniko/testutil" ) @@ -215,6 +216,16 @@ func TestRun(t *testing.T) { }) } + + if os.Getenv("BENCHMARK") == "true" { + f, err := os.Create("benchmark") + if err != nil { + t.Logf("Failed to create benchmark file") + } else { + f.WriteString(timing.Summary()) + } + defer f.Close() + } } func TestLayers(t *testing.T) { diff --git a/pkg/executor/build.go b/pkg/executor/build.go index e11c0fd53..88ebafe14 100644 --- a/pkg/executor/build.go +++ b/pkg/executor/build.go @@ -38,6 +38,7 @@ import ( "github.com/GoogleContainerTools/kaniko/pkg/constants" "github.com/GoogleContainerTools/kaniko/pkg/dockerfile" "github.com/GoogleContainerTools/kaniko/pkg/snapshot" + "github.com/GoogleContainerTools/kaniko/pkg/timing" "github.com/GoogleContainerTools/kaniko/pkg/util" ) @@ -56,14 +57,18 @@ type stageBuilder struct { // newStageBuilder returns a new type stageBuilder which contains all the information required to build the stage func newStageBuilder(opts *config.KanikoOptions, stage config.KanikoStage) (*stageBuilder, error) { + t := timing.Start("Retrieving Source Image") sourceImage, err := util.RetrieveSourceImage(stage, opts) if err != nil { return nil, err } + timing.DefaultRun.Stop(t) + t = timing.Start("Retrieving Config File") imageConfig, err := util.RetrieveConfigFile(sourceImage) if err != nil { return nil, err } + timing.DefaultRun.Stop(t) if err := resolveOnBuild(&stage, &imageConfig.Config); err != nil { return nil, err } @@ -179,17 +184,21 @@ func (s *stageBuilder) build() error { } } if shouldUnpack { + t := timing.Start("FS Unpacking") if _, err := util.GetFSFromImage(constants.RootDir, s.image); err != nil { return err } + timing.DefaultRun.Stop(t) } if err := util.DetectFilesystemWhitelist(constants.WhitelistPath); err != nil { return err } // Take initial snapshot + t := timing.Start("Initial FS snapshot") if err := s.snapshotter.Init(); err != nil { return err } + timing.DefaultRun.Stop(t) cacheGroup := errgroup.Group{} for index, command := range cmds { @@ -199,7 +208,7 @@ func (s *stageBuilder) build() error { // Add the next command to the cache key. compositeKey.AddKey(command.String()) - + t := timing.Start("Command: " + command.String()) // If the command uses files from the context, add them. files, err := command.FilesUsedFromContext(&s.cf.Config, args) if err != nil { @@ -239,6 +248,7 @@ func (s *stageBuilder) build() error { if err := s.saveSnapshotToImage(command.String(), tarPath); err != nil { return err } + timing.DefaultRun.Stop(t) } if err := cacheGroup.Wait(); err != nil { logrus.Warnf("error uploading layer to cache: %s", err) @@ -247,15 +257,21 @@ func (s *stageBuilder) build() error { } func (s *stageBuilder) takeSnapshot(files []string) (string, error) { + var snapshot string + var err error + t := timing.Start("Snapshotting FS") if files == nil || s.opts.SingleSnapshot { - return s.snapshotter.TakeSnapshotFS() + snapshot, err = s.snapshotter.TakeSnapshotFS() + } else { + // Volumes are very weird. They get created in their command, but snapshotted in the next one. + // Add them to the list of files to snapshot. + for v := range s.cf.Config.Volumes { + files = append(files, v) + } + snapshot, err = s.snapshotter.TakeSnapshot(files) } - // Volumes are very weird. They get created in their command, but snapshotted in the next one. - // Add them to the list of files to snapshot. - for v := range s.cf.Config.Volumes { - files = append(files, v) - } - return s.snapshotter.TakeSnapshot(files) + timing.DefaultRun.Stop(t) + return snapshot, err } func (s *stageBuilder) shouldTakeSnapshot(index int, files []string) bool { @@ -315,6 +331,7 @@ func (s *stageBuilder) saveSnapshotToImage(createdBy string, tarPath string) err // DoBuild executes building the Dockerfile func DoBuild(opts *config.KanikoOptions) (v1.Image, error) { + t := timing.Start("Total Build Time") // Parse dockerfile and unpack base image to root stages, err := dockerfile.Stages(opts) if err != nil { @@ -349,6 +366,17 @@ func DoBuild(opts *config.KanikoOptions) (v1.Image, error) { return nil, err } } + 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() + f.WriteString(timing.Summary()) + } return sourceImage, nil } if stage.SaveStage { @@ -364,6 +392,7 @@ func DoBuild(opts *config.KanikoOptions) (v1.Image, error) { return nil, err } } + return nil, err } diff --git a/pkg/timing/timing.go b/pkg/timing/timing.go index fcd212768..cb340a9b9 100644 --- a/pkg/timing/timing.go +++ b/pkg/timing/timing.go @@ -18,7 +18,6 @@ package timing import ( "bytes" - "fmt" "sync" "text/template" "time" @@ -42,7 +41,6 @@ func (tr *TimedRun) Stop(t *Timer) { if _, ok := tr.categories[t.category]; !ok { tr.categories[t.category] = 0 } - fmt.Println(stop) tr.cl.Lock() defer tr.cl.Unlock() tr.categories[t.category] += stop.Sub(t.startTime)