Merge pull request #1757 from kunalkushwaha/contrib-perftest

perf test a stress test to profile CPU load of podman

Makefile

@@ -190,6 +190,12 @@ clientintegration:
 	$(MAKE) -C contrib/python/podman integration
 	$(MAKE) -C contrib/python/pypodman integration
 
+perftest:
+	$ cd contrib/perftest;go build
+
+run-perftest: perftest
+	$ contrib/perftest/perftest
+
 vagrant-check:
 	BOX=$(BOX) sh ./vagrant.sh
 

contrib/perftest/README.md

@@ -0,0 +1,51 @@
+## perftest : tool for benchmarking and profiling libpod library
+perftest uses libpod as golang library and perform stress test and profile for CPU usage.
+
+Build:
+
+```
+# cd $GOPATH/src/github.com/containers/libpod/contrib/perftest
+# go build
+# go install
+```
+
+Usage:
+
+```
+# perftest -h
+Usage of perftest:
+
+-count int
+        count of loop counter for test (default 50)
+-image string
+        image-name to be used for test (default "docker.io/library/alpine:latest")
+
+```
+
+e.g.
+
+```
+# perftest
+runc version spec: 1.0.1-dev
+conmon version 1.12.0-dev, commit: b6c5cafeffa9b3cde89812207b29ccedd3102712
+
+preparing test environment...
+2018/11/05 16:52:14 profile: cpu profiling enabled, /tmp/profile626959338/cpu.pprof
+Test Round: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49
+Profile data
+
+        Create  Start   Stop    Delete
+Min     0.23s   0.34s   2.12s   0.51s
+Avg     0.25s   0.38s   2.13s   0.54s
+Max     0.27s   0.48s   2.13s   0.70s
+Total   12.33s  18.82s  106.47s 26.91s
+2018/11/05 16:54:59 profile: cpu profiling disabled, /tmp/profile626959338/cpu.pprof
+
+```
+
+Analyse CPU profile.
+
+```
+# go tool pprof -http=":8081" $GOPATH/src/github.com/containers/libpod/contrib/perftest/perftest /tmp/profile626959338/cpu.pprof
+```
+- Open http://localhost:8081 in webbrowser

contrib/perftest/main.go

