Add profiling metric flags to output metric data to local TSV file.

The idea behind conditionally compiled metrics originally was to use them in
hotpaths for profiling purposes. This CL makes that possible by outputting
declared metrics in TSV format, which can be used to track custom events at
runtime in relatively high resolution.

Usage:
    1. Optionally enable compilation of runsc conditionally-compiled metrics
       by passing in condmetric_profiling to the Go tags.
    2. Add these flags to runsc:
    - [Required] --profiling-metrics-log=/tmp/some.csv
    - [Optional] --profiling-metrics=/task/syscalls,/task/faults
      - If this flag is not specified it will monitor all
        conditionally-compiled metrics by default.
    - [Optional] --profiling-metrics-rate-us=10000

Some future improvements:
    - Flag to output a metric-difference between timestamps instead of
      constant accumulation.
    - Output a gnuplot command along with the data.
    - Current monitoring resolution is limited by what time.Sleep allows.
      This can be overcome by spinning/yielding when lower monitoring
      rates are requested.

PiperOrigin-RevId: 560849611
This commit is contained in:
Konstantin Bogomolov
2023-08-28 16:28:09 -07:00
committed by gVisor bot
parent 2ba23f3ae4
commit 440b37a5c1
11 changed files with 482 additions and 10 deletions
+1
View File
@@ -13,6 +13,7 @@ go_library(
"fake_metric.go",
"metric.go",
"metric_unsafe.go",
"profiling_metric.go",
],
visibility = ["//:sandbox"],
deps = [
+25 -2
View File
@@ -17,6 +17,12 @@
package metric
import (
"fmt"
pb "gvisor.dev/gvisor/pkg/metric/metric_go_proto"
)
// This file defines conditional metrics that are meant to be used when profiling
// runsc during benchmark tests.
@@ -40,11 +46,11 @@ type ProfilingTimerMetric = TimerMetric
// NewProfilingUint64Metric is equivalent to NewUint64Metric except it creates a
// ProfilingUint64Metric
var NewProfilingUint64Metric = NewUint64Metric
var NewProfilingUint64Metric = newProfilingUint64Metric
// MustCreateNewProfilingUint64Metric is equivalent to MustCreateNewUint64Metric
// except it creates a ProfilingUint64Metric.
var MustCreateNewProfilingUint64Metric = MustCreateNewUint64Metric
var MustCreateNewProfilingUint64Metric = mustCreateNewProfilingUint64Metric
// NewProfilingDistributionMetric is equivalent to NewDistributionMetric except
// it creates a ProfilingDistributionMetric.
@@ -62,3 +68,20 @@ var NewProfilingTimerMetric = NewTimerMetric
// MustCreateNewProfilingTimerMetric is equivalent to MustCreateNewTimerMetric
// except it creates a ProfilingTimerMetric.
var MustCreateNewProfilingTimerMetric = MustCreateNewTimerMetric
func newProfilingUint64Metric(name string, sync bool, units pb.MetricMetadata_Units, description string, fields ...Field) (*Uint64Metric, error) {
m, err := NewUint64Metric(name, sync, units, description, fields...)
if err != nil {
return m, err
}
definedProfilingMetrics = append(definedProfilingMetrics, m.name)
return m, err
}
func mustCreateNewProfilingUint64Metric(name string, sync bool, description string, fields ...Field) *Uint64Metric {
m, err := newProfilingUint64Metric(name, sync, pb.MetricMetadata_UNITS_NONE, description, fields...)
if err != nil {
panic(fmt.Sprintf("Unable to create metric %q: %s", name, err))
}
return m
}
+156
View File
@@ -15,10 +15,14 @@
package metric
import (
"bufio"
"bytes"
"fmt"
"math"
"os"
"reflect"
"strconv"
"strings"
"testing"
"time"
@@ -1028,3 +1032,155 @@ func TestFieldMapperMustUseSameValuePointer(t *testing.T) {
t.Error("did not panic")
}
}
func TestMetricProfiling(t *testing.T) {
for _, test := range []struct {
name string
profilingMetricsFlag string
metricNames []string
incrementMetricBy []uint64
numIterations uint64
errOnStartProfiling bool
}{
{
name: "simple single metric",
profilingMetricsFlag: "/foo",
metricNames: []string{"/foo"},
incrementMetricBy: []uint64{50},
numIterations: 100,
errOnStartProfiling: false,
},
{
name: "single metric exceeds snapshot buffer",
profilingMetricsFlag: "/foo",
metricNames: []string{"/foo"},
incrementMetricBy: []uint64{1},
numIterations: 3500,
errOnStartProfiling: false,
},
{
name: "multiple metrics",
profilingMetricsFlag: "/foo,/bar,/big/test/baz,/metric",
metricNames: []string{"/foo", "/bar", "/big/test/baz", "/metric"},
incrementMetricBy: []uint64{1, 29, 73, 991},
numIterations: 100,
errOnStartProfiling: false,
},
{
name: "mismatched names",
profilingMetricsFlag: "/foo,/fighter,/big/test/baz,/metric",
metricNames: []string{"/foo", "/bar", "/big/test/baz", "/metric"},
incrementMetricBy: []uint64{},
numIterations: 0,
errOnStartProfiling: true,
},
} {
t.Run(test.name, func(t *testing.T) {
defer resetTest()
const profilingRate = 1000 * time.Microsecond
numMetrics := len(test.metricNames)
metrics := make([]*Uint64Metric, numMetrics)
for i, m := range test.metricNames {
newMetric, err := NewUint64Metric(m, true, pb.MetricMetadata_UNITS_NANOSECONDS, fooDescription)
metrics[i] = newMetric
if err != nil {
t.Fatalf("NewUint64Metric got err '%v' want nil", err)
}
}
f, err := os.CreateTemp(t.TempDir(), "profiling-metrics")
if err != nil {
t.Fatalf("failed to create file: '%v'", err)
}
fName := f.Name()
ProfilingMetricWriter = f
if err := Initialize(); err != nil {
t.Fatalf("Initialize error: got '%v' want nil", err)
}
if err := StartProfilingMetrics(test.profilingMetricsFlag, profilingRate); err != nil {
if test.errOnStartProfiling {
return
}
t.Fatalf("StartProfilingMetrics error: got '%v' want '%v'", err, test.errOnStartProfiling)
}
if test.errOnStartProfiling {
t.Fatal("did not error out on StartProflingMetrics as expected")
}
// Generate some test data
for i := 0; i < int(test.numIterations); i++ {
for metricIdx, m := range metrics {
m.IncrementBy(test.incrementMetricBy[metricIdx])
}
// Give time to the collector to record it.
time.Sleep(profilingRate)
}
StopProfilingMetrics()
f, err = os.Open(fName)
if err != nil {
t.Fatalf("failed to open file a second time: %v", err)
}
// Check the header
lines := bufio.NewScanner(f)
expectedHeader := "Time (ns)\t" + strings.Join(test.metricNames, "\t")
lines.Scan()
header := lines.Text()
if header != expectedHeader {
t.Fatalf("header mismatch: got '%s' want '%s'", header, expectedHeader)
}
// Check that data looks sane:
// - Each timestamp should always be bigger.
// - Each metric value should be at least as big as the previous.
prevTS := uint64(0)
prevValues := make([]uint64, numMetrics)
numDatapoints := 0
for lines.Scan() {
line := lines.Text()
numDatapoints++
items := strings.Split(line, "\t")
if len(items) != (numMetrics + 1) {
t.Fatalf("incorrect number of items on line '%s': got %d, want %d", line, len(items), numMetrics+1)
}
// Check timestamp
ts, err := strconv.ParseUint(items[0], 10, 64)
if err != nil {
t.Errorf("ts ParseUint error on line '%s': got '%v' want nil", line, err)
}
if ts <= prevTS && numDatapoints > 1 {
t.Errorf("expecting timestamp to always increase on line '%s': got %d, previous was %d", line, ts, prevTS)
}
prevTS = ts
// Check metric values
for i := 1; i <= numMetrics; i++ {
m, err := strconv.ParseUint(items[i], 10, 64)
if err != nil {
t.Errorf("m ParseUint error on line '%s': got '%v' want nil", line, err)
}
if m < prevValues[i-1] {
t.Errorf("expecting metric value to always increase on line '%s': got %d, previous was %d", line, m, prevValues[i-1])
}
prevValues[i-1] = m
}
}
expectedMinNumDatapoints := int(0.7 * float32(test.numIterations))
if numDatapoints < expectedMinNumDatapoints {
t.Errorf("numDatapoints: got %d, want at least %d", numDatapoints, expectedMinNumDatapoints)
}
// Check that the final total for each metric is correct
for i := 0; i < numMetrics; i++ {
expected := test.numIterations * test.incrementMetricBy[i]
if prevValues[i] != expected {
t.Errorf("incorrect final metric value: got %d, want %d", prevValues[i], expected)
}
}
f.Close()
})
}
}
+249
View File
@@ -0,0 +1,249 @@
// Copyright 2023 The gVisor Authors.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package metric
import (
"bufio"
"errors"
"fmt"
"os"
"strings"
"time"
"gvisor.dev/gvisor/pkg/atomicbitops"
"gvisor.dev/gvisor/pkg/log"
"gvisor.dev/gvisor/pkg/prometheus"
)
const (
snapshotBufferSize = 1000
snapshotRingbufferSize = 16
)
var (
// ProfilingMetricWriter is the output destination to which
// ProfilingMetrics will be written to in TSV format.
ProfilingMetricWriter *os.File
// profilingMetricsStarted indicates whether StartProfilingMetrics has
// been called.
profilingMetricsStarted atomicbitops.Bool
// stopProfilingMetrics is used to signal to the profiling metrics
// goroutine to stop recording and writing metrics.
stopProfilingMetrics chan bool
// doneProfilingMetrics is used to signal that the profiling metrics
// goroutines are finished.
doneProfilingMetrics chan bool
// definedProfilingMetrics is the set of metrics known to be created for
// profiling (see condmetric_profiling.go).
definedProfilingMetrics []string
)
// snapshots is used to as temporary storage of metric data
// before it's written to the ProfilingMetricWriter.
type snapshots struct {
numMetrics int
// ringbuffer is used to store metric data.
ringbuffer [][]uint64
// curWriterIndex is the ringbuffer index currently being read by the
// writer. It should not be used by the collector.
curWriterIndex atomicbitops.Int32
}
// writeReq is the message sent between from the collector to the writer.
type writeReq struct {
ringbufferIdx int
// numLines indicates how many data lines are filled in the buffer.
numLines int
}
// StartProfilingMetrics checks the ProfilingMetrics runsc flags and creates
// goroutines responsible for outputting the profiling metric data.
//
// Preconditions:
// - All metrics are registered.
// - Initialize/Disable has been called.
func StartProfilingMetrics(profilingMetrics string, profilingRate time.Duration) error {
if !initialized.Load() {
// Wait for initialization to complete to make sure that all
// metrics are registered.
return errors.New("metric initialization is not complete")
}
if ProfilingMetricWriter == nil {
return errors.New("tried to initialize profiling metrics without log file")
}
var values []func(fieldValues ...*FieldValue) uint64
header := strings.Builder{}
header.WriteString("Time (ns)")
numMetrics := 0
if len(profilingMetrics) > 0 {
metrics := strings.Split(profilingMetrics, ",")
numMetrics = len(metrics)
for _, name := range metrics {
name := strings.TrimSpace(name)
m, ok := allMetrics.uint64Metrics[name]
if !ok {
return fmt.Errorf("given profiling metric name '%s' does not correspond to a registered Uint64 metric", name)
}
if len(m.fields) > 0 {
// TODO(b/240280155): Add support for field values.
return fmt.Errorf("will not profile metric '%s' because it has metric fields which are not supported", name)
}
header.WriteRune('\t')
header.WriteString(name)
values = append(values, m.value)
}
header.WriteRune('\n')
} else {
if len(definedProfilingMetrics) > 0 {
return fmt.Errorf("a value for --profiling-metrics was not specified; consider using a subset of '--profiling-metrics=%s'", strings.Join(definedProfilingMetrics, ","))
}
return fmt.Errorf("a value for --profiling-metrics was not specified; also no conditionally compiled metrics found, consider compiling runsc with --go_tag=condmetric_profiling")
}
if !profilingMetricsStarted.CompareAndSwap(0, 1) {
return errors.New("profiling metrics have already been started")
}
s := snapshots{
numMetrics: numMetrics,
ringbuffer: make([][]uint64, snapshotRingbufferSize),
// curWriterIndex is initialized to a valid index so that the
// collector cannot use up all indices before the writer even has
// a chance to start (as unlikely as that is).
curWriterIndex: atomicbitops.FromInt32(snapshotRingbufferSize - 1),
}
for i := 0; i < snapshotRingbufferSize; i++ {
s.ringbuffer[i] = make([]uint64, snapshotBufferSize*(numMetrics+1))
}
stopProfilingMetrics = make(chan bool, 1)
doneProfilingMetrics = make(chan bool, 1)
writeCh := make(chan writeReq, snapshotRingbufferSize)
go collectProfilingMetrics(&s, values, profilingRate, writeCh)
go writeProfilingMetrics(&s, header.String(), writeCh)
return nil
}
// collectProfilingMetrics will send metrics to the writeCh until it receives a
// signal via the stopProfilingMetrics channel.
func collectProfilingMetrics(s *snapshots, values []func(fieldValues ...*FieldValue) uint64, profilingRate time.Duration, writeCh chan<- writeReq) {
defer close(writeCh)
numEntries := s.numMetrics + 1 // to account for the timestamp
ringbufferIdx := 0
curSnapshot := 0
startTime := CheapNowNano()
// getNewRingbufferIdx will block until the writer indicates that some part
// of the ringbuffer is available for writing.
getNewRingbufferIdx := func() {
for {
nextIdx := (ringbufferIdx + 1) % snapshotRingbufferSize
if nextIdx != int(s.curWriterIndex.Load()) {
ringbufferIdx = nextIdx
break
}
// Going too fast, stop collecting for a bit.
log.Warningf("Profiling metrics collector exhausted the entire ringbuffer... backing off to let writer catch up.")
time.Sleep(profilingRate * 100)
}
}
stopCollecting := false
for nextCollection := CheapNowNano() + profilingRate.Nanoseconds(); !stopCollecting; nextCollection += profilingRate.Nanoseconds() {
now := CheapNowNano()
if now < nextCollection {
time.Sleep(time.Duration(nextCollection-now) * time.Nanosecond)
} else {
// Skip collection since we just did one anyway.
continue
}
select {
case <-stopProfilingMetrics:
stopCollecting = true
// Collect one last time before stopping.
default:
}
collectStart := CheapNowNano()
timestamp := time.Duration(collectStart - startTime)
base := curSnapshot * numEntries
s.ringbuffer[ringbufferIdx][base] = uint64(timestamp)
for i := 1; i < numEntries; i++ {
s.ringbuffer[ringbufferIdx][base+i] = values[i-1]()
}
curSnapshot++
if curSnapshot == snapshotBufferSize {
writeCh <- writeReq{ringbufferIdx: ringbufferIdx, numLines: curSnapshot}
curSnapshot = 0
getNewRingbufferIdx()
}
}
if curSnapshot != 0 {
writeCh <- writeReq{ringbufferIdx: ringbufferIdx, numLines: curSnapshot}
}
}
// writeProfilingMetrics will write to the ProfilingMetricsWriter on every
// request via writeReqs, until writeReqs is closed.
func writeProfilingMetrics(s *snapshots, header string, writeReqs <-chan writeReq) {
numEntries := s.numMetrics + 1
out := bufio.NewWriter(ProfilingMetricWriter)
out.WriteString(header)
for req := range writeReqs {
s.curWriterIndex.Store(int32(req.ringbufferIdx))
for i := 0; i < req.numLines; i++ {
base := i * numEntries
// Write the time
prometheus.WriteInteger(out, int64(s.ringbuffer[req.ringbufferIdx][base]))
// Then everything else
for j := 1; j < numEntries; j++ {
out.WriteRune('\t')
prometheus.WriteInteger(out, int64(s.ringbuffer[req.ringbufferIdx][base+j]))
}
out.WriteRune('\n')
}
}
out.Flush()
ProfilingMetricWriter.Close()
doneProfilingMetrics <- true
close(doneProfilingMetrics)
profilingMetricsStarted.Store(false)
}
// StopProfilingMetrics stops the profiling metrics goroutines. Call to make sure
// all metric data has been flushed.
// Note that calling this function prior to StartProfilingMetrics has no effect.
func StopProfilingMetrics() {
if !profilingMetricsStarted.Load() {
return
}
select {
case stopProfilingMetrics <- true:
<-doneProfilingMetrics
default: // Stop signal was already sent
}
}
+6 -4
View File
@@ -239,8 +239,10 @@ func (n *Number) GreaterThan(other *Number) bool {
return n.Float > other.Float
}
// writeInteger writes the given integer to a writer without allocating strings.
func writeInteger(w io.Writer, val int64) (int, error) {
// WriteInteger writes the given integer to a writer without allocating strings.
//
//go:nosplit
func WriteInteger(w io.Writer, val int64) (int, error) {
const decimalDigits = "0123456789"
if val == 0 {
return io.WriteString(w, decimalDigits[0:1])
@@ -279,7 +281,7 @@ func (n *Number) writeTo(w io.Writer) error {
// Integer case:
case n.Int != 0:
_, err := writeInteger(w, n.Int)
_, err := WriteInteger(w, n.Int)
return err
// Special float cases:
@@ -753,7 +755,7 @@ func (d *Data) writeMetricLine(w io.Writer, metricSuffix string, val *Number, wh
if _, err := io.WriteString(w, " "); err != nil {
return err
}
if _, err := writeInteger(w, when.UnixMilli()); err != nil {
if _, err := WriteInteger(w, when.UnixMilli()); err != nil {
return err
}
if _, err := io.WriteString(w, "\n"); err != nil {
+1
View File
@@ -15,6 +15,7 @@ go_library(
deps = [
"//pkg/coverage",
"//pkg/log",
"//pkg/metric",
"//pkg/refs",
"//pkg/sentry/platform",
"//pkg/sentry/syscalls/linux",
+12 -4
View File
@@ -29,6 +29,7 @@ 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"
@@ -51,10 +52,11 @@ 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.")
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.")
)
// Main is the main entrypoint.
@@ -174,6 +176,12 @@ 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")
}
}
log.SetTarget(e)
+8
View File
@@ -25,6 +25,7 @@ import (
"runtime/debug"
"strconv"
"strings"
"time"
"github.com/google/subcommands"
specs "github.com/opencontainers/runtime-spec/specs-go"
@@ -450,6 +451,13 @@ 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 err := metric.StartProfilingMetrics(conf.ProfilingMetrics, time.Duration(conf.ProfilingMetricsRate)*time.Microsecond); err != nil {
l.Destroy()
util.Fatalf("unable to start profiling metrics: %v", err)
}
defer metric.StopProfilingMetrics()
}
// Notify the parent process the sandbox has booted (and that the controller
// is up).
+18
View File
@@ -155,6 +155,21 @@ type Config struct {
// The value of this flag must also match across the two command lines.
MetricServer string `flag:"metric-server"`
// ProfilingMetrics is a comma separated list of metric names which are
// going to be written to the ProfilingMetricsLog file from within the
// sentry in CSV format. ProfilingMetrics will be snapshotted at a rate
// specified by ProfilingMetricsRate. Requires ProfilingMetricsLog to be
// set.
ProfilingMetrics string `flag:"profiling-metrics"`
// ProfilingMetricsLog is the file name to use for ProfilingMetrics
// output.
ProfilingMetricsLog string `flag:"profiling-metrics-log"`
// ProfilingMetricsRate is the target rate (in microseconds) at which
// profiling metrics will be snapshotted.
ProfilingMetricsRate int `flag:"profiling-metrics-rate-us"`
// Strace indicates that strace should be enabled.
Strace bool `flag:"strace"`
@@ -347,6 +362,9 @@ func (c *Config) validate() error {
// Deprecated flag was used together with flag that replaced it.
return fmt.Errorf("fsgofer-host-uds has been replaced with host-uds flag")
}
if len(c.ProfilingMetrics) > 0 && len(c.ProfilingMetricsLog) == 0 {
return fmt.Errorf("profiling-metrics flag requires defining a profiling-metrics-log for output")
}
return nil
}
+3
View File
@@ -61,6 +61,9 @@ 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.Int("profiling-metrics-rate-us", 1000, "the target rate (in microseconds) at which profiling metrics will be snapshotted.")
// Debugging flags: strace related
flagSet.Bool("strace", false, "enable strace.")
+3
View File
@@ -684,6 +684,9 @@ 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()...)