Merge pull request #740 from restic/add-debug-profiles

Add debug memory/cpu profile options

src/cmds/restic/global_debug.go

@@ -0,0 +1,60 @@
+// +build debug
+
+package main
+
+import (
+	"fmt"
+	"net/http"
+	_ "net/http/pprof"
+	"os"
+	"restic/errors"
+
+	"github.com/pkg/profile"
+)
+
+var (
+	listenMemoryProfile string
+	memProfilePath      string
+	cpuProfilePath      string
+
+	prof interface {
+		Stop()
+	}
+)
+
+func init() {
+	f := cmdRoot.PersistentFlags()
+	f.StringVar(&listenMemoryProfile, "listen-profile", "", "listen on this `address:port` for memory profiling")
+	f.StringVar(&memProfilePath, "mem-profile", "", "write memory profile to `dir`")
+	f.StringVar(&cpuProfilePath, "cpu-profile", "", "write cpu profile to `dir`")
+}
+
+func runDebug() error {
+	if listenMemoryProfile != "" {
+		fmt.Fprintf(os.Stderr, "running memory profile HTTP server on %v\n", listenMemoryProfile)
+		go func() {
+			err := http.ListenAndServe(listenMemoryProfile, nil)
+			if err != nil {
+				fmt.Fprintf(os.Stderr, "memory profile listen failed: %v\n", err)
+			}
+		}()
+	}
+
+	if memProfilePath != "" && cpuProfilePath != "" {
+		return errors.Fatal("only one profile (memory or CPU) may be activated at the same time")
+	}
+
+	if memProfilePath != "" {
+		prof = profile.Start(profile.Quiet, profile.MemProfile, profile.ProfilePath(memProfilePath))
+	} else if memProfilePath != "" {
+		prof = profile.Start(profile.Quiet, profile.CPUProfile, profile.ProfilePath(memProfilePath))
+	}
+
+	return nil
+}
+
+func shutdownDebug() {
+	if prof != nil {
+		prof.Stop()
+	}
+}

src/cmds/restic/global_release.go

@@ -0,0 +1,9 @@
+// +build !debug
+
+package main
+
+// runDebug is a noop without the debug tag.
+func runDebug() error { return nil }
+
+// shutdownDebug is a noop without the debug tag.
+func shutdownDebug() {}

src/cmds/restic/main.go