@@ -0,0 +1,283 @@
+package main
+
+import (
+	"context"
+	"flag"
+	"fmt"
+	"os"
+	"strings"
+	"text/tabwriter"
+	"time"
+
+	"github.com/containers/image/types"
+	"github.com/containers/libpod/libpod"
+	image2 "github.com/containers/libpod/libpod/image"
+	cc "github.com/containers/libpod/pkg/spec"
+	"github.com/containers/libpod/pkg/util"
+	"github.com/containers/storage/pkg/reexec"
+	"github.com/cri-o/ocicni/pkg/ocicni"
+	"github.com/pkg/profile"
+	"github.com/sirupsen/logrus"
+)
+
+const (
+	defaultTestImage = "docker.io/library/alpine:latest"
+	defaultRunCount  = 50
+)
+
+var helpMessage = `
+-count int
+	count of loop counter for test (default 50)
+-image string
+	image-name to be used for test (default "docker.io/library/alpine:latest")
+-log string
+	log level (info|debug|warn|error) (default "error")
+
+`
+
+func main() {
+
+	ctx := context.Background()
+	imageName := ""
+
+	testImageName := flag.String("image", defaultTestImage, "image-name to be used for test")
+	testRunCount := flag.Int("count", defaultRunCount, "count of loop counter for test")
+	logLevel := flag.String("log", "error", "log level (info|debug|warn|error)")
+
+	flag.Usage = func() {
+		fmt.Fprintf(os.Stderr, "Usage of %s:\n", os.Args[0])
+		fmt.Fprintf(os.Stderr, "%s \n", helpMessage)
+	}
+
+	flag.Parse()
+
+	if reexec.Init() {
+		return
+	}
+
+	switch strings.ToLower(*logLevel) {
+	case "error":
+		logrus.SetLevel(logrus.ErrorLevel)
+	case "warn":
+		logrus.SetLevel(logrus.WarnLevel)
+	case "info":
+		logrus.SetLevel(logrus.InfoLevel)
+	case "debug":
+		logrus.SetLevel(logrus.DebugLevel)
+	default:
+		logrus.Fatalf("invalid option : %s ", *logLevel)
+	}
+
+	opts := defaultRuntimeOptions()
+	client, err := libpod.NewRuntime(opts...)
+	if err != nil {
+		logrus.Fatal(err)
+	}
+	defer client.Shutdown(false)
+
+	// Print Runtime & System Information.
+	err = printSystemInfo(client)
+	if err != nil {
+		logrus.Fatal(err)
+	}
+
+	imageRuntime := client.ImageRuntime()
+	if imageRuntime == nil {
+		logrus.Fatal("ImageRuntime is null")
+	}
+
+	fmt.Printf("preparing test environment...\n")
+	//Prepare for test.
+	testImage, err := imageRuntime.NewFromLocal(*testImageName)
+	if err != nil {
+		// Download the image from remote registry.
+		writer := os.Stderr
+		registryCreds := &types.DockerAuthConfig{
+			Username: "",
+			Password: "",
+		}
+		dockerRegistryOptions := image2.DockerRegistryOptions{
+			DockerRegistryCreds:         registryCreds,
+			DockerCertPath:              "",
+			DockerInsecureSkipTLSVerify: types.OptionalBoolFalse,
+		}
+		fmt.Printf("image %s not found locally, fetching from remote registry..\n", *testImageName)
+
+		testImage, err = client.ImageRuntime().New(ctx, *testImageName, "", "", writer, &dockerRegistryOptions, image2.SigningOptions{}, false)
+		if err != nil {
+			logrus.Fatal(err)
+		}
+		fmt.Printf("image downloaded successfully\n\n")
+	}
+
+	names := testImage.Names()
+	if len(names) > 0 {
+		imageName = names[0]
+	} else {
+		imageName = testImage.ID()
+	}
+
+	idmappings, err := util.ParseIDMapping(nil, nil, "", "")
+	if err != nil {
+		logrus.Fatal(err)
+	}
+	config := &cc.CreateConfig{
+		Tty:        true,
+		Image:      imageName,
+		ImageID:    testImage.ID(),
+		IDMappings: idmappings,
+		Command:    []string{"/bin/sh"},
+		WorkDir:    "/",
+		NetMode:    "bridge",
+		Network:    "bridge",
+	}
+
+	// Enable CPU Profile
+	defer profile.Start().Stop()
+
+	data, err := runSingleThreadedStressTest(ctx, client, imageName, testImage.ID(), config, *testRunCount)
+	if err != nil {
+		logrus.Fatal(err)
+	}
+
+	data.printProfiledData((float64)(*testRunCount))
+}
+
+func defaultRuntimeOptions() []libpod.RuntimeOption {
+	options := []libpod.RuntimeOption{}
+	return options
+	/*
+		//TODO: Shall we test in clean environment?
+		sOpts := storage.StoreOptions{
+			GraphDriverName: "overlay",
+			RunRoot:         "/var/run/containers/storage",
+			GraphRoot:       "/var/lib/containers/storage",
+		}
+
+		storageOpts := libpod.WithStorageConfig(sOpts)
+		options = append(options, storageOpts)
+		return options
+	*/
+}
+
+func printSystemInfo(client *libpod.Runtime) error {
+	OCIRuntimeInfo, err := client.GetOCIRuntimeVersion()
+	if err != nil {
+		return err
+	}
+
+	connmanInfo, err := client.GetConmonVersion()
+	if err != nil {
+		return err
+	}
+	fmt.Printf("%s\n%s\n\n", OCIRuntimeInfo, connmanInfo)
+	return nil
+}
+
+func runSingleThreadedStressTest(ctx context.Context, client *libpod.Runtime, imageName string, imageID string, config *cc.CreateConfig, testCount int) (*profileData, error) {
+	data := new(profileData)
+	fmt.Printf("Test Round: ")
+	for i := 0; i < testCount; i++ {
+		fmt.Printf("%d ", i)
+
+		runtimeSpec, err := cc.CreateConfigToOCISpec(config)
+		if err != nil {
+			return nil, err
+		}
+
+		//Create Container
+		networks := make([]string, 0)
+		netmode := "bridge"
+		createStartTime := time.Now()
+		ctr, err := client.NewContainer(ctx,
+			runtimeSpec,
+			libpod.WithRootFSFromImage(imageID, imageName, false),
+			libpod.WithNetNS([]ocicni.PortMapping{}, false, netmode, networks),
+		)
+		if err != nil {
+			return nil, err
+		}
+		createTotalTime := time.Now().Sub(createStartTime)
+
+		// Start container
+		startStartTime := time.Now()
+		err = ctr.Start(ctx)
+		if err != nil {
+			return nil, err
+		}
+		startTotalTime := time.Now().Sub(startStartTime)
+
+		//Stop Container
+		stopStartTime := time.Now()
+		err = ctr.StopWithTimeout(2)
+		if err != nil {
+			return nil, err
+		}
+		stopTotalTime := time.Now().Sub(stopStartTime)
+
+		//Delete Container
+		deleteStartTime := time.Now()
+
+		err = client.RemoveContainer(ctx, ctr, true)
+		if err != nil {
+			return nil, err
+		}
+
+		deleteTotalTime := time.Now().Sub(deleteStartTime)
+
+		data.updateProfileData(createTotalTime, startTotalTime, stopTotalTime, deleteTotalTime)
+	}
+	return data, nil
+}
+
+type profileData struct {
+	minCreate, minStart, minStop, minDel time.Duration
+	avgCreate, avgStart, avgStop, avgDel time.Duration
+	maxCreate, maxStart, maxStop, maxDel time.Duration
+}
+
+func (data *profileData) updateProfileData(create, start, stop, delete time.Duration) {
+	if create < data.minCreate || data.minCreate == 0 {
+		data.minCreate = create
+	}
+	if create > data.maxCreate || data.maxCreate == 0 {
+		data.maxCreate = create
+	}
+	if start < data.minStart || data.minStart == 0 {
+		data.minStart = start
+	}
+	if start > data.maxStart || data.maxStart == 0 {
+		data.maxStart = start
+	}
+	if stop < data.minStop || data.minStop == 0 {
+		data.minStop = stop
+	}
+	if stop > data.maxStop || data.maxStop == 0 {
+		data.maxStop = stop
+	}
+	if delete < data.minDel || data.minDel == 0 {
+		data.minDel = delete
+	}
+	if delete > data.maxDel || data.maxDel == 0 {
+		data.maxDel = delete
+	}
+
+	data.avgCreate = data.avgCreate + create
+	data.avgStart = data.avgStart + start
+	data.avgStop = data.avgStop + stop
+	data.avgDel = data.avgDel + delete
+}
+
+func (data *profileData) printProfiledData(testCount float64) {
+
+	fmt.Printf("\nProfile data\n\n")
+	w := new(tabwriter.Writer)
+	w.Init(os.Stdout, 0, 8, 0, '\t', 0)
+	fmt.Fprintln(w, "\tCreate\tStart\tStop\tDelete")
+	fmt.Fprintf(w, "Min\t%.2fs\t%.2fs\t%.2fs\t%.2fs\n", data.minCreate.Seconds(), data.minStart.Seconds(), data.minStop.Seconds(), data.minDel.Seconds())
+	fmt.Fprintf(w, "Avg\t%.2fs\t%.2fs\t%.2fs\t%.2fs\n", data.avgCreate.Seconds()/testCount, data.avgStart.Seconds()/testCount, data.avgStop.Seconds()/testCount, data.avgDel.Seconds()/testCount)
+	fmt.Fprintf(w, "Max\t%.2fs\t%.2fs\t%.2fs\t%.2fs\n", data.maxCreate.Seconds(), data.maxStart.Seconds(), data.maxStop.Seconds(), data.maxDel.Seconds())
+	fmt.Fprintf(w, "Total\t%.2fs\t%.2fs\t%.2fs\t%.2fs\n", data.avgCreate.Seconds(), data.avgStart.Seconds(), data.avgStop.Seconds(), data.avgDel.Seconds())
+	fmt.Fprintln(w)
+	w.Flush()
+}

