From 79b38029d778d6b3e3978606739beaa2b81b0031 Mon Sep 17 00:00:00 2001 From: Etienne Perot Date: Fri, 21 Apr 2023 14:18:54 -0700 Subject: [PATCH] gVisor metric library: Optimize operations for large-cardinality metrics. This optimizes both increments and lookup operations. It does so using the following: - For metrics of potential cardinality larger than 48, it will switch to using a map rather than linear search for mapping field value combinations to the index that combination corresponds to in the flattened list of values. For metrics of cardinality 48 or smaller, linear search is still used as it is still faster (and also still faster than binary search), as determined by benchmarks. - All field values are checked for pointer uniqueness (i.e. the pointer to the start of each field value string must be unique). This is then used for faster matching: instead of comparing whole strings (and needing to hash them, in the case of doing map-based lookups), it compares pointer values. In the context of this metric library, because all field values must be pre-declared ahead of time, keeping references to these pre-declared strings should always be possible. This is enforced: it will `panic` if the metric user does not do this. In practice, this is easy to do by using `const` strings for all metric values. This change does just that for existing metrics with string fields. From benchmarks, this speeds up the time to take a snapshot of existing metrics by -8.35%. With the unimplemented syscall counter metric, this optimization reduces the slowdown of adding this metric from +4,250% to a still-large but much more manageable +290%. A further optimization (cl/524419591) will reduce this overhead further before re-introducing the unimplemented syscall counter metric. PiperOrigin-RevId: 526134756 --- .github/workflows/go.yml | 2 +- pkg/metric/metric.go | 97 ++++++++++++++----------- pkg/metric/metric_test.go | 59 ++++++++++++--- pkg/metric/metric_unsafe.go | 77 ++++++++++++++++++++ pkg/sentry/fsimpl/gofer/regular_file.go | 2 +- pkg/sentry/fsimpl/gofer/special_file.go | 2 +- pkg/sentry/kernel/task_syscall.go | 2 +- pkg/sentry/platform/kvm/machine.go | 20 +++-- pkg/sentry/syscalls/linux/error.go | 2 +- pkg/sentry/time/calibrated_clock.go | 2 +- pkg/sentry/watchdog/watchdog.go | 4 +- 11 files changed, 202 insertions(+), 67 deletions(-) diff --git a/.github/workflows/go.yml b/.github/workflows/go.yml index 98781e5df..2618c4c59 100644 --- a/.github/workflows/go.yml +++ b/.github/workflows/go.yml @@ -45,7 +45,7 @@ jobs: fetch-depth: 0 - uses: actions/setup-go@v3.5.0 with: - go-version: 1.19 + go-version: '1.20' - run: tools/go_branch.sh - run: git checkout go && git clean -xf . && go build ./... - if: github.event_name == 'push' diff --git a/pkg/metric/metric.go b/pkg/metric/metric.go index c0ba64f3d..66a9b2d4d 100644 --- a/pkg/metric/metric.go +++ b/pkg/metric/metric.go @@ -52,23 +52,42 @@ var ( // ErrTooManyFieldCombinations indicates that the number of unique // combinations of fields is too large to support. ErrTooManyFieldCombinations = errors.New("metric has too many combinations of allowed field values") +) +// Weirdness metric type constants. +const ( + WeirdnessTypeTimeFallback = "time_fallback" + WeirdnessTypePartialResult = "partial_result" + WeirdnessTypeVsyscallCount = "vsyscall_count" + WeirdnessTypeWatchdogStuckStartup = "watchdog_stuck_startup" + WeirdnessTypeWatchdogStuckTasks = "watchdog_stuck_tasks" +) + +// Suspicious operations metric type constants. +const ( + SuspiciousOperationsTypeOpenedWriteExecuteFile = "opened_write_execute_file" +) + +// List of global metrics that are used in multiple places. +var ( // WeirdnessMetric is a metric with fields created to track the number // of weird occurrences such as time fallback, partial_result, vsyscall // count, watchdog startup timeouts and stuck tasks. WeirdnessMetric = MustCreateNewUint64Metric("/weirdness", true /* sync */, "Increment for weird occurrences of problems such as time fallback, partial result, vsyscalls invoked in the sandbox, watchdog startup timeouts and stuck tasks.", - Field{ - name: "weirdness_type", - allowedValues: []string{"time_fallback", "partial_result", "vsyscall_count", "watchdog_stuck_startup", "watchdog_stuck_tasks"}, - }) + NewField("weirdness_type", []string{ + WeirdnessTypeTimeFallback, + WeirdnessTypePartialResult, + WeirdnessTypeVsyscallCount, + WeirdnessTypeWatchdogStuckStartup, + WeirdnessTypeWatchdogStuckTasks, + })) // SuspiciousOperationsMetric is a metric with fields created to detect // operations such as opening an executable file to write from a gofer. SuspiciousOperationsMetric = MustCreateNewUint64Metric("/suspicious_operations", true /* sync */, "Increment for suspicious operations such as opening an executable file to write from a gofer.", - Field{ - name: "operation_type", - allowedValues: []string{"opened_write_execute_file"}, - }) + NewField("operation_type", []string{ + SuspiciousOperationsTypeOpenedWriteExecuteFile, + })) ) // InitStage is the name of a Sentry initialization stage. @@ -196,22 +215,30 @@ type customUint64Metric struct { value func(fieldValues ...string) uint64 } +// fieldMapperMapThreshold is the number of field values after which we switch +// to using map lookups when looking up field values. +// This value was determined using benchmarks to see which is fastest. +const fieldMapperMapThreshold = 48 + // Field contains the field name and allowed values for the metric which is // used in registration of the metric. type Field struct { // name is the metric field name. name string - // allowedValues is the list of allowed values for the field. - allowedValues []string -} + // values is the list of values for the field. + // `values` is always populated but not always used for lookup. It depends + // on the number of allowed field values. `values` is used for lookups on + // fields with small numbers of field values. + values []string -// NewField defines a new Field that can be used to break down a metric. -func NewField(name string, allowedValues []string) Field { - return Field{ - name: name, - allowedValues: allowedValues, - } + // valuesPtrMap is a map version of `values`. For each string in `values`, + // its underlying byte string pointer is mapped to its index in `values`. + // `valuesPtrMap` is used for fields with large numbers of possible values. + // For fields with small numbers of field values, it is nil. + // This map allows doing faster string matching than a normal string map, + // as it avoids the string hashing step that normal string maps need to do. + valuesPtrMap map[*byte]int } // toProto returns the proto definition of this field, for use in metric @@ -219,7 +246,7 @@ func NewField(name string, allowedValues []string) Field { func (f Field) toProto() *pb.MetricMetadata_Field { return &pb.MetricMetadata_Field{ FieldName: f.name, - AllowedValues: f.allowedValues, + AllowedValues: f.values, } } @@ -242,10 +269,10 @@ func newFieldMapper(fields ...Field) (fieldMapper, error) { for _, f := range fields { // Disallow fields with no possible values. We could also ignore them // instead, but passing in a no-allowed-values field is probably a mistake. - if len(f.allowedValues) == 0 { + if len(f.values) == 0 { return fieldMapper{nil, 0}, ErrFieldHasNoAllowedValues } - numFieldCombinations *= len(f.allowedValues) + numFieldCombinations *= len(f.values) // Sanity check, could be useful in case someone dynamically generates too // many fields accidentally. @@ -274,31 +301,13 @@ func (m fieldMapper) lookupConcat(fields1, fields2 []string) int { } idx := 0 remainingCombinationBucket := m.numFieldCombinations - -IdxLookup1: for i, val := range fields1 { - for valIdx, allowedVal := range m.fields[i].allowedValues { - if val == allowedVal { - remainingCombinationBucket /= len(m.fields[i].allowedValues) - idx += remainingCombinationBucket * valIdx - continue IdxLookup1 - } - } - - panic("disallowed field value") + idx, remainingCombinationBucket = m.lookupSingle(i, val, idx, remainingCombinationBucket) } -IdxLookup2: + numFields1 := len(fields1) for i, val := range fields2 { - for valIdx, allowedVal := range m.fields[i+len(fields1)].allowedValues { - if val == allowedVal { - remainingCombinationBucket /= len(m.fields[i+len(fields1)].allowedValues) - idx += remainingCombinationBucket * valIdx - continue IdxLookup2 - } - } - - panic("disallowed field value") + idx, remainingCombinationBucket = m.lookupSingle(i+numFields1, val, idx, remainingCombinationBucket) } return idx @@ -346,8 +355,8 @@ func (m fieldMapper) keyToMultiField(key int) []string { fields := make([]string, depth) remainingCombinationBucket := m.numFieldCombinations for i := 0; i < depth; i++ { - remainingCombinationBucket /= len(m.fields[i].allowedValues) - fields[i] = m.fields[i].allowedValues[key/remainingCombinationBucket] + remainingCombinationBucket /= len(m.fields[i].values) + fields[i] = m.fields[i].values[key/remainingCombinationBucket] key = key % remainingCombinationBucket } return fields @@ -438,7 +447,7 @@ func NewUint64Metric(name string, sync bool, units pb.MetricMetadata_Units, desc return &m, RegisterCustomUint64Metric(name, true /* cumulative */, sync, units, description, m.Value, fields...) } -// MustCreateNewUint64Metric calls RegisterUint64Metric and panics if it returns +// MustCreateNewUint64Metric calls NewUint64Metric and panics if it returns // an error. func MustCreateNewUint64Metric(name string, sync bool, description string, fields ...Field) *Uint64Metric { m, err := NewUint64Metric(name, sync, pb.MetricMetadata_UNITS_NONE, description, fields...) diff --git a/pkg/metric/metric_test.go b/pkg/metric/metric_test.go index df7b4e126..dd5fc5c8a 100644 --- a/pkg/metric/metric_test.go +++ b/pkg/metric/metric_test.go @@ -409,9 +409,11 @@ func TestEmitMetricUpdate(t *testing.T) { func TestEmitMetricUpdateWithFields(t *testing.T) { defer resetTest() - field := Field{ - name: "weirdness_type", - allowedValues: []string{"weird1", "weird2"}} + const ( + weird1 = "weird1" + weird2 = "weird2" + ) + field := NewField("weirdness_type", []string{weird1, weird2}) counter, err := NewUint64Metric("/weirdness", false, pb.MetricMetadata_UNITS_NONE, counterDescription, field) if err != nil { @@ -434,8 +436,8 @@ func TestEmitMetricUpdateWithFields(t *testing.T) { } verifyPrometheusParsing(t) - counter.IncrementBy(4, "weird1") - counter.Increment("weird2") + counter.IncrementBy(4, weird1) + counter.Increment(weird2) emitter.Reset() EmitMetricUpdate() @@ -466,7 +468,7 @@ func TestEmitMetricUpdateWithFields(t *testing.T) { } switch m.FieldValues[0] { - case "weird1": + case weird1: uv, ok := m.Value.(*pb.MetricValue_Uint64Value) if !ok { t.Errorf("%+v: value %v got %T want pb.MetricValue_Uint64Value", m, m.Value, m.Value) @@ -475,7 +477,7 @@ func TestEmitMetricUpdateWithFields(t *testing.T) { t.Errorf("%v: Value got %v want 4", m, uv.Uint64Value) } foundWeird1 = true - case "weird2": + case weird2: uv, ok := m.Value.(*pb.MetricValue_Uint64Value) if !ok { t.Errorf("%+v: value %v got %T want pb.MetricValue_Uint64Value", m, m.Value, m.Value) @@ -910,7 +912,7 @@ func TestFieldMapperWithFields(t *testing.T) { return } if depth == 1 { - for _, val := range remFields[0].allowedValues { + for _, val := range remFields[0].values { fields := append(curFields, val) key := m.lookup(fields...) mapping[key]++ @@ -924,7 +926,7 @@ func TestFieldMapperWithFields(t *testing.T) { } } } else { - for _, val := range remFields[0].allowedValues { + for _, val := range remFields[0].values { visitCombinations(append(curFields, val), remFields[1:]) } } @@ -955,3 +957,42 @@ func TestFieldMapperNoFields(t *testing.T) { t.Errorf("keyToMultiField using key %v (corresponding to no field values): expected no values, got some", key) } } + +func TestFieldPointerUniqueness(t *testing.T) { + foobar := "foobar" + foo := foobar[:3] + panicked := false + func() { + defer func() { + recover() + panicked = true + }() + NewField("field1", []string{foobar, foo}) + }() + if !panicked { + t.Error("did not panic") + } +} + +func TestFieldMapperMustUseSamePointerString(t *testing.T) { + const constFoo = "foo" + heapBar := fmt.Sprintf("%sr", "ba") + n, err := newFieldMapper(NewField("field1", []string{constFoo, heapBar})) + if err != nil { + t.Fatalf("newFieldMapper err: got %v wanted nil", err) + } + n.lookup(constFoo) + n.lookup(heapBar) + newFoo := fmt.Sprintf("%so", "fo") + panicked := false + func() { + defer func() { + recover() + panicked = true + }() + n.lookup(newFoo) + }() + if !panicked { + t.Error("did not panic") + } +} diff --git a/pkg/metric/metric_unsafe.go b/pkg/metric/metric_unsafe.go index 06c043e2a..1a60e5ff0 100644 --- a/pkg/metric/metric_unsafe.go +++ b/pkg/metric/metric_unsafe.go @@ -15,6 +15,7 @@ package metric import ( + "fmt" "unsafe" "gvisor.dev/gvisor/pkg/atomicbitops" @@ -52,3 +53,79 @@ func snapshotDistribution(samples []atomicbitops.Uint64) []uint64 { func CheapNowNano() int64 { return gohacks.Nanotime() } + +// NewField defines a new Field that can be used to break down a metric. +// The set of allowedValues must have unique string pointers (i.e. one cannot +// be a prefix of another from the same underlying byte slice). +// The *same* string pointers must be used during metric modifications. +// In practice, in most cases, this means you should declare these strings as +// `const`s, and always use these `const` strings during metric modifications. +func NewField(name string, allowedValues []string) Field { + // Verify that all string values have a unique pointer. + // We do this because we try to match strings by pointer matching first, + // as this will work in pretty much all cases. + ptrMap := make(map[uintptr]string, len(allowedValues)) + for _, v := range allowedValues { + ptr := uintptr(unsafe.Pointer(unsafe.StringData(v))) + if duplicate, found := ptrMap[ptr]; found { + panic(fmt.Sprintf("found duplicate string values: %q vs %q", v, duplicate)) + } + ptrMap[ptr] = v + } + + if useMap := len(allowedValues) > fieldMapperMapThreshold; !useMap { + return Field{ + name: name, + values: allowedValues, + } + } + + valuesPtrMap := make(map[*byte]int, len(allowedValues)) + for i, v := range allowedValues { + valuesPtrMap[unsafe.StringData(v)] = i + } + return Field{ + name: name, + values: allowedValues, + valuesPtrMap: valuesPtrMap, + } +} + +// lookupSingle looks up a single key for a single field within fieldMapper. +// It is used internally within lookupConcat. +// It returns the updated `idx` and `remainingCombinationBucket` values. +// +checkescape:all +// +//go:nosplit +func (m fieldMapper) lookupSingle(fieldIndex int, fieldValue string, idx, remainingCombinationBucket int) (int, int) { + field := m.fields[fieldIndex] + numValues := len(field.values) + fieldValPtr := unsafe.StringData(fieldValue) + + // Are we doing a linear search? + if field.valuesPtrMap == nil { + // We scan by pointers only. This means the caller must pass the same + // string as the one used in `NewField`. + for valIdx, allowedVal := range field.values { + if fieldValPtr == unsafe.StringData(allowedVal) { + remainingCombinationBucket /= numValues + idx += remainingCombinationBucket * valIdx + return idx, remainingCombinationBucket + } + } + panic("invalid field value or did not reuse the same string pointer as passed in NewField") + } + + // Use map lookup instead. + + // Match using the raw byte pointer of the string. + // This avoids the string hashing step that string maps otherwise do. + valIdx, found := field.valuesPtrMap[fieldValPtr] + if found { + remainingCombinationBucket /= numValues + idx += remainingCombinationBucket * valIdx + return idx, remainingCombinationBucket + } + + panic("invalid field value or did not reuse the same string pointer as passed in NewField") +} diff --git a/pkg/sentry/fsimpl/gofer/regular_file.go b/pkg/sentry/fsimpl/gofer/regular_file.go index 663464c78..afa4437cf 100644 --- a/pkg/sentry/fsimpl/gofer/regular_file.go +++ b/pkg/sentry/fsimpl/gofer/regular_file.go @@ -58,7 +58,7 @@ func newRegularFileFD(mnt *vfs.Mount, d *dentry, flags uint32) (*regularFileFD, return nil, err } if fd.vfsfd.IsWritable() && (d.mode.Load()&0111 != 0) { - metric.SuspiciousOperationsMetric.Increment("opened_write_execute_file") + metric.SuspiciousOperationsMetric.Increment(metric.SuspiciousOperationsTypeOpenedWriteExecuteFile) } if d.mmapFD.Load() >= 0 { fsmetric.GoferOpensHost.Increment() diff --git a/pkg/sentry/fsimpl/gofer/special_file.go b/pkg/sentry/fsimpl/gofer/special_file.go index abba77ffd..7871b1104 100644 --- a/pkg/sentry/fsimpl/gofer/special_file.go +++ b/pkg/sentry/fsimpl/gofer/special_file.go @@ -119,7 +119,7 @@ func newSpecialFileFD(h handle, mnt *vfs.Mount, d *dentry, flags uint32) (*speci d.fs.specialFileFDs.PushBack(fd) d.fs.syncMu.Unlock() if fd.vfsfd.IsWritable() && (d.mode.Load()&0111 != 0) { - metric.SuspiciousOperationsMetric.Increment("opened_write_execute_file") + metric.SuspiciousOperationsMetric.Increment(metric.SuspiciousOperationsTypeOpenedWriteExecuteFile) } if h.fd >= 0 { fsmetric.GoferOpensHost.Increment() diff --git a/pkg/sentry/kernel/task_syscall.go b/pkg/sentry/kernel/task_syscall.go index 11592e300..246044965 100644 --- a/pkg/sentry/kernel/task_syscall.go +++ b/pkg/sentry/kernel/task_syscall.go @@ -367,7 +367,7 @@ func (*runSyscallExit) execute(t *Task) taskRunState { // indicated by an execution fault at address addr. doVsyscall returns the // task's next run state. func (t *Task) doVsyscall(addr hostarch.Addr, sysno uintptr) taskRunState { - metric.WeirdnessMetric.Increment("vsyscall_count") + metric.WeirdnessMetric.Increment(metric.WeirdnessTypeVsyscallCount) // Grab the caller up front, to make sure there's a sensible stack. caller := t.Arch().Native(uintptr(0)) diff --git a/pkg/sentry/platform/kvm/machine.go b/pkg/sentry/platform/kvm/machine.go index b0ee55c1d..4ca8e32e5 100644 --- a/pkg/sentry/platform/kvm/machine.go +++ b/pkg/sentry/platform/kvm/machine.go @@ -103,6 +103,14 @@ const ( vCPUWaiter uint32 = 1 << 2 ) +// Field values for the get_vcpu metric acquisition path used. +const ( + getVCPUAcquisitionFastReused = "fast_reused" + getVCPUAcquisitionReused = "reused" + getVCPUAcquisitionUnused = "unused" + getVCPUAcquisitionStolen = "stolen" +) + var ( // hostExitCounter is a metric that tracks how many times the sentry // performed a host to guest world switch. @@ -128,7 +136,7 @@ var ( // machine.Get() are triggered. getVCPUCounter = metric.MustCreateNewProfilingUint64Metric( "/kvm/get_vcpu", false, "The number of times that machine.Get() was called, split by path the function took.", - metric.NewField("acquisition_type", []string{"fast_reused", "reused", "unused", "stolen"})) + metric.NewField("acquisition_type", []string{getVCPUAcquisitionFastReused, getVCPUAcquisitionReused, getVCPUAcquisitionUnused, getVCPUAcquisitionStolen})) // asInvalidateDuration are durations of calling addressSpace.invalidate(). asInvalidateDuration = metric.MustCreateNewProfilingTimerMetric("/kvm/address_space_invalidate", @@ -453,7 +461,7 @@ func (m *machine) Get() *vCPU { if c := m.vCPUsByTID[tid]; c != nil { c.lock() m.mu.RUnlock() - getVCPUCounter.Increment("fast_reused") + getVCPUCounter.Increment(getVCPUAcquisitionFastReused) return c } @@ -473,7 +481,7 @@ func (m *machine) Get() *vCPU { if c := m.vCPUsByTID[tid]; c != nil { c.lock() m.mu.Unlock() - getVCPUCounter.Increment("reused") + getVCPUCounter.Increment(getVCPUAcquisitionReused) return c } @@ -486,7 +494,7 @@ func (m *machine) Get() *vCPU { m.vCPUsByTID[tid] = c m.mu.Unlock() c.loadSegments(tid) - getVCPUCounter.Increment("unused") + getVCPUCounter.Increment(getVCPUAcquisitionUnused) return c } @@ -497,7 +505,7 @@ func (m *machine) Get() *vCPU { m.vCPUsByTID[tid] = c m.mu.Unlock() c.loadSegments(tid) - getVCPUCounter.Increment("unused") + getVCPUCounter.Increment(getVCPUAcquisitionUnused) return c } } @@ -525,7 +533,7 @@ func (m *machine) Get() *vCPU { m.vCPUsByTID[tid] = c m.mu.Unlock() c.loadSegments(tid) - getVCPUCounter.Increment("stolen") + getVCPUCounter.Increment(getVCPUAcquisitionStolen) return c } diff --git a/pkg/sentry/syscalls/linux/error.go b/pkg/sentry/syscalls/linux/error.go index ed0fd7a72..c71de33d7 100644 --- a/pkg/sentry/syscalls/linux/error.go +++ b/pkg/sentry/syscalls/linux/error.go @@ -36,7 +36,7 @@ var ( // us to pass a function which does not take any arguments, whereas Increment() // takes a variadic number of arguments. func incrementPartialResultMetric() { - metric.WeirdnessMetric.Increment("partial_result") + metric.WeirdnessMetric.Increment(metric.WeirdnessTypePartialResult) } // HandleIOError handles special error cases for partial results. For some diff --git a/pkg/sentry/time/calibrated_clock.go b/pkg/sentry/time/calibrated_clock.go index aa4128a70..4ef1b9542 100644 --- a/pkg/sentry/time/calibrated_clock.go +++ b/pkg/sentry/time/calibrated_clock.go @@ -97,7 +97,7 @@ func (c *CalibratedClock) resetLocked(str string, v ...any) { c.Warningf(str+" Resetting clock; time may jump.", v...) c.ready = false c.ref.Reset() - metric.WeirdnessMetric.Increment("time_fallback") + metric.WeirdnessMetric.Increment(metric.WeirdnessTypeTimeFallback) } // updateParams updates the timekeeping parameters based on the passed diff --git a/pkg/sentry/watchdog/watchdog.go b/pkg/sentry/watchdog/watchdog.go index 6f15a30b5..bf4325fdb 100644 --- a/pkg/sentry/watchdog/watchdog.go +++ b/pkg/sentry/watchdog/watchdog.go @@ -236,7 +236,7 @@ func (w *Watchdog) waitForStart() { return } - metric.WeirdnessMetric.Increment("watchdog_stuck_startup") + metric.WeirdnessMetric.Increment(metric.WeirdnessTypeWatchdogStuckStartup) var buf bytes.Buffer buf.WriteString(fmt.Sprintf("Watchdog.Start() not called within %s", w.StartupTimeout)) @@ -309,7 +309,7 @@ func (w *Watchdog) runTurn() { // unless they are surrounded by // Task.UninterruptibleSleepStart/Finish. tc = &offender{lastUpdateTime: lastUpdateTime} - metric.WeirdnessMetric.Increment("watchdog_stuck_tasks") + metric.WeirdnessMetric.Increment(metric.WeirdnessTypeWatchdogStuckTasks) newTaskFound = true } newOffenders[t] = tc