Make profiling commands synchronous.

This allows for a model of profiling when you can start collection, and
it will terminate when the sandbox terminates. Without this synchronous
call, it is effectively impossible to collect length blocking and mutex
profiles.

PiperOrigin-RevId: 349483418

4 files changed, 143 insertions, 165 deletions

diff --git a/runsc/boot/controller.go b/runsc/boot/controller.go
index 865126ac5..9008e1282 100644
--- a/runsc/boot/controller.go
+++ b/runsc/boot/controller.go
@@ -104,13 +104,11 @@ const (
 
 // Profiling related commands (see pprof.go for more details).
 const (
-	StartCPUProfile = "Profile.StartCPUProfile"
-	StopCPUProfile  = "Profile.StopCPUProfile"
-	HeapProfile     = "Profile.HeapProfile"
-	BlockProfile    = "Profile.BlockProfile"
-	MutexProfile    = "Profile.MutexProfile"
-	StartTrace      = "Profile.StartTrace"
-	StopTrace       = "Profile.StopTrace"
+	CPUProfile   = "Profile.CPU"
+	HeapProfile  = "Profile.Heap"
+	BlockProfile = "Profile.Block"
+	MutexProfile = "Profile.Mutex"
+	Trace        = "Profile.Trace"
 )
 
 // Logging related commands (see logging.go for more details).
@@ -132,8 +130,13 @@ type controller struct {
 	// manager holds the containerManager methods.
 	manager *containerManager
 
-	// pprop holds the profile instance if enabled. It may be nil.
+	// pprof holds the profile instance if enabled. It may be nil.
 	pprof *control.Profile
+
+	// stopProfiling has the callback to stop profiling calls. As
+	// this may be executed only once at most, it will be set to nil
+	// after it is executed for the first time.
+	stopProfiling func()
 }
 
 // newController creates a new controller. The caller must call
@@ -164,7 +167,7 @@ func newController(fd int, l *Loader) (*controller, error) {
 	ctrl.srv.Register(&control.Logging{})
 
 	if l.root.conf.ProfileEnable {
-		ctrl.pprof = &control.Profile{Kernel: l.k}
+		ctrl.pprof, ctrl.stopProfiling = control.NewProfile(l.k)
 		ctrl.srv.Register(ctrl.pprof)
 	}
 
@@ -172,10 +175,9 @@ func newController(fd int, l *Loader) (*controller, error) {
 }
 
 func (c *controller) stop() {
-	if c.pprof != nil {
-		// These are noop if there is nothing being profiled.
-		_ = c.pprof.StopCPUProfile(nil, nil)
-		_ = c.pprof.StopTrace(nil, nil)
+	if c.stopProfiling != nil {
+		c.stopProfiling()
+		c.stopProfiling = nil
 	}
 }
 
diff --git a/runsc/boot/loader.go b/runsc/boot/loader.go
index 98ea8db64..f41d6c665 100644
--- a/runsc/boot/loader.go
+++ b/runsc/boot/loader.go
@@ -598,7 +598,6 @@ func (l *Loader) run() error {
 		if err != nil {
 			return err
 		}
-
 	}
 
 	ep.tg = l.k.GlobalInit()
@@ -1045,9 +1044,10 @@ func (l *Loader) WaitExit() kernel.ExitStatus {
 	// Wait for container.
 	l.k.WaitExited()
 
-	// Cleanup
+	// Stop the control server.
 	l.ctrl.stop()
 
+	// Check all references.
 	refs.OnExit()
 
 	return l.k.GlobalInit().ExitStatus()
diff --git a/runsc/cmd/debug.go b/runsc/cmd/debug.go
index 1e5a7471a..195a32ac1 100644
--- a/runsc/cmd/debug.go
+++ b/runsc/cmd/debug.go
@@ -19,6 +19,7 @@ import (
 	"os"
 	"strconv"
 	"strings"
+	"sync"
 	"syscall"
 	"time"
 
@@ -70,10 +71,10 @@ func (d *Debug) SetFlags(f *flag.FlagSet) {
 	f.StringVar(&d.profileCPU, "profile-cpu", "", "writes CPU profile to the given file.")
 	f.StringVar(&d.profileBlock, "profile-block", "", "writes block profile to the given file.")
 	f.StringVar(&d.profileMutex, "profile-mutex", "", "writes mutex profile to the given file.")
-	f.DurationVar(&d.duration, "duration", time.Second, "amount of time to wait for CPU and trace profiles")
+	f.DurationVar(&d.duration, "duration", time.Second, "amount of time to wait for CPU and trace profiles.")
 	f.StringVar(&d.trace, "trace", "", "writes an execution trace to the given file.")
 	f.IntVar(&d.signal, "signal", -1, "sends signal to the sandbox")
-	f.StringVar(&d.strace, "strace", "", `A comma separated list of syscalls to trace. "all" enables all traces, "off" disables all`)
+	f.StringVar(&d.strace, "strace", "", `A comma separated list of syscalls to trace. "all" enables all traces, "off" disables all.`)
 	f.StringVar(&d.logLevel, "log-level", "", "The log level to set: warning (0), info (1), or debug (2).")
 	f.StringVar(&d.logPackets, "log-packets", "", "A boolean value to enable or disable packet logging: true or false.")
 	f.BoolVar(&d.ps, "ps", false, "lists processes")
@@ -128,6 +129,7 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 	}
 	log.Infof("Found sandbox %q, PID: %d", c.Sandbox.ID, c.Sandbox.Pid)
 
+	// Perform synchronous actions.
 	if d.signal > 0 {
 		log.Infof("Sending signal %d to process: %d", d.signal, c.Sandbox.Pid)
 		if err := syscall.Kill(c.Sandbox.Pid, syscall.Signal(d.signal)); err != nil {
@@ -143,80 +145,15 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 		log.Infof("     *** Stack dump ***\n%s", stacks)
 	}
 	if d.profileHeap != "" {
-		f, err := os.Create(d.profileHeap)
+		f, err := os.OpenFile(d.profileHeap, os.O_CREATE|os.O_TRUNC, 0644)
 		if err != nil {
-			return Errorf(err.Error())
+			return Errorf("error opening heap profile output: %v", err)
 		}
 		defer f.Close()
-
 		if err := c.Sandbox.HeapProfile(f); err != nil {
-			return Errorf(err.Error())
-		}
-		log.Infof("Heap profile written to %q", d.profileHeap)
-	}
-	if d.profileBlock != "" {
-		f, err := os.Create(d.profileBlock)
-		if err != nil {
-			return Errorf(err.Error())
-		}
-		defer f.Close()
-
-		if err := c.Sandbox.BlockProfile(f); err != nil {
-			return Errorf(err.Error())
-		}
-		log.Infof("Block profile written to %q", d.profileBlock)
-	}
-	if d.profileMutex != "" {
-		f, err := os.Create(d.profileMutex)
-		if err != nil {
-			return Errorf(err.Error())
-		}
-		defer f.Close()
-
-		if err := c.Sandbox.MutexProfile(f); err != nil {
-			return Errorf(err.Error())
-		}
-		log.Infof("Mutex profile written to %q", d.profileMutex)
-	}
-
-	delay := false
-	if d.profileCPU != "" {
-		delay = true
-		f, err := os.Create(d.profileCPU)
-		if err != nil {
-			return Errorf(err.Error())
-		}
-		defer func() {
-			f.Close()
-			if err := c.Sandbox.StopCPUProfile(); err != nil {
-				Fatalf(err.Error())
-			}
-			log.Infof("CPU profile written to %q", d.profileCPU)
-		}()
-		if err := c.Sandbox.StartCPUProfile(f); err != nil {
-			return Errorf(err.Error())
-		}
-		log.Infof("CPU profile started for %v, writing to %q", d.duration, d.profileCPU)
-	}
-	if d.trace != "" {
-		delay = true
-		f, err := os.Create(d.trace)
-		if err != nil {
-			return Errorf(err.Error())
-		}
-		defer func() {
-			f.Close()
-			if err := c.Sandbox.StopTrace(); err != nil {
-				Fatalf(err.Error())
-			}
-			log.Infof("Trace written to %q", d.trace)
-		}()
-		if err := c.Sandbox.StartTrace(f); err != nil {
-			return Errorf(err.Error())
+			return Errorf("error collecting heap profile: %v", err)
 		}
-		log.Infof("Tracing started for %v, writing to %q", d.duration, d.trace)
 	}
-
 	if d.strace != "" || len(d.logLevel) != 0 || len(d.logPackets) != 0 {
 		args := control.LoggingArgs{}
 		switch strings.ToLower(d.strace) {
@@ -285,8 +222,98 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 		log.Infof(o)
 	}
 
-	if delay {
-		time.Sleep(d.duration)
+	// Open profiling files.
+	var (
+		cpuFile   *os.File
+		traceFile *os.File
+		blockFile *os.File
+		mutexFile *os.File
+	)
+	if d.profileCPU != "" {
+		f, err := os.OpenFile(d.profileCPU, os.O_CREATE|os.O_TRUNC, 0644)
+		if err != nil {
+			return Errorf("error opening cpu profile output: %v", err)
+		}
+		defer f.Close()
+		cpuFile = f
+	}
+	if d.trace != "" {
+		f, err := os.OpenFile(d.trace, os.O_CREATE|os.O_TRUNC, 0644)
+		if err != nil {
+			return Errorf("error opening trace profile output: %v", err)
+		}
+		traceFile = f
+	}
+	if d.profileBlock != "" {
+		f, err := os.OpenFile(d.profileBlock, os.O_CREATE|os.O_TRUNC, 0644)
+		if err != nil {
+			return Errorf("error opening blocking profile output: %v", err)
+		}
+		defer f.Close()
+		blockFile = f
+	}
+	if d.profileMutex != "" {
+		f, err := os.OpenFile(d.profileMutex, os.O_CREATE|os.O_TRUNC, 0644)
+		if err != nil {
+			return Errorf("error opening mutex profile output: %v", err)
+		}
+		defer f.Close()
+		mutexFile = f
+	}
+
+	// Collect profiles.
+	var (
+		wg       sync.WaitGroup
+		cpuErr   error
+		traceErr error
+		blockErr error
+		mutexErr error
+	)
+	if cpuFile != nil {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			cpuErr = c.Sandbox.CPUProfile(cpuFile, d.duration)
+		}()
+	}
+	if traceFile != nil {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			traceErr = c.Sandbox.Trace(traceFile, d.duration)
+		}()
+	}
+	if blockFile != nil {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			blockErr = c.Sandbox.BlockProfile(blockFile, d.duration)
+		}()
+	}
+	if mutexFile != nil {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			mutexErr = c.Sandbox.MutexProfile(mutexFile, d.duration)
+		}()
+	}
+
+	wg.Wait()
+	errorCount := 0
+	if cpuErr != nil {
+		log.Infof("error collecting cpu profile: %v", cpuErr)
+	}
+	if traceErr != nil {
+		log.Infof("error collecting trace profile: %v", traceErr)
+	}
+	if blockErr != nil {
+		log.Infof("error collecting block profile: %v", blockErr)
+	}
+	if mutexErr != nil {
+		log.Infof("error collecting mutex profile: %v", mutexErr)
+	}
+	if errorCount > 0 {
+		return subcommands.ExitFailure
 	}
 
 	return subcommands.ExitSuccess
diff --git a/runsc/sandbox/sandbox.go b/runsc/sandbox/sandbox.go
index c84ebcd8a..c1d13a58d 100644
--- a/runsc/sandbox/sandbox.go
+++ b/runsc/sandbox/sandbox.go
@@ -999,54 +999,30 @@ func (s *Sandbox) HeapProfile(f *os.File) error {
 	}
 	defer conn.Close()
 
-	opts := control.ProfileOpts{
-		FilePayload: urpc.FilePayload{
-			Files: []*os.File{f},
-		},
+	opts := control.HeapProfileOpts{
+		FilePayload: urpc.FilePayload{Files: []*os.File{f}},
 	}
-	if err := conn.Call(boot.HeapProfile, &opts, nil); err != nil {
-		return fmt.Errorf("getting sandbox %q heap profile: %v", s.ID, err)
-	}
-	return nil
+	return conn.Call(boot.HeapProfile, &opts, nil)
 }
 
-// StartCPUProfile start CPU profile writing to the given file.
-func (s *Sandbox) StartCPUProfile(f *os.File) error {
-	log.Debugf("CPU profile start %q", s.ID)
+// CPUProfile collects a CPU profile.
+func (s *Sandbox) CPUProfile(f *os.File, duration time.Duration) error {
+	log.Debugf("CPU profile %q", s.ID)
 	conn, err := s.sandboxConnect()
 	if err != nil {
 		return err
 	}
 	defer conn.Close()
 
-	opts := control.ProfileOpts{
-		FilePayload: urpc.FilePayload{
-			Files: []*os.File{f},
-		},
-	}
-	if err := conn.Call(boot.StartCPUProfile, &opts, nil); err != nil {
-		return fmt.Errorf("starting sandbox %q CPU profile: %v", s.ID, err)
+	opts := control.CPUProfileOpts{
+		FilePayload: urpc.FilePayload{Files: []*os.File{f}},
+		Duration:    duration,
 	}
-	return nil
-}
-
-// StopCPUProfile stops a previously started CPU profile.
-func (s *Sandbox) StopCPUProfile() error {
-	log.Debugf("CPU profile stop %q", s.ID)
-	conn, err := s.sandboxConnect()
-	if err != nil {
-		return err
-	}
-	defer conn.Close()
-
-	if err := conn.Call(boot.StopCPUProfile, nil, nil); err != nil {
-		return fmt.Errorf("stopping sandbox %q CPU profile: %v", s.ID, err)
-	}
-	return nil
+	return conn.Call(boot.CPUProfile, &opts, nil)
 }
 
 // BlockProfile writes a block profile to the given file.
-func (s *Sandbox) BlockProfile(f *os.File) error {
+func (s *Sandbox) BlockProfile(f *os.File, duration time.Duration) error {
 	log.Debugf("Block profile %q", s.ID)
 	conn, err := s.sandboxConnect()
 	if err != nil {
@@ -1054,19 +1030,15 @@ func (s *Sandbox) BlockProfile(f *os.File) error {
 	}
 	defer conn.Close()
 
-	opts := control.ProfileOpts{
-		FilePayload: urpc.FilePayload{
-			Files: []*os.File{f},
-		},
+	opts := control.BlockProfileOpts{
+		FilePayload: urpc.FilePayload{Files: []*os.File{f}},
+		Duration:    duration,
 	}
-	if err := conn.Call(boot.BlockProfile, &opts, nil); err != nil {
-		return fmt.Errorf("getting sandbox %q block profile: %v", s.ID, err)
-	}
-	return nil
+	return conn.Call(boot.BlockProfile, &opts, nil)
 }
 
 // MutexProfile writes a mutex profile to the given file.
-func (s *Sandbox) MutexProfile(f *os.File) error {
+func (s *Sandbox) MutexProfile(f *os.File, duration time.Duration) error {
 	log.Debugf("Mutex profile %q", s.ID)
 	conn, err := s.sandboxConnect()
 	if err != nil {
@@ -1074,50 +1046,27 @@ func (s *Sandbox) MutexProfile(f *os.File) error {
 	}
 	defer conn.Close()
 
-	opts := control.ProfileOpts{
-		FilePayload: urpc.FilePayload{
-			Files: []*os.File{f},
-		},
-	}
-	if err := conn.Call(boot.MutexProfile, &opts, nil); err != nil {
-		return fmt.Errorf("getting sandbox %q mutex profile: %v", s.ID, err)
-	}
-	return nil
-}
-
-// StartTrace start trace  writing to the given file.
-func (s *Sandbox) StartTrace(f *os.File) error {
-	log.Debugf("Trace start %q", s.ID)
-	conn, err := s.sandboxConnect()
-	if err != nil {
-		return err
-	}
-	defer conn.Close()
-
-	opts := control.ProfileOpts{
-		FilePayload: urpc.FilePayload{
-			Files: []*os.File{f},
-		},
-	}
-	if err := conn.Call(boot.StartTrace, &opts, nil); err != nil {
-		return fmt.Errorf("starting sandbox %q trace: %v", s.ID, err)
+	opts := control.MutexProfileOpts{
+		FilePayload: urpc.FilePayload{Files: []*os.File{f}},
+		Duration:    duration,
 	}
-	return nil
+	return conn.Call(boot.MutexProfile, &opts, nil)
 }
 
-// StopTrace stops a previously started trace.
-func (s *Sandbox) StopTrace() error {
-	log.Debugf("Trace stop %q", s.ID)
+// Trace collects an execution trace.
+func (s *Sandbox) Trace(f *os.File, duration time.Duration) error {
+	log.Debugf("Trace %q", s.ID)
 	conn, err := s.sandboxConnect()
 	if err != nil {
 		return err
 	}
 	defer conn.Close()
 
-	if err := conn.Call(boot.StopTrace, nil, nil); err != nil {
-		return fmt.Errorf("stopping sandbox %q trace: %v", s.ID, err)
+	opts := control.TraceProfileOpts{
+		FilePayload: urpc.FilePayload{Files: []*os.File{f}},
+		Duration:    duration,
 	}
-	return nil
+	return conn.Call(boot.Trace, &opts, nil)
 }
 
 // ChangeLogging changes logging options.