Add support for collecting execution trace to runsc.

Updates #220

PiperOrigin-RevId: 250532302

pkg/sentry/control/pprof.go

@@ -18,6 +18,7 @@ import (
 	"errors"
 	"runtime"
 	"runtime/pprof"
+	"runtime/trace"
 	"sync"
 
 	"gvisor.googlesource.com/gvisor/pkg/fd"
@@ -52,6 +53,9 @@ type Profile struct {
 
 	// cpuFile is the current CPU profile output file.
 	cpuFile *fd.FD
+
+	// traceFile is the current execution trace output file.
+	traceFile *fd.FD
 }
 
 // StartCPUProfile is an RPC stub which starts recording the CPU profile in a
@@ -122,3 +126,43 @@ func (p *Profile) Goroutine(o *ProfileOpts, _ *struct{}) error {
 	}
 	return nil
 }
+
+// StartTrace is an RPC stub which starts collection of an execution trace.
+func (p *Profile) StartTrace(o *ProfileOpts, _ *struct{}) error {
+	if len(o.FilePayload.Files) < 1 {
+		return errNoOutput
+	}
+
+	output, err := fd.NewFromFile(o.FilePayload.Files[0])
+	if err != nil {
+		return err
+	}
+
+	p.mu.Lock()
+	defer p.mu.Unlock()
+
+	// Returns an error if profiling is already started.
+	if err := trace.Start(output); err != nil {
+		output.Close()
+		return err
+	}
+
+	p.traceFile = output
+	return nil
+}
+
+// StopTrace is an RPC stub which stops collection of an ongoing execution
+// trace and flushes the trace data. It takes no argument.
+func (p *Profile) StopTrace(_, _ *struct{}) error {
+	p.mu.Lock()
+	defer p.mu.Unlock()
+
+	if p.traceFile == nil {
+		return errors.New("Execution tracing not start")
+	}
+
+	trace.Stop()
+	p.traceFile.Close()
+	p.traceFile = nil
+	return nil
+}

runsc/boot/controller.go

@@ -101,6 +101,8 @@ const (
 	StartCPUProfile = "Profile.StartCPUProfile"
 	StopCPUProfile  = "Profile.StopCPUProfile"
 	HeapProfile     = "Profile.HeapProfile"
+	StartTrace      = "Profile.StartTrace"
+	StopTrace       = "Profile.StopTrace"
 )
 
 // ControlSocketAddr generates an abstract unix socket name for the given ID.

runsc/cmd/debug.go

@@ -35,6 +35,7 @@ type Debug struct {
 	profileHeap  string
 	profileCPU   string
 	profileDelay int
+	trace        string
 }
 
 // Name implements subcommands.Command.
@@ -59,6 +60,7 @@ func (d *Debug) SetFlags(f *flag.FlagSet) {
 	f.StringVar(&d.profileHeap, "profile-heap", "", "writes heap profile to the given file.")
 	f.StringVar(&d.profileCPU, "profile-cpu", "", "writes CPU profile to the given file.")
 	f.IntVar(&d.profileDelay, "profile-delay", 5, "amount of time to wait before stoping CPU profile")
+	f.StringVar(&d.trace, "trace", "", "writes an execution trace to the given file.")
 	f.IntVar(&d.signal, "signal", -1, "sends signal to the sandbox")
 }
 
@@ -122,24 +124,6 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 		}
 		log.Infof("     *** Stack dump ***\n%s", stacks)
 	}
-	if d.profileCPU != "" {
-		f, err := os.Create(d.profileCPU)
-		if err != nil {
-			Fatalf(err.Error())
-		}
-		defer f.Close()
-
-		if err := c.Sandbox.StartCPUProfile(f); err != nil {
-			Fatalf(err.Error())
-		}
-		log.Infof("CPU profile started for %d sec, writing to %q", d.profileDelay, d.profileCPU)
-		time.Sleep(time.Duration(d.profileDelay) * time.Second)
-
-		if err := c.Sandbox.StopCPUProfile(); err != nil {
-			Fatalf(err.Error())
-		}
-		log.Infof("CPU profile written to %q", d.profileCPU)
-	}
 	if d.profileHeap != "" {
 		f, err := os.Create(d.profileHeap)
 		if err != nil {
@@ -152,5 +136,50 @@ func (d *Debug) Execute(_ context.Context, f *flag.FlagSet, args ...interface{})
 		}
 		log.Infof("Heap profile written to %q", d.profileHeap)
 	}
+
+	delay := false
+	if d.profileCPU != "" {
+		delay = true
+		f, err := os.Create(d.profileCPU)
+		if err != nil {
+			Fatalf(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 {
+			Fatalf(err.Error())
+		}
+		log.Infof("CPU profile started for %d sec, writing to %q", d.profileDelay, d.profileCPU)
+	}
+	if d.trace != "" {
+		delay = true
+		f, err := os.Create(d.trace)
+		if err != nil {
+			Fatalf(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 {
+			Fatalf(err.Error())
+		}
+		log.Infof("Tracing started for %d sec, writing to %q", d.profileDelay, d.trace)
+
+	}
+
+	if delay {
+		time.Sleep(time.Duration(d.profileDelay) * time.Second)
+
+	}
+
 	return subcommands.ExitSuccess
 }

runsc/sandbox/sandbox.go

@@ -883,6 +883,41 @@ func (s *Sandbox) StopCPUProfile() error {
 	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)
+	}
+	return nil
+}
+
+// StopTrace stops a previously started trace..
+func (s *Sandbox) StopTrace() error {
+	log.Debugf("Trace stop %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)
+	}
+	return nil
+}
+
 // DestroyContainer destroys the given container. If it is the root container,
 // then the entire sandbox is destroyed.
 func (s *Sandbox) DestroyContainer(cid string) error {