From c8da73daaf635e7ad372ed6b49ce68e8ab4010b8 Mon Sep 17 00:00:00 2001 From: Etienne Perot Date: Wed, 1 May 2024 18:29:47 -0700 Subject: [PATCH] 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 | 4 ++-- pkg/metric/profiling_metric.go | 7 ++++++- runsc/cli/BUILD | 1 - runsc/cli/main.go | 16 ++++------------ runsc/cmd/boot.go | 7 ++++++- runsc/config/flags.go | 2 +- runsc/sandbox/sandbox.go | 10 +++++++--- 7 files changed, 26 insertions(+), 21 deletions(-) diff --git a/pkg/metric/metric_test.go b/pkg/metric/metric_test.go index 65eafc0db..57e24601e 100644 --- a/pkg/metric/metric_test.go +++ b/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) { diff --git a/pkg/metric/profiling_metric.go b/pkg/metric/profiling_metric.go index ae5b0d5d0..1964b709c 100644 --- a/pkg/metric/profiling_metric.go +++ b/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])) diff --git a/runsc/cli/BUILD b/runsc/cli/BUILD index 000d3f033..df7226ca0 100644 --- a/runsc/cli/BUILD +++ b/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", diff --git a/runsc/cli/main.go b/runsc/cli/main.go index c44ad0cb5..0e79ef39b 100644 --- a/runsc/cli/main.go +++ b/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. diff --git a/runsc/cmd/boot.go b/runsc/cmd/boot.go index 1f72e8165..665fec975 100644 --- a/runsc/cmd/boot.go +++ b/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) diff --git a/runsc/config/flags.go b/runsc/config/flags.go index a3e44a9e5..96d6bd1f3 100644 --- a/runsc/config/flags.go +++ b/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 diff --git a/runsc/sandbox/sandbox.go b/runsc/sandbox/sandbox.go index dbc068a46..b5feb4228 100644 --- a/runsc/sandbox/sandbox.go +++ b/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 {