@@ -22,6 +22,15 @@ directories in an encrypted repository stored on different backends.
 `,
 	SilenceErrors: true,
 	SilenceUsage:  true,
+
+	// run the debug functions for all subcommands (if build tag "debug" is
+	// enabled)
+	PersistentPreRunE: func(*cobra.Command, []string) error {
+		return runDebug()
+	},
+	PersistentPostRun: func(*cobra.Command, []string) {
+		shutdownDebug()
+	},
 }
 
 func init() {

vendor/manifest

@@ -37,6 +37,12 @@
 			"revision": "17b591df37844cde689f4d5813e5cea0927d8dd2",
 			"branch": "master"
 		},
+		{
+			"importpath": "github.com/pkg/profile",
+			"repository": "https://github.com/pkg/profile",
+			"revision": "1c16f117a3ab788fdf0e334e623b8bccf5679866",
+			"branch": "HEAD"
+		},
 		{
 			"importpath": "github.com/pkg/sftp",
 			"repository": "https://github.com/pkg/sftp",

vendor/src/github.com/pkg/profile/AUTHORS

@@ -0,0 +1 @@
+Dave Cheney <dave@cheney.net>

vendor/src/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/src/github.com/pkg/profile/README.md

@@ -0,0 +1,47 @@
+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).

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

@@ -0,0 +1,56 @@
+package profile_test
+
+import (
+	"flag"
+	"os"
+
+	"github.com/pkg/profile"
+)
+
+func ExampleStart() {
+	// start a simple CPU profile and register
+	// a defer to Stop (flush) the profiling data.
+	defer profile.Start().Stop()
+}
+
+func ExampleCPUProfile() {
+	// CPU profiling is the default profiling mode, but you can specify it
+	// explicitly for completeness.
+	defer profile.Start(profile.CPUProfile).Stop()
+}
+
+func ExampleMemProfile() {
+	// use memory profiling, rather than the default cpu profiling.
+	defer profile.Start(profile.MemProfile).Stop()
+}
+
+func ExampleMemProfileRate() {
+	// use memory profiling with custom rate.
+	defer profile.Start(profile.MemProfileRate(2048)).Stop()
+}
+
+func ExampleProfilePath() {
+	// set the location that the profile will be written to
+	defer profile.Start(profile.ProfilePath(os.Getenv("HOME")))
+}
+
+func ExampleNoShutdownHook() {
+	// disable the automatic shutdown hook.
+	defer profile.Start(profile.NoShutdownHook).Stop()
+}
+
+func ExampleStart_withFlags() {
+	// use the flags package to selectively enable profiling.
+	mode := flag.String("profile.mode", "", "enable profiling mode, one of [cpu, mem, block]")
+	flag.Parse()
+	switch *mode {
+	case "cpu":
+		defer profile.Start(profile.CPUProfile).Stop()
+	case "mem":
+		defer profile.Start(profile.MemProfile).Stop()
+	case "block":
+		defer profile.Start(profile.BlockProfile).Stop()
+	default:
+		// do nothing
+	}
+}

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

@@ -0,0 +1,216 @@
+// 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
+	blockMode
+	traceMode
+)
+
+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
+	}
+}
+
+// BlockProfile enables block (contention) profiling.
+// It disables any previous profiling settings.
+func BlockProfile(p *profile) { p.mode = blockMode }
+
+// 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 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/src/github.com/pkg/profile/profile_test.go

@@ -0,0 +1,304 @@
+package profile
+
+import (
+	"bufio"
+	"bytes"
+	"io"
+	"io/ioutil"
+	"os"
+	"os/exec"
+	"path/filepath"
+	"strings"
+	"testing"
+)
+
+type checkFn func(t *testing.T, stdout, stderr []byte, err error)
+
+var profileTests = []struct {
+	name   string
+	code   string
+	checks []checkFn
+}{{
+	name: "default profile (cpu)",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+	defer profile.Start().Stop()
+}	
+`,
+	checks: []checkFn{
+		NoStdout,
+		Stderr("profile: cpu profiling enabled"),
+		NoErr,
+	},
+}, {
+	name: "memory profile",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+	defer profile.Start(profile.MemProfile).Stop()
+}	
+`,
+	checks: []checkFn{
+		NoStdout,
+		Stderr("profile: memory profiling enabled"),
+		NoErr,
+	},
+}, {
+	name: "memory profile (rate 2048)",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+	defer profile.Start(profile.MemProfileRate(2048)).Stop()
+}	
+`,
+	checks: []checkFn{
+		NoStdout,
+		Stderr("profile: memory profiling enabled (rate 2048)"),
+		NoErr,
+	},
+}, {
+	name: "double start",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+	profile.Start()
+	profile.Start()
+}	
+`,
+	checks: []checkFn{
+		NoStdout,
+		Stderr("cpu profiling enabled", "profile: Start() already called"),
+		Err,
+	},
+}, {
+	name: "block profile",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+	defer profile.Start(profile.BlockProfile).Stop()
+}	
+`,
+	checks: []checkFn{
+		NoStdout,
+		Stderr("profile: block profiling enabled"),
+		NoErr,
+	},
+}, {
+	name: "profile path",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+	defer profile.Start(profile.ProfilePath(".")).Stop()
+}	
+`,
+	checks: []checkFn{
+		NoStdout,
+		Stderr("profile: cpu profiling enabled, cpu.pprof"),
+		NoErr,
+	},
+}, {
+	name: "profile path error",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+		defer profile.Start(profile.ProfilePath("README.md")).Stop()
+}	
+`,
+	checks: []checkFn{
+		NoStdout,
+		Stderr("could not create initial output"),
+		Err,
+	},
+}, {
+	name: "multiple profile sessions",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+	profile.Start(profile.CPUProfile).Stop()
+	profile.Start(profile.MemProfile).Stop()
+	profile.Start(profile.BlockProfile).Stop()
+	profile.Start(profile.CPUProfile).Stop()
+}
+`,
+	checks: []checkFn{
+		NoStdout,
+		Stderr("profile: cpu profiling enabled",
+			"profile: cpu profiling disabled",
+			"profile: memory profiling enabled",
+			"profile: memory profiling disabled",
+			"profile: block profiling enabled",
+			"profile: block profiling disabled"),
+		NoErr,
+	},
+}, {
+	name: "profile quiet",
+	code: `
+package main
+
+import "github.com/pkg/profile"
+
+func main() {
+        defer profile.Start(profile.Quiet).Stop()
+}       
+`,
+	checks: []checkFn{NoStdout, NoStderr, NoErr},
+}}
+
+func TestProfile(t *testing.T) {
+	for _, tt := range profileTests {
+		t.Log(tt.name)
+		stdout, stderr, err := runTest(t, tt.code)
+		for _, f := range tt.checks {
+			f(t, stdout, stderr, err)
+		}
+	}
+}
+
+// NoStdout checks that stdout was blank.
+func NoStdout(t *testing.T, stdout, _ []byte, _ error) {
+	if len := len(stdout); len > 0 {
+		t.Errorf("stdout: wanted 0 bytes, got %d", len)
+	}
+}
+
+// Stderr verifies that the given lines match the output from stderr
+func Stderr(lines ...string) checkFn {
+	return func(t *testing.T, _, stderr []byte, _ error) {
+		r := bytes.NewReader(stderr)
+		if !validateOutput(r, lines) {
+			t.Errorf("stderr: wanted '%s', got '%s'", lines, stderr)
+		}
+	}
+}
+
+// NoStderr checks that stderr was blank.
+func NoStderr(t *testing.T, _, stderr []byte, _ error) {
+	if len := len(stderr); len > 0 {
+		t.Errorf("stderr: wanted 0 bytes, got %d", len)
+	}
+}
+
+// Err checks that there was an error returned
+func Err(t *testing.T, _, _ []byte, err error) {
+	if err == nil {
+		t.Errorf("expected error")
+	}
+}
+
+// NoErr checks that err was nil
+func NoErr(t *testing.T, _, _ []byte, err error) {
+	if err != nil {
+		t.Errorf("error: expected nil, got %v", err)
+	}
+}
+
+// validatedOutput validates the given slice of lines against data from the given reader.
+func validateOutput(r io.Reader, want []string) bool {
+	s := bufio.NewScanner(r)
+	for _, line := range want {
+		if !s.Scan() || !strings.Contains(s.Text(), line) {
+			return false
+		}
+	}
+	return true
+}
+
+var validateOutputTests = []struct {
+	input string
+	lines []string
+	want  bool
+}{{
+	input: "",
+	want:  true,
+}, {
+	input: `profile: yes
+`,
+	want: true,
+}, {
+	input: `profile: yes
+`,
+	lines: []string{"profile: yes"},
+	want:  true,
+}, {
+	input: `profile: yes
+profile: no
+`,
+	lines: []string{"profile: yes"},
+	want:  true,
+}, {
+	input: `profile: yes
+profile: no
+`,
+	lines: []string{"profile: yes", "profile: no"},
+	want:  true,
+}, {
+	input: `profile: yes
+profile: no
+`,
+	lines: []string{"profile: no"},
+	want:  false,
+}}
+
+func TestValidateOutput(t *testing.T) {
+	for _, tt := range validateOutputTests {
+		r := strings.NewReader(tt.input)
+		got := validateOutput(r, tt.lines)
+		if tt.want != got {
+			t.Errorf("validateOutput(%q, %q), want %v, got %v", tt.input, tt.lines, tt.want, got)
+		}
+	}
+}
+
+// runTest executes the go program supplied and returns the contents of stdout,
+// stderr, and an error which may contain status information about the result
+// of the program.
+func runTest(t *testing.T, code string) ([]byte, []byte, error) {
+	chk := func(err error) {
+		if err != nil {
+			t.Fatal(err)
+		}
+	}
+	gopath, err := ioutil.TempDir("", "profile-gopath")
+	chk(err)
+	defer os.RemoveAll(gopath)
+
+	srcdir := filepath.Join(gopath, "src")
+	err = os.Mkdir(srcdir, 0755)
+	chk(err)
+	src := filepath.Join(srcdir, "main.go")
+	err = ioutil.WriteFile(src, []byte(code), 0644)
+	chk(err)
+
+	cmd := exec.Command("go", "run", src)
+
+	var stdout, stderr bytes.Buffer
+	cmd.Stdout = &stdout
+	cmd.Stderr = &stderr
+	err = cmd.Run()
+	return stdout.Bytes(), stderr.Bytes(), err
+}

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

@@ -0,0 +1,11 @@
+// +build go1.7
+
+package profile
+
+import "runtime/trace"
+
+// Trace profile controls if execution tracing will be enabled. It disables any previous profiling settings.
+func TraceProfile(p *profile) { p.mode = traceMode }
+
+var startTrace = trace.Start
+var stopTrace = trace.Stop

vendor/src/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()                   {}

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

@@ -0,0 +1,10 @@
+// +build go1.7
+
+package profile_test
+
+import "github.com/pkg/profile"
+
+func ExampleTraceProfile() {
+	// use execution tracing, rather than the default cpu profiling.
+	defer profile.Start(profile.TraceProfile).Stop()
+}