vendor.conf

@@ -100,3 +100,4 @@ github.com/ulikunitz/xz v0.5.4
 github.com/mailru/easyjson 03f2033d19d5860aef995fe360ac7d395cd8ce65
 github.com/coreos/go-iptables 25d087f3cffd9aedc0c2b7eff25f23cbf3c20fe1
 github.com/google/shlex c34317bd91bf98fab745d77b03933cf8769299fe
+github.com/pkg/profile v1.2.1

vendor/github.com/pkg/profile/LICENSE

@@ -0,0 +1,24 @@
+Copyright (c) 2013 Dave Cheney. All rights reserved.
+
+Redistribution and use in source and binary forms, with or without
+modification, are permitted provided that the following conditions are
+met:
+
+   * Redistributions of source code must retain the above copyright
+notice, this list of conditions and the following disclaimer.
+   * Redistributions in binary form must reproduce the above
+copyright notice, this list of conditions and the following disclaimer
+in the documentation and/or other materials provided with the
+distribution.
+
+THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+"AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+(INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.

vendor/github.com/pkg/profile/README.md

@@ -0,0 +1,54 @@
+profile
+=======
+
+Simple profiling support package for Go
+
+[![Build Status](https://travis-ci.org/pkg/profile.svg?branch=master)](https://travis-ci.org/pkg/profile) [![GoDoc](http://godoc.org/github.com/pkg/profile?status.svg)](http://godoc.org/github.com/pkg/profile)
+
+
+installation
+------------
+
+    go get github.com/pkg/profile
+
+usage
+-----
+
+Enabling profiling in your application is as simple as one line at the top of your main function
+
+```go
+import "github.com/pkg/profile"
+
+func main() {
+    defer profile.Start().Stop()
+    ...
+}
+```
+
+options
+-------
+
+What to profile is controlled by config value passed to profile.Start. 
+By default CPU profiling is enabled.
+
+```go
+import "github.com/pkg/profile"
+
+func main() {
+    // p.Stop() must be called before the program exits to
+    // ensure profiling information is written to disk.
+    p := profile.Start(profile.MemProfile, profile.ProfilePath("."), profile.NoShutdownHook)
+    ...
+}
+```
+
+Several convenience package level values are provided for cpu, memory, and block (contention) profiling.
+
+For more complex options, consult the [documentation](http://godoc.org/github.com/pkg/profile).
+
+contributing
+------------
+
+We welcome pull requests, bug fixes and issue reports.
+
+Before proposing a change, please discuss it first by raising an issue.

vendor/github.com/pkg/profile/mutex.go

@@ -0,0 +1,13 @@
+// +build go1.8
+
+package profile
+
+import "runtime"
+
+func enableMutexProfile() {
+	runtime.SetMutexProfileFraction(1)
+}
+
+func disableMutexProfile() {
+	runtime.SetMutexProfileFraction(0)
+}

vendor/github.com/pkg/profile/mutex17.go

@@ -0,0 +1,9 @@
+// +build !go1.8
+
+package profile
+
+// mock mutex support for Go 1.7 and earlier.
+
+func enableMutexProfile() {}
+
+func disableMutexProfile() {}

vendor/github.com/pkg/profile/profile.go

@@ -0,0 +1,244 @@
+// Package profile provides a simple way to manage runtime/pprof
+// profiling of your Go application.
+package profile
+
+import (
+	"io/ioutil"
+	"log"
+	"os"
+	"os/signal"
+	"path/filepath"
+	"runtime"
+	"runtime/pprof"
+	"sync/atomic"
+)
+
+const (
+	cpuMode = iota
+	memMode
+	mutexMode
+	blockMode
+	traceMode
+)
+
+// Profile represents an active profiling session.
+type Profile struct {
+	// quiet suppresses informational messages during profiling.
+	quiet bool
+
+	// noShutdownHook controls whether the profiling package should
+	// hook SIGINT to write profiles cleanly.
+	noShutdownHook bool
+
+	// mode holds the type of profiling that will be made
+	mode int
+
+	// path holds the base path where various profiling files are  written.
+	// If blank, the base path will be generated by ioutil.TempDir.
+	path string
+
+	// memProfileRate holds the rate for the memory profile.
+	memProfileRate int
+
+	// closer holds a cleanup function that run after each profile
+	closer func()
+
+	// stopped records if a call to profile.Stop has been made
+	stopped uint32
+}
+
+// NoShutdownHook controls whether the profiling package should
+// hook SIGINT to write profiles cleanly.
+// Programs with more sophisticated signal handling should set
+// this to true and ensure the Stop() function returned from Start()
+// is called during shutdown.
+func NoShutdownHook(p *Profile) { p.noShutdownHook = true }
+
+// Quiet suppresses informational messages during profiling.
+func Quiet(p *Profile) { p.quiet = true }
+
+// CPUProfile enables cpu profiling.
+// It disables any previous profiling settings.
+func CPUProfile(p *Profile) { p.mode = cpuMode }
+
+// DefaultMemProfileRate is the default memory profiling rate.
+// See also http://golang.org/pkg/runtime/#pkg-variables
+const DefaultMemProfileRate = 4096
+
+// MemProfile enables memory profiling.
+// It disables any previous profiling settings.
+func MemProfile(p *Profile) {
+	p.memProfileRate = DefaultMemProfileRate
+	p.mode = memMode
+}
+
+// MemProfileRate enables memory profiling at the preferred rate.
+// It disables any previous profiling settings.
+func MemProfileRate(rate int) func(*Profile) {
+	return func(p *Profile) {
+		p.memProfileRate = rate
+		p.mode = memMode
+	}
+}
+
+// MutexProfile enables mutex profiling.
+// It disables any previous profiling settings.
+//
+// Mutex profiling is a no-op before go1.8.
+func MutexProfile(p *Profile) { p.mode = mutexMode }
+
+// BlockProfile enables block (contention) profiling.
+// It disables any previous profiling settings.
+func BlockProfile(p *Profile) { p.mode = blockMode }
+
+// Trace profile controls if execution tracing will be enabled. It disables any previous profiling settings.
+func TraceProfile(p *Profile) { p.mode = traceMode }
+
+// ProfilePath controls the base path where various profiling
+// files are written. If blank, the base path will be generated
+// by ioutil.TempDir.
+func ProfilePath(path string) func(*Profile) {
+	return func(p *Profile) {
+		p.path = path
+	}
+}
+
+// Stop stops the profile and flushes any unwritten data.
+func (p *Profile) Stop() {
+	if !atomic.CompareAndSwapUint32(&p.stopped, 0, 1) {
+		// someone has already called close
+		return
+	}
+	p.closer()
+	atomic.StoreUint32(&started, 0)
+}
+
+// started is non zero if a profile is running.
+var started uint32
+
+// Start starts a new profiling session.
+// The caller should call the Stop method on the value returned
+// to cleanly stop profiling.
+func Start(options ...func(*Profile)) interface {
+	Stop()
+} {
+	if !atomic.CompareAndSwapUint32(&started, 0, 1) {
+		log.Fatal("profile: Start() already called")
+	}
+
+	var prof Profile
+	for _, option := range options {
+		option(&prof)
+	}
+
+	path, err := func() (string, error) {
+		if p := prof.path; p != "" {
+			return p, os.MkdirAll(p, 0777)
+		}
+		return ioutil.TempDir("", "profile")
+	}()
+
+	if err != nil {
+		log.Fatalf("profile: could not create initial output directory: %v", err)
+	}
+
+	logf := func(format string, args ...interface{}) {
+		if !prof.quiet {
+			log.Printf(format, args...)
+		}
+	}
+
+	switch prof.mode {
+	case cpuMode:
+		fn := filepath.Join(path, "cpu.pprof")
+		f, err := os.Create(fn)
+		if err != nil {
+			log.Fatalf("profile: could not create cpu profile %q: %v", fn, err)
+		}
+		logf("profile: cpu profiling enabled, %s", fn)
+		pprof.StartCPUProfile(f)
+		prof.closer = func() {
+			pprof.StopCPUProfile()
+			f.Close()
+			logf("profile: cpu profiling disabled, %s", fn)
+		}
+
+	case memMode:
+		fn := filepath.Join(path, "mem.pprof")
+		f, err := os.Create(fn)
+		if err != nil {
+			log.Fatalf("profile: could not create memory profile %q: %v", fn, err)
+		}
+		old := runtime.MemProfileRate
+		runtime.MemProfileRate = prof.memProfileRate
+		logf("profile: memory profiling enabled (rate %d), %s", runtime.MemProfileRate, fn)
+		prof.closer = func() {
+			pprof.Lookup("heap").WriteTo(f, 0)
+			f.Close()
+			runtime.MemProfileRate = old
+			logf("profile: memory profiling disabled, %s", fn)
+		}
+
+	case mutexMode:
+		fn := filepath.Join(path, "mutex.pprof")
+		f, err := os.Create(fn)
+		if err != nil {
+			log.Fatalf("profile: could not create mutex profile %q: %v", fn, err)
+		}
+		enableMutexProfile()
+		logf("profile: mutex profiling enabled, %s", fn)
+		prof.closer = func() {
+			if mp := pprof.Lookup("mutex"); mp != nil {
+				mp.WriteTo(f, 0)
+			}
+			f.Close()
+			disableMutexProfile()
+			logf("profile: mutex profiling disabled, %s", fn)
+		}
+
+	case blockMode:
+		fn := filepath.Join(path, "block.pprof")
+		f, err := os.Create(fn)
+		if err != nil {
+			log.Fatalf("profile: could not create block profile %q: %v", fn, err)
+		}
+		runtime.SetBlockProfileRate(1)
+		logf("profile: block profiling enabled, %s", fn)
+		prof.closer = func() {
+			pprof.Lookup("block").WriteTo(f, 0)
+			f.Close()
+			runtime.SetBlockProfileRate(0)
+			logf("profile: block profiling disabled, %s", fn)
+		}
+
+	case traceMode:
+		fn := filepath.Join(path, "trace.out")
+		f, err := os.Create(fn)
+		if err != nil {
+			log.Fatalf("profile: could not create trace output file %q: %v", fn, err)
+		}
+		if err := startTrace(f); err != nil {
+			log.Fatalf("profile: could not start trace: %v", err)
+		}
+		logf("profile: trace enabled, %s", fn)
+		prof.closer = func() {
+			stopTrace()
+			logf("profile: trace disabled, %s", fn)
+		}
+	}
+
+	if !prof.noShutdownHook {
+		go func() {
+			c := make(chan os.Signal, 1)
+			signal.Notify(c, os.Interrupt)
+			<-c
+
+			log.Println("profile: caught interrupt, stopping profiles")
+			prof.Stop()
+
+			os.Exit(0)
+		}()
+	}
+
+	return &prof
+}

vendor/github.com/pkg/profile/trace.go

@@ -0,0 +1,8 @@
+// +build go1.7
+
+package profile
+
+import "runtime/trace"
+
+var startTrace = trace.Start
+var stopTrace = trace.Stop

vendor/github.com/pkg/profile/trace16.go

@@ -0,0 +1,10 @@
+// +build !go1.7
+
+package profile
+
+import "io"
+
+// mock trace support for Go 1.6 and earlier.
+
+func startTrace(w io.Writer) error { return nil }
+func stopTrace()                   {}