Add option to dump profiling metrics within a container's stdout logs.

This is part of a series of changes to add metric charts in performance
benchmarks.

This change is useful to be able to extract profiling metric data easily
regardless of runtime configuration.

This change also changes where profiling metrics are initialized and
configured. They are now only part of `runsc boot`, rather than all `runsc`
invocations.

PiperOrigin-RevId: 629900287

pkg/metric/metric_test.go

@@ -1127,7 +1127,7 @@ func TestMetricProfiling(t *testing.T) {
 
 			// Check the header
 			lines := bufio.NewScanner(f)
-			expectedHeader := "Time (ns)\t" + strings.Join(test.metricNames, "\t")
+			expectedHeader := metricsPrefix + "Time (ns)\t" + strings.Join(test.metricNames, "\t")
 			lines.Scan()
 			header := lines.Text()
 			if header != expectedHeader {
@@ -1141,7 +1141,7 @@ func TestMetricProfiling(t *testing.T) {
 			prevValues := make([]uint64, numMetrics)
 			numDatapoints := 0
 			for lines.Scan() {
-				line := lines.Text()
+				line := strings.TrimPrefix(lines.Text(), metricsPrefix)
 				numDatapoints++
 				items := strings.Split(line, "\t")
 				if len(items) != (numMetrics + 1) {

pkg/metric/profiling_metric.go

@@ -30,6 +30,8 @@ import (
 const (
 	snapshotBufferSize     = 1000
 	snapshotRingbufferSize = 16
+	// metricsPrefix is prepended before every metrics line.
+	metricsPrefix = "GVISOR_METRICS\t"
 )
 
 var (
@@ -85,7 +87,8 @@ func StartProfilingMetrics(profilingMetrics string, profilingRate time.Duration)
 	}
 
 	var values []func(fieldValues ...*FieldValue) uint64
-	header := strings.Builder{}
+	var header strings.Builder
+	header.WriteString(metricsPrefix)
 	header.WriteString("Time (ns)")
 	numMetrics := 0
 
@@ -136,6 +139,7 @@ func StartProfilingMetrics(profilingMetrics string, profilingRate time.Duration)
 	writeCh := make(chan writeReq, snapshotRingbufferSize)
 	go collectProfilingMetrics(&s, values, profilingRate, writeCh)
 	go writeProfilingMetrics(&s, header.String(), writeCh)
+	log.Infof("Profiling metrics started.")
 
 	return nil
 }
@@ -213,6 +217,7 @@ func writeProfilingMetrics(s *snapshots, header string, writeReqs <-chan writeRe
 		s.curWriterIndex.Store(int32(req.ringbufferIdx))
 
 		for i := 0; i < req.numLines; i++ {
+			out.WriteString(metricsPrefix)
 			base := i * numEntries
 			// Write the time
 			prometheus.WriteInteger(out, int64(s.ringbuffer[req.ringbufferIdx][base]))

runsc/cli/BUILD

@@ -15,7 +15,6 @@ go_library(
     deps = [
         "//pkg/coverage",
         "//pkg/log",
-        "//pkg/metric",
         "//pkg/refs",
         "//pkg/sentry/platform",
         "//pkg/sentry/syscalls/linux",

runsc/cli/main.go

@@ -31,7 +31,6 @@ import (
 	"golang.org/x/sys/unix"
 	"gvisor.dev/gvisor/pkg/coverage"
 	"gvisor.dev/gvisor/pkg/log"
-	"gvisor.dev/gvisor/pkg/metric"
 	"gvisor.dev/gvisor/pkg/refs"
 	"gvisor.dev/gvisor/pkg/sentry/platform"
 	"gvisor.dev/gvisor/pkg/sentry/syscalls/linux"
@@ -55,11 +54,10 @@ var (
 	// system that are not covered by the runtime spec.
 
 	// Debugging flags.
-	logFD              = flag.Int("log-fd", -1, "file descriptor to log to.  If set, the 'log' flag is ignored.")
-	debugLogFD         = flag.Int("debug-log-fd", -1, "file descriptor to write debug logs to.  If set, the 'debug-log-dir' flag is ignored.")
-	panicLogFD         = flag.Int("panic-log-fd", -1, "file descriptor to write Go's runtime messages.")
-	coverageFD         = flag.Int("coverage-fd", -1, "file descriptor to write Go coverage output.")
-	profilingMetricsFD = flag.Int("profiling-metrics-fd", -1, "file descriptor to write sentry profiling metrics.")
+	logFD      = flag.Int("log-fd", -1, "file descriptor to log to.  If set, the 'log' flag is ignored.")
+	debugLogFD = flag.Int("debug-log-fd", -1, "file descriptor to write debug logs to.  If set, the 'debug-log-dir' flag is ignored.")
+	panicLogFD = flag.Int("panic-log-fd", -1, "file descriptor to write Go's runtime messages.")
+	coverageFD = flag.Int("coverage-fd", -1, "file descriptor to write Go coverage output.")
 )
 
 // Main is the main entrypoint.
@@ -202,12 +200,6 @@ func Main() {
 		f := os.NewFile(uintptr(*coverageFD), "coverage file")
 		coverage.EnableReport(f)
 	}
-	if *profilingMetricsFD >= 0 {
-		metric.ProfilingMetricWriter = os.NewFile(uintptr(*profilingMetricsFD), "metrics file")
-		if metric.ProfilingMetricWriter == nil {
-			log.Warningf("Failed to use -profiling-metrics-fd")
-		}
-	}
 	if conf.TestOnlyAllowRunAsCurrentUserWithoutChroot {
 		// SIGTERM is sent to all processes if a test exceeds its
 		// timeout and this case is handled by syscall_test_runner.

runsc/cmd/boot.go

@@ -153,6 +153,9 @@ type Boot struct {
 	// FDs for profile data.
 	profileFDs profile.FDArgs
 
+	// profilingMetricsFD is a file descriptor to write Sentry metrics data to.
+	profilingMetricsFD int
+
 	// procMountSyncFD is a file descriptor that has to be closed when the
 	// procfs mount isn't needed anymore.
 	procMountSyncFD int
@@ -215,6 +218,7 @@ func (b *Boot) SetFlags(f *flag.FlagSet) {
 
 	// Profiling flags.
 	b.profileFDs.SetFromFlags(f)
+	f.IntVar(&b.profilingMetricsFD, "profiling-metrics-fd", -1, "file descriptor to write sentry profiling metrics.")
 }
 
 // Execute implements subcommands.Command.Execute.  It starts a sandbox in a
@@ -478,7 +482,8 @@ func (b *Boot) Execute(_ context.Context, f *flag.FlagSet, args ...any) subcomma
 	// but before the start-sync file is notified, as the parent process needs to query for
 	// registered metrics prior to sending the start signal.
 	metric.Initialize()
-	if metric.ProfilingMetricWriter != nil {
+	if b.profilingMetricsFD != -1 {
+		metric.ProfilingMetricWriter = os.NewFile(uintptr(b.profilingMetricsFD), "metrics file")
 		if err := metric.StartProfilingMetrics(conf.ProfilingMetrics, time.Duration(conf.ProfilingMetricsRate)*time.Microsecond); err != nil {
 			l.Destroy()
 			util.Fatalf("unable to start profiling metrics: %v", err)

runsc/config/flags.go

@@ -63,7 +63,7 @@ func RegisterFlags(flagSet *flag.FlagSet) {
 	// Metrics flags.
 	flagSet.String("metric-server", "", "if set, export metrics on this address. This may either be 1) 'addr:port' to export metrics on a specific network interface address, 2) ':port' for exporting metrics on all interfaces, or 3) an absolute path to a Unix Domain Socket. The substring '%ID%' will be replaced by the container ID, and '%RUNTIME_ROOT%' by the root. This flag must be specified in both `runsc metric-server` and `runsc create`, and their values must match.")
 	flagSet.String("profiling-metrics", "", "comma separated list of metric names which are going to be written to the profiling-metrics-log file from within the sentry in CSV format. profiling-metrics will be snapshotted at a rate specified by profiling-metrics-rate-us. Requires profiling-metrics-log to be set. (DO NOT USE IN PRODUCTION).")
-	flagSet.String("profiling-metrics-log", "", "file name to use for profiling-metrics output. (DO NOT USE IN PRODUCTION)")
+	flagSet.String("profiling-metrics-log", "", "file name to use for profiling-metrics output; use the special value '-' to write to the user-visible logs. (DO NOT USE IN PRODUCTION)")
 	flagSet.Int("profiling-metrics-rate-us", 1000, "the target rate (in microseconds) at which profiling metrics will be snapshotted.")
 
 	// Debugging flags: strace related

runsc/sandbox/sandbox.go

@@ -772,9 +772,6 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn
 			return err
 		}
 	}
-	if err := donations.DonateDebugLogFile("profiling-metrics-fd", conf.ProfilingMetricsLog, "metrics", test); err != nil {
-		return err
-	}
 
 	// Relay all the config flags to the sandbox process.
 	cmd := exec.Command(specutils.ExePath, conf.ToFlags()...)
@@ -1075,6 +1072,13 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn
 	// Note: this must be done right after "cmd.SysProcAttr.Ctty" is set above
 	// because it relies on stdin being the next FD donated.
 	donations.Donate("stdio-fds", stdios[:]...)
+	if conf.ProfilingMetricsLog == "-" {
+		donations.Donate("profiling-metrics-fd", stdios[1])
+	} else {
+		if err := donations.DonateDebugLogFile("profiling-metrics-fd", conf.ProfilingMetricsLog, "metrics", test); err != nil {
+			return err
+		}
+	}
 
 	totalSysMem, err := totalSystemMemory()
 	if err != nil {