From cffce1a94a0849a672de65510c7dbd5bca9a64b3 Mon Sep 17 00:00:00 2001 From: Konstantin Bogomolov Date: Wed, 25 Oct 2023 11:53:10 -0700 Subject: [PATCH] systrap: Revise slow-path enablement. The current systrap fastpath heuristics do a good job getting high performance when there are idle CPUs, but fail when there are not enough and do much worse then even the "pure slowpath". Here is a summary of changes made to remedy that: 1. Disable stub and dispatcher fastpath by default. 2. Decouple fastpath states to be separate between dispatcher and stub fastpath. 3. Implement response latency metrics for both sentry->stub and stub->sentry messages. Use these latency metrics in order keep track of the baseline latency for both sides. With baseline latency established, compare fastpath latency to determine how beneficial it is to keep fastpath enabled. Some sampled benchmarks: - sysbench-X-Y: ``` ``` - gettid_benchmark - getpid_benchmark Some benchmark results (5-run average): - On a 4 core machine: []() | HEAD | ThisCL -------------------|----------|----------- sysbench-1-8: | 48218ms | 50282ms sysbench-2-4: | 65900ms | 72282ms sysbench-4-2: |427880ms | 175714ms sysbench-1-2: | 12998ms | 13688ms getpid_benchmark: (HEAD) ``` Benchmark Time CPU Iterations ------------------------------------------------------- BM_Getpid 3471 ns 3441 ns 212121 BM_GetpidOpt 1039 ns 1029 ns 700000 ``` getpid_benchmark: (This CL) ``` Benchmark Time CPU Iterations ------------------------------------------------------- BM_Getpid 3718 ns 3600 ns 200000 BM_GetpidOpt 1320 ns 1281 ns 538462 ``` gettid_benchmark: Like getpid, this CL slightly slower on lower thread count test variants. - On a 1 core machine: getpid_benchmark: (HEAD) ``` Benchmark Time CPU Iterations ------------------------------------------------------- BM_Getpid 74868 ns 75000 ns 10000 BM_GetpidOpt 74463 ns 74286 ns 8750 ``` getpid_benchmark: (This CL) ``` Benchmark Time CPU Iterations ------------------------------------------------------- BM_Getpid 12425 ns 12443 ns 53846 BM_GetpidOpt 8645 ns 8686 ns 87500 ``` gettid_benchmark: Same trend as for getpid_benchmark across the board. Another interesting case to look at for 1-core machines is copying one large file: ``` ./runsc --rootless --network none --ignore-cgroups do --force-overlay=false sh -c "time head -c 1073741824 full-file" ``` - file copy (HEAD): 36.07user 0.00system 0:36.44elapsed 98%CPU - file copy (This CL): 2.96user 0.23system 0:07.14elapsed 44%CPU Fixes #9119. PiperOrigin-RevId: 576600019 --- pkg/sentry/platform/systrap/BUILD | 4 + pkg/sentry/platform/systrap/context_queue.go | 36 +- pkg/sentry/platform/systrap/metrics.go | 580 ++++++++++++++++++ pkg/sentry/platform/systrap/shared_context.go | 135 ++-- pkg/sentry/platform/systrap/subprocess.go | 26 +- pkg/sentry/platform/systrap/sysmsg/sysmsg.go | 12 +- pkg/sentry/platform/systrap/sysmsg/sysmsg.h | 3 +- .../platform/systrap/sysmsg/sysmsg_lib.c | 71 ++- pkg/sentry/platform/systrap/systrap.go | 8 + .../platform/systrap/systrap_profiling.go | 60 ++ .../systrap/systrap_profiling_fake.go | 30 + 11 files changed, 832 insertions(+), 133 deletions(-) create mode 100644 pkg/sentry/platform/systrap/metrics.go create mode 100644 pkg/sentry/platform/systrap/systrap_profiling.go create mode 100644 pkg/sentry/platform/systrap/systrap_profiling_fake.go diff --git a/pkg/sentry/platform/systrap/BUILD b/pkg/sentry/platform/systrap/BUILD index 05e81c470..ab3678984 100644 --- a/pkg/sentry/platform/systrap/BUILD +++ b/pkg/sentry/platform/systrap/BUILD @@ -40,6 +40,7 @@ go_library( "filters_arm64.go", "lib_amd64.s", "lib_arm64.s", + "metrics.go", "shared_context.go", "shared_context_norace.go", "shared_context_race.go", @@ -68,6 +69,8 @@ go_library( "systrap_amd64.go", "systrap_arm64.go", "systrap_arm64_unsafe.go", + "systrap_profiling.go", + "systrap_profiling_fake.go", "systrap_unsafe.go", ], visibility = ["//:sandbox"], @@ -80,6 +83,7 @@ go_library( "//pkg/hostarch", "//pkg/log", "//pkg/memutil", + "//pkg/metric", "//pkg/pool", "//pkg/refs", "//pkg/safecopy", diff --git a/pkg/sentry/platform/systrap/context_queue.go b/pkg/sentry/platform/systrap/context_queue.go index cb771882f..8b2002b74 100644 --- a/pkg/sentry/platform/systrap/context_queue.go +++ b/pkg/sentry/platform/systrap/context_queue.go @@ -44,6 +44,9 @@ type contextQueue struct { // numActiveThreads indicates to the sentry how many stubs are running. // It is changed only by stub threads. numActiveThreads uint32 + // numSpinningThreads indicates to the sentry how many stubs are waiting + // to receive a context from the queue, and are not doing useful work. + numSpinningThreads uint32 // numThreadsToWakeup is the number of threads requested by Sentry to wake up. // The Sentry increments it and stub threads decrements. numThreadsToWakeup uint32 @@ -53,10 +56,9 @@ type contextQueue struct { // active contexts and contexts that are running in the Sentry. numAwakeContexts uint32 - fastPathDisabledTS uint64 - fastPathFailedInRow uint32 - fastPathDisabled uint32 - ringbuffer [maxContextQueueEntries]uint64 + fastPathDisabled uint32 + usedFastPath uint32 + ringbuffer [maxContextQueueEntries]uint64 } const ( @@ -75,13 +77,13 @@ func (q *contextQueue) init() { idx := ^uint32(0) - maxContextQueueEntries*4 atomic.StoreUint32(&q.start, idx) atomic.StoreUint32(&q.end, idx) - atomic.StoreUint64(&q.fastPathDisabledTS, 0) - atomic.StoreUint32(&q.fastPathFailedInRow, 0) atomic.StoreUint32(&q.numActiveThreads, 0) + atomic.StoreUint32(&q.numSpinningThreads, 0) atomic.StoreUint32(&q.numThreadsToWakeup, 0) atomic.StoreUint32(&q.numActiveContexts, 0) atomic.StoreUint32(&q.numAwakeContexts, 0) - atomic.StoreUint32(&q.fastPathDisabled, 0) + atomic.StoreUint32(&q.fastPathDisabled, 1) + atomic.StoreUint32(&q.usedFastPath, 0) } func (q *contextQueue) isEmpty() bool { @@ -92,8 +94,13 @@ func (q *contextQueue) queuedContexts() uint32 { return (atomic.LoadUint32(&q.end) + maxContextQueueEntries - atomic.LoadUint32(&q.start)) % maxContextQueueEntries } -func (q *contextQueue) add(ctx *sharedContext, stubFastPathEnabled bool) uint32 { - if stubFastPathEnabled { +// add puts the the given ctx onto the context queue, and records a state of +// the subprocess after insertion to see if there are more active stub threads +// or more waiting contexts. +func (q *contextQueue) add(ctx *sharedContext) { + ctx.startWaitingTS = cputicks() + + if fpState.stubFastPath() { q.enableFastPath() } else { q.disableFastPath() @@ -103,14 +110,17 @@ func (q *contextQueue) add(ctx *sharedContext, stubFastPathEnabled bool) uint32 next := atomic.AddUint32(&q.end, 1) if (next % maxContextQueueEntries) == (atomic.LoadUint32(&q.start) % maxContextQueueEntries) { - // should be unreacheable + // should be unreachable panic("contextQueue is full") } idx := next - 1 next = idx % maxContextQueueEntries v := (uint64(idx) << contextQueueIndexShift) + uint64(contextID) atomic.StoreUint64(&q.ringbuffer[next], v) - return next // remove me + + if atomic.SwapUint32(&q.usedFastPath, 0) != 0 { + fpState.usedStubFastPath.Store(true) + } } func (q *contextQueue) disableFastPath() { @@ -120,3 +130,7 @@ func (q *contextQueue) disableFastPath() { func (q *contextQueue) enableFastPath() { atomic.StoreUint32(&q.fastPathDisabled, 0) } + +func (q *contextQueue) fastPathEnabled() bool { + return atomic.LoadUint32(&q.fastPathDisabled) == 0 +} diff --git a/pkg/sentry/platform/systrap/metrics.go b/pkg/sentry/platform/systrap/metrics.go new file mode 100644 index 000000000..f982aee13 --- /dev/null +++ b/pkg/sentry/platform/systrap/metrics.go @@ -0,0 +1,580 @@ +// 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 systrap + +import ( + "time" + + "gvisor.dev/gvisor/pkg/atomicbitops" + "gvisor.dev/gvisor/pkg/hostarch" +) + +// This file contains all logic related to context switch latency metrics. +// +// Latency metrics are the main method by which fastpath for both stub threads +// and the sentry is enabled and disabled. We measure latency in CPU cycles. +// +// The high level overview of metric collection looks like this: +// 1a) When a context is switched from the sentry to the stub, the sentry +// records the time it was put into the context queue. +// 1b) When a stub thread picks up the context from the context queue, the stub +// thread records the time when it's about to switch back to user code. +// Getting the diff between these timestamps gives us the stub-bound latency. +// +// 2a) When a stub thread gives back a context to the sentry for handling, +// it records the time just before notifying the sentry task goroutine. +// 2b) When the task goroutine sees that it has been notified, it records the +// time. +// Getting the diff between these timestamps gives us the sentry-bound latency. +// +// 3) Both latencies are recorded at once via recordLatency(). This means +// there is a delay on getting stubBoundLatencies. In practice this should not +// matter that much due to our relatively large latency measurement periods. +// +// There is a bucket array for each latency type, where each bucket is of size +// `bucketIncrements`. Latencies are collected in time periods of length +// `recordingPeriod`, and measurements for the current period are stored +// in the `latencies` variable. + +type latencyBuckets [numLatencyBuckets]atomicbitops.Uint64 +type cpuTicks uint64 + +const ( + numLatencyBuckets = 80 + bucketIncrements = 2048 + + // minNecessaryRecordings defines the minimum amount of recordings we + // want to see in latencyBuckets in order to get a reasonable median. + minNecessaryRecordings = 5 +) + +// latencyRecorder is used to collect latency metrics. +type latencyRecorder struct { + stubBound latencyBuckets + sentryBound latencyBuckets +} + +// latencies stores the latency counts for the current measurement period. +var latencies latencyRecorder + +// record increments the correct bucket assigned to the given latency l. +// +//go:nosplit +func (b *latencyBuckets) record(l cpuTicks) { + bucket := l / bucketIncrements + if bucket >= numLatencyBuckets { + bucket = numLatencyBuckets - 1 + } + b[bucket].Add(1) +} + +// getMedian returns a latency measure in the range of +// [bucketIncrements, numLatencyBuckets * bucketIncrements], or 0 if unable to +// find a median in the latencyBuckets. +func (b *latencyBuckets) getMedian() cpuTicks { + i := 0 + j := numLatencyBuckets - 1 + var totalForwards, totalBackwards uint64 + for i <= j { + if totalForwards < totalBackwards { + totalForwards += b[i].Load() + i++ + } else { + totalBackwards += b[j].Load() + j-- + } + } + if totalForwards+totalBackwards < minNecessaryRecordings { + return 0 + } + return cpuTicks(max(uint64(i), 1) * bucketIncrements) +} + +// merge combines two latencyBuckets instances. +func (b *latencyBuckets) merge(other *latencyBuckets) { + for i := 0; i < numLatencyBuckets; i++ { + b[i].Add(other[i].Load()) + } +} + +// reset zeroes all buckets. +func (b *latencyBuckets) reset() { + for i := 0; i < numLatencyBuckets; i++ { + b[i].Store(0) + } +} + +// recordLatency records the latency of both the sentry->stub and the +// stub->sentry context switches. +// For the stub->sentry context switch, the final timestamp is taken by this +// function. +// Preconditions: +// - ctx.isAcked() is true. +// +//go:nosplit +func (sc *sharedContext) recordLatency() { + // Record stub->sentry latency. + sentryBoundLatency := sc.getStateChangedTimeDiff() + if sentryBoundLatency != 0 { + latencies.sentryBound.record(sentryBoundLatency) + } + + // Record sentry->stub latency. + stubBoundLatency := sc.getAckedTimeDiff() + if stubBoundLatency != 0 { + latencies.stubBound.record(stubBoundLatency) + } + + updateDebugMetrics(stubBoundLatency, sentryBoundLatency) +} + +// When a measurement period ends, the latencies are used to determine the fast +// path state. Fastpath is independently enabled for both the sentry and stub +// threads, and is modeled as the following state machine: +// +// +----------StubFPOff,SentryFPOff-------+ +// | ^ ^ | +// V | | V +// +-->StubFPOn,SentryFPOff StubFPOff,SentryFPOn<--+ +// | | ^ | ^ | +// | V | V | | +// | StubFPOn,SentryFPOn StubFPOn,SentryFPOn | +// | LastEnabledSentryFP LastEnabledStubFP | +// | | | | +// | | | | +// | +---------> StubFPOn,SentryFPOn <-------+ | +// | | | | +// |______________________________| |___________________________| +// +// The default state is to have both stub and sentry fastpath OFF. +// A state transition to enable one fastpath is done when +// fpState.(stub|sentry)FPBackoff reaches 0. (stub|sentry)FPBackoff is +// decremented every recording period that the corresponding fastpath is +// disabled. +// A state transition to disable one fastpath is decided through the predicates +// shouldDisableStubFP or shouldDisableSentryFP, and activated with +// disableStubFP or disableSentryFP. +// +// Why have 3 states for both FPs being ON? The logic behind that is to do with +// the fact that fastpaths are interdependent. Enabling one fastpath can have +// negative effects on the latency metrics of the other in the event that there +// are not enough CPUs to run the fastpath. So it's very possible that the system +// finds itself in a state where it's beneficial to run one fastpath but not the +// other based on the workload it's doing. For this case, we need to remember +// what the last stable state was to return to, because the metrics will likely +// be bad enough for both sides to be eligible for being disabled. +// +// Once the system establishes that having both the stub and sentry fastpath ON +// is acceptable, it does prioritize disabling stub fastpath over disabling +// sentry fastpath, because the sentry fastpath at most takes one thread to spin. + +const ( + recordingPeriod = 400 * time.Microsecond + fastPathBackoffMin = 2 + maxRecentFPFailures = 9 + numConsecutiveFailsToDisableFP = 2 +) + +// fastPathState is used to keep track of long term metrics that span beyond +// one measurement period. +type fastPathState struct { + // stubBoundBaselineLatency and sentryBoundBaselineLatency record all + // latency measures recorded during periods when their respective + // fastpath was OFF. + stubBoundBaselineLatency latencyBuckets + sentryBoundBaselineLatency latencyBuckets + + // stubFPBackoff and sentryFPBackoff are the periods remaining until + // the system attempts to use the fastpath again. + stubFPBackoff int + sentryFPBackoff int + + // stubFPRecentFailures and sentryFPRecentFailures are counters in the + // range [0, maxRecentFPFailures] that are incremented by + // disable(Stub|Sentry)FP and decremented by (stub|sentry)FPSuccess. + // They are used to set the backoffs. + stubFPRecentFailures int + sentryFPRecentFailures int + + consecutiveStubFPFailures int + consecutiveSentryFPFailures int + + _ [hostarch.CacheLineSize]byte + // stubFastPathEnabled is a global flag referenced in other parts of + // systrap to determine if the stub fast path is enabled or not. + stubFastPathEnabled atomicbitops.Bool + + _ [hostarch.CacheLineSize]byte + // sentryFastPathEnabled is a global flag referenced in other parts of + // systrap to determine if the sentry fastpath is enabled or not. + sentryFastPathEnabled atomicbitops.Bool + + _ [hostarch.CacheLineSize]byte + // nrMaxAwakeStubThreads is the maximum number of awake stub threads over + // all subprocesses at the this moment. + nrMaxAwakeStubThreads atomicbitops.Uint32 + + // usedStubFastPath and usedSentryFastPath are reset every recording + // period, and are populated in case the system actually used the + // fastpath (i.e. stub or dispatcher spun for some time without work). + _ [hostarch.CacheLineSize]byte + usedStubFastPath atomicbitops.Bool + _ [hostarch.CacheLineSize]byte + usedSentryFastPath atomicbitops.Bool + + _ [hostarch.CacheLineSize]byte + // curState is the current fastpath state function, which is called at + // the end of every recording period. + curState func(*fastPathState) +} + +var ( + fpState = fastPathState{ + stubFPBackoff: fastPathBackoffMin, + sentryFPBackoff: fastPathBackoffMin, + curState: sentryOffStubOff, + } + + // fastPathContextLimit is the maximum number of contexts after which the fast + // path in stub threads is disabled. Its value can be higher than the number of + // CPU-s, because the Sentry is running with higher priority than stub threads, + // deepSleepTimeout is much shorter than the Linux scheduler timeslice, so the + // only thing that matters here is whether the Sentry handles syscall faster + // than the overhead of scheduling another stub thread. + fastPathContextLimit = uint32(maxSysmsgThreads * 2) +) + +// controlFastPath is used to spawn a goroutine when creating the Systrap +// platform. +func controlFastPath() { + for { + time.Sleep(recordingPeriod) + + fpState.curState(&fpState) + // Reset FP trackers. + fpState.usedStubFastPath.Store(false) + fpState.usedSentryFastPath.Store(false) + } +} + +// getBackoff returns the number of recording periods that fastpath should remain +// disabled for, based on the num of recentFailures. +func getBackoff(recentFailures int) int { + return 1 << recentFailures +} + +//go:nosplit +func (s *fastPathState) sentryFastPath() bool { + return s.sentryFastPathEnabled.Load() +} + +//go:nosplit +func (s *fastPathState) stubFastPath() bool { + return s.stubFastPathEnabled.Load() && (s.nrMaxAwakeStubThreads.Load() <= fastPathContextLimit) +} + +// enableSentryFP is a wrapper to unconditionally enable sentry FP and increment +// a debug metric. +func (s *fastPathState) enableSentryFP() { + s.sentryFastPathEnabled.Store(true) + numTimesSentryFastPathEnabled.Increment() +} + +// disableSentryFP returns true if the sentry fastpath was able to be disabled. +// +// It takes two calls to disableSentryFP without any calls to sentryFPSuccess in +// between to disable the sentry fastpath. This is done in order to mitigate the +// effects of outlier measures due to rdtsc inaccuracies. +func (s *fastPathState) disableSentryFP() bool { + s.consecutiveSentryFPFailures++ + if s.consecutiveSentryFPFailures < numConsecutiveFailsToDisableFP { + return false + } + s.consecutiveSentryFPFailures = 0 + s.sentryFastPathEnabled.Store(false) + numTimesSentryFastPathDisabled.Increment() + + s.sentryFPBackoff = getBackoff(s.sentryFPRecentFailures) + s.sentryFPRecentFailures = min(maxRecentFPFailures, s.sentryFPRecentFailures+1) + return true +} + +// enableStubFP is a wrapper to unconditionally enable stub FP and increment +// a debug metric. +func (s *fastPathState) enableStubFP() { + s.stubFastPathEnabled.Store(true) + numTimesStubFastPathEnabled.Increment() +} + +// disableStubFP returns true if the stub fastpath was able to be disabled. +// +// It takes two calls to disableStubFP without any calls to stubFPSuccess in +// between to disable the stub fastpath. This is done in order to mitigate the +// effects of outlier measures due to rdtsc inaccuracies. +func (s *fastPathState) disableStubFP() bool { + s.consecutiveStubFPFailures++ + if s.consecutiveStubFPFailures < numConsecutiveFailsToDisableFP { + return false + } + s.consecutiveStubFPFailures = 0 + s.stubFastPathEnabled.Store(false) + numTimesStubFastPathDisabled.Increment() + + s.stubFPBackoff = getBackoff(s.stubFPRecentFailures) + s.stubFPRecentFailures = min(maxRecentFPFailures, s.stubFPRecentFailures+1) + return true +} + +func (s *fastPathState) sentryFPSuccess() { + s.sentryFPRecentFailures = max(0, s.sentryFPRecentFailures-1) + s.consecutiveSentryFPFailures = 0 +} + +func (s *fastPathState) stubFPSuccess() { + s.stubFPRecentFailures = max(0, s.stubFPRecentFailures-1) + s.consecutiveStubFPFailures = 0 +} + +// shouldDisableSentryFP returns true if the metrics indicate sentry fastpath +// should be disabled. +func (s *fastPathState) shouldDisableSentryFP(stubMedian, sentryMedian cpuTicks) bool { + if !s.usedSentryFastPath.Load() { + return false + } + stubBaseline := s.stubBoundBaselineLatency.getMedian() + sentryBaseline := s.sentryBoundBaselineLatency.getMedian() + if sentryMedian < sentryBaseline { + // Assume the number of productive stubs is the core count on the + // system, not counting the 1 core taken by the dispatcher for + // the fast path. + n := cpuTicks(maxSysmsgThreads - 1) + // If the sentry fastpath is causing the stub latency to be + // higher than normal, the point at which it's considered to be + // too high is when the time saved via the sentry fastpath is + // less than the time lost via higher stub latency (with some + // error margin). Assume that all possible stub threads are + // active for this comparison. + diff := (sentryBaseline - sentryMedian) * n + errorMargin := stubBaseline / 8 + return (stubMedian > stubBaseline) && (stubMedian-stubBaseline) > (diff+errorMargin) + } + // Running the fastpath resulted in higher sentry latency than baseline? + // This does not happen often, but it is an indication that the fastpath + // wasn't used to full effect: for example the dispatcher kept changing, + // and that there was not enough CPU to place a new dispatcher fast + // enough. + // + // If there isn't enough CPU we will most likely see large stub latency + // regressions, and should disable the fastpath. + return stubMedian > (stubBaseline + stubBaseline/2) +} + +// shouldDisableStubFP returns true if the metrics indicate stub fastpath should +// be disabled. +func (s *fastPathState) shouldDisableStubFP(stubMedian, sentryMedian cpuTicks) bool { + if !s.usedStubFastPath.Load() { + return false + } + stubBaseline := s.stubBoundBaselineLatency.getMedian() + sentryBaseline := s.sentryBoundBaselineLatency.getMedian() + if stubMedian < stubBaseline { + // If the stub fastpath is causing the sentry latency to be + // higher than normal, the point at which it's considered to be + // too high is when the time saved via the stub fastpath is + // less than the time lost via higher sentry latency (with some + // error margin). Unlike the stub latency, the sentry latency is + // largely dependent on one thread (the dispatcher). + diff := stubBaseline - stubMedian + errorMargin := sentryBaseline / 8 + return (sentryMedian > sentryBaseline) && (sentryMedian-sentryBaseline) > (diff+errorMargin) + } + // Running the fastpath resulted in higher stub latency than baseline? + // This is either an indication that there isn't enough CPU to schedule + // stub threads to run the fastpath, or the user workload has changed to + // be such that it returns less often to the sentry. + // + // If there isn't enough CPU we will most likely see large sentry latency + // regressions, and should disable the fastpath. + return sentryMedian > (sentryBaseline + sentryBaseline/2) +} + +// The following functions are used for state transitions in the sentry/stub +// fastpath state machine described above. + +func sentryOffStubOff(s *fastPathState) { + periodStubBoundMedian := latencies.stubBound.getMedian() + s.stubBoundBaselineLatency.merge(&latencies.stubBound) + latencies.stubBound.reset() + if periodStubBoundMedian != 0 { + s.stubFPBackoff = max(s.stubFPBackoff-1, 0) + } + + periodSentryBoundMedian := latencies.sentryBound.getMedian() + s.sentryBoundBaselineLatency.merge(&latencies.sentryBound) + latencies.sentryBound.reset() + if periodSentryBoundMedian != 0 { + s.sentryFPBackoff = max(s.sentryFPBackoff-1, 0) + } + + if s.sentryFPBackoff == 0 { + s.enableSentryFP() + s.curState = sentryOnStubOff + } else if s.stubFPBackoff == 0 { + s.enableStubFP() + s.curState = sentryOffStubOn + } +} + +func sentryOnStubOff(s *fastPathState) { + periodStubBoundMedian := latencies.stubBound.getMedian() + periodSentryBoundMedian := latencies.sentryBound.getMedian() + if periodStubBoundMedian == 0 || periodSentryBoundMedian == 0 { + return + } + + if s.shouldDisableSentryFP(periodStubBoundMedian, periodSentryBoundMedian) { + if s.disableSentryFP() { + s.curState = sentryOffStubOff + } + } else { + s.sentryFPSuccess() + // If we are going to keep sentry FP on that means stub latency + // was fine; update the baseline. + s.stubBoundBaselineLatency.merge(&latencies.stubBound) + latencies.stubBound.reset() + s.stubFPBackoff = max(s.stubFPBackoff-1, 0) + if s.stubFPBackoff == 0 { + s.enableStubFP() + s.curState = sentryOnStubOnLastEnabledStub + } + } + latencies.sentryBound.reset() +} + +func sentryOffStubOn(s *fastPathState) { + periodStubBoundMedian := latencies.stubBound.getMedian() + periodSentryBoundMedian := latencies.sentryBound.getMedian() + if periodStubBoundMedian == 0 || periodSentryBoundMedian == 0 { + return + } + + if s.shouldDisableStubFP(periodStubBoundMedian, periodSentryBoundMedian) { + if s.disableStubFP() { + s.curState = sentryOffStubOff + } + } else { + s.stubFPSuccess() + + s.sentryBoundBaselineLatency.merge(&latencies.sentryBound) + latencies.sentryBound.reset() + s.sentryFPBackoff = max(s.sentryFPBackoff-1, 0) + if s.sentryFPBackoff == 0 { + s.enableSentryFP() + s.curState = sentryOnStubOnLastEnabledSentry + } + } + latencies.stubBound.reset() +} + +func sentryOnStubOnLastEnabledSentry(s *fastPathState) { + periodStubBoundMedian := latencies.stubBound.getMedian() + periodSentryBoundMedian := latencies.sentryBound.getMedian() + if periodStubBoundMedian == 0 || periodSentryBoundMedian == 0 { + return + } + + latencies.stubBound.reset() + latencies.sentryBound.reset() + + if s.shouldDisableSentryFP(periodStubBoundMedian, periodSentryBoundMedian) { + if s.disableSentryFP() { + s.curState = sentryOffStubOn + } + } else { + s.curState = sentryOnStubOn + s.sentryFPSuccess() + s.stubFPSuccess() + } +} + +func sentryOnStubOnLastEnabledStub(s *fastPathState) { + periodStubBoundMedian := latencies.stubBound.getMedian() + periodSentryBoundMedian := latencies.sentryBound.getMedian() + if periodStubBoundMedian == 0 || periodSentryBoundMedian == 0 { + return + } + + latencies.stubBound.reset() + latencies.sentryBound.reset() + + if s.shouldDisableStubFP(periodStubBoundMedian, periodSentryBoundMedian) { + if s.disableStubFP() { + s.curState = sentryOnStubOff + } + } else { + s.curState = sentryOnStubOn + s.sentryFPSuccess() + s.stubFPSuccess() + } +} + +func sentryOnStubOn(s *fastPathState) { + periodStubBoundMedian := latencies.stubBound.getMedian() + periodSentryBoundMedian := latencies.sentryBound.getMedian() + if periodStubBoundMedian == 0 || periodSentryBoundMedian == 0 { + return + } + + latencies.stubBound.reset() + latencies.sentryBound.reset() + + // Prioritize disabling stub fastpath over sentry fastpath, since sentry + // only spins with one thread. + if s.shouldDisableStubFP(periodStubBoundMedian, periodSentryBoundMedian) { + if s.disableStubFP() { + s.curState = sentryOnStubOff + } + } else if s.shouldDisableSentryFP(latencies.stubBound.getMedian(), latencies.sentryBound.getMedian()) { + if s.disableSentryFP() { + s.curState = sentryOffStubOn + } + } else { + s.sentryFPSuccess() + s.stubFPSuccess() + } +} + +// Profiling metrics intended for debugging purposes. +var ( + numTimesSentryFastPathDisabled = SystrapProfiling.MustCreateNewUint64Metric("/systrap/numTimesSentryFastPathDisabled", false, "") + numTimesSentryFastPathEnabled = SystrapProfiling.MustCreateNewUint64Metric("/systrap/numTimesSentryFastPathEnabled", false, "") + numTimesStubFastPathDisabled = SystrapProfiling.MustCreateNewUint64Metric("/systrap/numTimesStubFastPathDisabled", false, "") + numTimesStubFastPathEnabled = SystrapProfiling.MustCreateNewUint64Metric("/systrap/numTimesStubFastPathEnabled", false, "") + numTimesStubKicked = SystrapProfiling.MustCreateNewUint64Metric("/systrap/numTimesStubKicked", false, "") + + stubLatWithin1kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/stubLatWithin1kUS", false, "") + stubLatWithin5kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/stubLatWithin5kUS", false, "") + stubLatWithin10kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/stubLatWithin10kUS", false, "") + stubLatWithin20kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/stubLatWithin20kUS", false, "") + stubLatWithin40kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/stubLatWithin40kUS", false, "") + stubLatGreater40kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/stubLatGreater40kUS", false, "") + + sentryLatWithin1kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/sentryLatWithin1kUS", false, "") + sentryLatWithin5kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/sentryLatWithin5kUS", false, "") + sentryLatWithin10kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/sentryLatWithin10kUS", false, "") + sentryLatWithin20kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/sentryLatWithin20kUS", false, "") + sentryLatWithin40kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/sentryLatWithin40kUS", false, "") + sentryLatGreater40kUS = SystrapProfiling.MustCreateNewUint64Metric("/systrap/sentryLatGreater40kUS", false, "") +) diff --git a/pkg/sentry/platform/systrap/shared_context.go b/pkg/sentry/platform/systrap/shared_context.go index 8cc97db96..0c37ceb04 100644 --- a/pkg/sentry/platform/systrap/shared_context.go +++ b/pkg/sentry/platform/systrap/shared_context.go @@ -16,7 +16,6 @@ package systrap import ( "fmt" - "runtime" "strconv" "sync" "sync/atomic" @@ -30,7 +29,8 @@ import ( ) const ( - ackReset uint32 = 0 + ackReset uint64 = 0 + stateChangedReset uint64 = 0 ) // sharedContext is an abstraction for interactions that the sentry has to @@ -108,7 +108,6 @@ func (sc *sharedContext) release() { } if !sc.sleeping { sc.subprocess.decAwakeContexts() - } sc.subprocess.threadContextPool.Put(uint64(sc.contextID)) sc.subprocess.DecRef(sc.subprocess.release) @@ -183,11 +182,40 @@ func (sc *sharedContext) disableSentryFastPath() { } func (sc *sharedContext) isAcked() bool { - return atomic.LoadUint32(&sc.shared.Acked) != ackReset + return atomic.LoadUint64(&sc.shared.AckedTime) != ackReset } -func (sc *sharedContext) resetAcked() { - atomic.StoreUint32(&sc.shared.Acked, ackReset) +// getAckedTimeDiff returns the time difference between when this context was +// put into the context queue, and when this context was acked by a stub thread. +// Precondition: must be called after isAcked() == true. +// +//go:nosplit +func (sc *sharedContext) getAckedTimeDiff() cpuTicks { + ackedAt := atomic.LoadUint64(&sc.shared.AckedTime) + if ackedAt < uint64(sc.startWaitingTS) { + log.Warningf("likely memory tampering detected: found a condition where ackedAt (%d) < startWaitingTS (%d)", ackedAt, uint64(sc.startWaitingTS)) + return 0 + } + return cpuTicks(ackedAt - uint64(sc.startWaitingTS)) +} + +// getStateChangedTimeDiff returns the time difference between the time the +// context state got changed by a stub thread, and now. +// +//go:nosplit +func (sc *sharedContext) getStateChangedTimeDiff() cpuTicks { + changedAt := atomic.LoadUint64(&sc.shared.StateChangedTime) + now := uint64(cputicks()) + if now < changedAt { + log.Warningf("likely memory tampering detected: found a condition where now (%d) < changedAt (%d)", now, changedAt) + return 0 + } + return cpuTicks(now - changedAt) +} + +func (sc *sharedContext) resetLatencyMeasures() { + atomic.StoreUint64(&sc.shared.AckedTime, ackReset) + atomic.StoreUint64(&sc.shared.StateChangedTime, stateChangedReset) } const ( @@ -243,60 +271,23 @@ type fastPathDispatcher struct { // entrants contains new contexts that haven't been added to `list` yet. // +checklocks:mu entrants contextList - - // fastPathDisabledTS is the time stamp when the stub fast path was - // disabled. It is zero if the fast path is enabled. - fastPathDisabledTS atomic.Uint64 } var dispatcher fastPathDispatcher -// fastPathContextLimit is the maximum number of contexts after which the fast -// path in stub threads is disabled. Its value can be higher than the number of -// CPU-s, because the Sentry is running with higher priority than stub threads, -// deepSleepTimeout is much shorter than the Linux scheduler timeslice, so the -// only thing that matters here is whether the Sentry handles syscall faster -// than the overhead of scheduling another stub thread. -var fastPathContextLimit = uint32(runtime.GOMAXPROCS(0) * 2) - -// fastPathDisabledTimeout is the timeout after which the fast path in stub -// processes will be re-enabled. -const fastPathDisabledTimeout = uint64(200 * 1000 * 1000) // 100ms for 2GHz. - -// nrMaxAwakeStubThreads is the maximum number of awake stub threads over all -// subprocesses at the this moment. -var nrMaxAwakeStubThreads atomic.Uint32 - -// stubFastPathEnabled returns true if the fast path in stub processes is -// enabled. If the fast path is disabled, it revises whether it has to be -// re-enabled or not. -func (q *fastPathDispatcher) stubFastPathEnabled() bool { - ts := q.fastPathDisabledTS.Load() - if ts != 0 { - if uint64(cputicks())-ts < fastPathDisabledTimeout { - return false - } - if nrMaxAwakeStubThreads.Load() > fastPathContextLimit { - q.fastPathDisabledTS.Store(uint64(cputicks())) - return false - } - q.fastPathDisabledTS.Store(0) - } - return true -} - -// disableStubFastPath disables the fast path over all subprocesses with active -// contexts. -func (q *fastPathDispatcher) disableStubFastPath() { - q.fastPathDisabledTS.Store(uint64(cputicks())) -} - -// deep_sleep_timeout is the timeout after which we stops polling and fall asleep. -// -// The value is 40µs for 2GHz CPU. This timeout matches the sentry<->stub round -// trip in the pure deep sleep case. -const deepSleepTimeout = uint64(80000) -const handshakeTimeout = uint64(1000) +const ( + // deepSleepTimeout is the timeout after which both stub threads and the + // dispatcher consider whether to stop polling. They need to have elapsed + // this timeout twice in a row in order to stop, so the actual timeout + // can be considered to be (deepSleepTimeout*2). Falling asleep after two + // shorter timeouts instead of one long timeout is done in order to + // mitigate the effects of rdtsc inaccuracies. + // + // The value is 20µs for 2GHz CPU. 40µs matches the sentry<->stub + // round trip in the pure deep sleep case. + deepSleepTimeout = uint64(40000) + handshakeTimeout = uint64(1000) +) // loop is processing contexts in the queue. Only one instance of it can be // running, because it has exclusive access to the list. @@ -305,16 +296,13 @@ const handshakeTimeout = uint64(1000) func (q *fastPathDispatcher) loop(target *sharedContext) { done := false processed := 0 + firstTimeout := false slowPath := false - start := cputicks() + startedSpinning := cputicks() for { var ctx, next *sharedContext q.mu.Lock() - if processed != 0 || !q.entrants.Empty() { - start = cputicks() - slowPath = false - } q.nr -= processed // Add new contexts to the list. q.list.PushBackList(&q.entrants) @@ -329,6 +317,7 @@ func (q *fastPathDispatcher) loop(target *sharedContext) { break } + slowPath = !fpState.sentryFastPath() || slowPath processed = 0 now := cputicks() for ctx = q.list.Front(); ctx != nil; ctx = next { @@ -355,20 +344,26 @@ func (q *fastPathDispatcher) loop(target *sharedContext) { } ctx.sync.Receiver().Notify(event) } - if processed == 0 { - if uint64(cputicks()-start) > deepSleepTimeout { - slowPath = true - // Do one more run to notify all contexts. - // q.list has to be empty at the end. - continue - } - yield() + + if processed != 0 { + startedSpinning = now + firstTimeout = false + } else { + fpState.usedSentryFastPath.Store(true) } + // If dispatcher has been spinning for too long, send this + // dispatcher to sleep. + if uint64(now-startedSpinning) > deepSleepTimeout { + slowPath = firstTimeout + firstTimeout = true + } + + yield() } } func (q *fastPathDispatcher) waitFor(ctx *sharedContext) syncevent.Set { - events := syncevent.Set(0) + events := syncevent.NoEvents q.mu.Lock() q.entrants.PushBack(ctx) diff --git a/pkg/sentry/platform/systrap/subprocess.go b/pkg/sentry/platform/systrap/subprocess.go index 2cafc36d6..4dab9e8fc 100644 --- a/pkg/sentry/platform/systrap/subprocess.go +++ b/pkg/sentry/platform/systrap/subprocess.go @@ -701,10 +701,7 @@ func (s *subprocess) incAwakeContexts() { if nr > uint32(maxSysmsgThreads) { return } - nr = nrMaxAwakeStubThreads.Add(1) - if nr > fastPathContextLimit { - dispatcher.disableStubFastPath() - } + fpState.nrMaxAwakeStubThreads.Add(1) } func (s *subprocess) decAwakeContexts() { @@ -712,7 +709,7 @@ func (s *subprocess) decAwakeContexts() { if nr >= uint32(maxSysmsgThreads) { return } - nrMaxAwakeStubThreads.Add(^uint32(0)) + fpState.nrMaxAwakeStubThreads.Add(^uint32(0)) } // switchToApp is called from the main SwitchToApp entrypoint. @@ -747,10 +744,9 @@ func (s *subprocess) switchToApp(c *context, ac *arch.Context64) (isSyscall bool ctx.sleeping = false s.incAwakeContexts() } - stubFastPathEnabled := dispatcher.stubFastPathEnabled() ctx.setState(sysmsg.ContextStateNone) - s.contextQueue.add(ctx, stubFastPathEnabled) - s.waitOnState(ctx, stubFastPathEnabled) + s.contextQueue.add(ctx) + s.waitOnState(ctx) // Check if there's been an error. threadID := ctx.threadID() @@ -789,12 +785,10 @@ func (s *subprocess) switchToApp(c *context, ac *arch.Context64) (isSyscall bool return false, false, nil } -func (s *subprocess) waitOnState(ctx *sharedContext, stubFastPathEnabled bool) { +func (s *subprocess) waitOnState(ctx *sharedContext) { ctx.kicked = false slowPath := false - start := cputicks() - ctx.startWaitingTS = start - if !stubFastPathEnabled || atomic.LoadUint32(&s.contextQueue.numActiveThreads) == 0 { + if !s.contextQueue.fastPathEnabled() || atomic.LoadUint32(&s.contextQueue.numActiveThreads) == 0 { ctx.kicked = s.kickSysmsgThread() } for curState := ctx.state(); curState == sysmsg.ContextStateNone; curState = ctx.state() { @@ -828,7 +822,8 @@ func (s *subprocess) waitOnState(ctx *sharedContext, stubFastPathEnabled bool) { } } - ctx.resetAcked() + ctx.recordLatency() + ctx.resetLatencyMeasures() ctx.enableSentryFastPath() } @@ -857,6 +852,8 @@ func (s *subprocess) canKickSysmsgThread() (bool, uint32) { return true, nrActiveThreads } +// kickSysmsgThread returns true if it was able to wake up or create a new sysmsg +// stub thread. func (s *subprocess) kickSysmsgThread() bool { kick, _ := s.canKickSysmsgThread() if !kick { @@ -869,6 +866,7 @@ func (s *subprocess) kickSysmsgThread() bool { s.sysmsgThreadsMu.Unlock() return false } + numTimesStubKicked.Increment() atomic.AddUint32(&s.contextQueue.numThreadsToWakeup, 1) if s.numSysmsgThreads < maxSysmsgThreads && s.numSysmsgThreads < int(nrThreads) { s.numSysmsgThreads++ @@ -884,7 +882,7 @@ func (s *subprocess) kickSysmsgThread() bool { } s.contextQueue.wakeupSysmsgThread() - return false + return true } // syscall executes the given system call without handling interruptions. diff --git a/pkg/sentry/platform/systrap/sysmsg/sysmsg.go b/pkg/sentry/platform/systrap/sysmsg/sysmsg.go index cd6853b60..dd061d7c8 100644 --- a/pkg/sentry/platform/systrap/sysmsg/sysmsg.go +++ b/pkg/sentry/platform/systrap/sysmsg/sysmsg.go @@ -250,9 +250,15 @@ type ThreadContext struct { // goroutine used for this thread context is busy-polling for a response // instead of using FUTEX_WAIT. SentryFastPath uint32 - // Acked is used by sysmsg threads to signal to the sentry that this context + // AckedTime is used by sysmsg threads to signal to the sentry that this context // has been picked up from the context queue and is actively being worked on. - Acked uint32 + // The stub thread puts down the timestamp at which it has started processing + // this context. + AckedTime uint64 + // StateChangedTime is the time when the ThreadContext.State changed, as + // recorded by the stub thread when it gave it back to the sentry + // (the sentry does not populate this field except to reset it). + StateChangedTime uint64 // TLS is a pointer to a thread local storage. // It is is only populated on ARM64. TLS uint64 @@ -300,7 +306,7 @@ func (c *ThreadContext) String() string { fmt.Fprintf(&b, " FPStateChanged %d Regs %+v", c.FPStateChanged, c.Regs) fmt.Fprintf(&b, " Interrupt %d", c.Interrupt) fmt.Fprintf(&b, " ThreadID %d LastThreadID %d", c.ThreadID, c.LastThreadID) - fmt.Fprintf(&b, " SentryFastPath %d Acked %d", c.SentryFastPath, c.Acked) + fmt.Fprintf(&b, " SentryFastPath %d Acked %d", c.SentryFastPath, c.AckedTime) fmt.Fprintf(&b, " signo: %d, siginfo: %+v", c.Signo, c.SignalInfo) fmt.Fprintf(&b, " debug %d", atomic.LoadUint64(&c.Debug)) b.WriteString("}") diff --git a/pkg/sentry/platform/systrap/sysmsg/sysmsg.h b/pkg/sentry/platform/systrap/sysmsg/sysmsg.h index cce2a5a81..bcce52c5f 100644 --- a/pkg/sentry/platform/systrap/sysmsg/sysmsg.h +++ b/pkg/sentry/platform/systrap/sysmsg/sysmsg.h @@ -93,7 +93,8 @@ struct thread_context { uint32_t thread_id; uint32_t last_thread_id; uint32_t sentry_fast_path; - uint32_t acked; + uint64_t acked_time; + uint64_t state_changed_time; uint64_t tls; uint64_t debug; }; diff --git a/pkg/sentry/platform/systrap/sysmsg/sysmsg_lib.c b/pkg/sentry/platform/systrap/sysmsg/sysmsg_lib.c index 65fbbb272..69fc85f9d 100644 --- a/pkg/sentry/platform/systrap/sysmsg/sysmsg_lib.c +++ b/pkg/sentry/platform/systrap/sysmsg/sysmsg_lib.c @@ -45,12 +45,12 @@ struct context_queue { uint32_t start; uint32_t end; uint32_t num_active_threads; + uint32_t num_spinning_threads; uint32_t num_threads_to_wakeup; uint32_t num_active_contexts; uint32_t num_awake_contexts; - uint64_t fast_path_disalbed_ts; - uint32_t fast_path_failed_in_row; uint32_t fast_path_disabled; + uint32_t used_fast_path; uint64_t ringbuffer[MAX_CONTEXT_QUEUE_ENTRIES]; }; @@ -113,22 +113,33 @@ void memcpy(uint8_t *dest, uint8_t *src, size_t n) { // MAX_SPINNING_THREADS is half of SPINNING_QUEUE_SIZE to be sure that the tail // doesn't catch the head. More details are in spinning_queue_remove_first. #define MAX_SPINNING_THREADS (SPINNING_QUEUE_SIZE / 2) + +// MAX_RE_ENQUEUE defines the amount of time a given entry in the spinning queue +// needs to reach timeout in order to be removed. Re-enqueuing a timeout is done +// in order to mitigate rdtsc inaccuracies. +#define MAX_RE_ENQUEUE 2 + struct spinning_queue { uint32_t start; uint32_t end; uint64_t start_times[SPINNING_QUEUE_SIZE]; + uint8_t num_times_re_enqueued[SPINNING_QUEUE_SIZE]; }; struct spinning_queue *__export_spinning_queue_addr; // spinning_queue_push adds a new thread to the queue. It returns false if the -// queue if full. -static bool spinning_queue_push() __attribute__((warn_unused_result)); -static bool spinning_queue_push(void) { +// queue is full, or if re_enqueue_times has reached MAX_RE_ENQUEUE. +static bool spinning_queue_push(uint8_t re_enqueue_times) + __attribute__((warn_unused_result)); +static bool spinning_queue_push(uint8_t re_enqueue_times) { struct spinning_queue *queue = __export_spinning_queue_addr; uint32_t idx, start, end; BUILD_BUG_ON(sizeof(struct spinning_queue) > SPINNING_QUEUE_MEM_SIZE); + if (re_enqueue_times >= MAX_RE_ENQUEUE) { + return false; + } end = atomic_add(&queue->end, 1); start = atomic_load(&queue->start); @@ -138,12 +149,15 @@ static bool spinning_queue_push(void) { } idx = end - 1; + atomic_store(&queue->num_times_re_enqueued[idx % SPINNING_QUEUE_SIZE], + re_enqueue_times); atomic_store(&queue->start_times[idx % SPINNING_QUEUE_SIZE], rdtsc()); return true; } // spinning_queue_pop() removes one thread from a queue that has been spinning // the shortest time. +// However it doesn't take into account the spinning re-enqueue. static void spinning_queue_pop() { struct spinning_queue *queue = __export_spinning_queue_addr; @@ -162,6 +176,7 @@ static bool spinning_queue_remove_first(uint64_t timeout) { struct spinning_queue *queue = __export_spinning_queue_addr; uint64_t ts; uint32_t idx; + uint8_t re_enqueue = 0; while (1) { idx = atomic_load(&queue->start); @@ -173,12 +188,15 @@ static bool spinning_queue_remove_first(uint64_t timeout) { // twice of the maximum number of threads, so we can zero the element and be // sure that nobody is trying to set it in a non-zero value. atomic_store(&queue->start_times[idx % SPINNING_QUEUE_SIZE], 0); + re_enqueue = + atomic_load(&queue->num_times_re_enqueued[idx % SPINNING_QUEUE_SIZE]); if (atomic_compare_exchange(&queue->start, &idx, idx + 1)) { break; } } - return true; + if (timeout == 0) return true; + return !spinning_queue_push(re_enqueue + 1); } struct thread_context *queue_get_context(struct sysmsg *sysmsg) { @@ -210,30 +228,27 @@ struct thread_context *queue_get_context(struct sysmsg *sysmsg) { } struct thread_context *ctx = thread_context_addr(context_id); sysmsg->context = ctx; - atomic_store(&ctx->acked, 1); + atomic_store(&ctx->acked_time, rdtsc()); atomic_store(&ctx->thread_id, sysmsg->thread_id); return ctx; } return NULL; } -#define FAILED_FAST_PATH_LIMIT 5 -#define FAILED_FAST_PATH_TIMEOUT 20000000 // 10ms - // get_context_fast sets nr_active_threads_p only if it deactivates the thread. static struct thread_context *get_context_fast(struct sysmsg *sysmsg, struct context_queue *queue, uint32_t *nr_active_threads_p) { uint32_t nr_active_threads, nr_awake_contexts; - if (!spinning_queue_push()) return NULL; + if (!spinning_queue_push(0)) return NULL; + atomic_store(&queue->used_fast_path, 1); while (1) { struct thread_context *ctx; ctx = queue_get_context(sysmsg); if (ctx) { - atomic_store(&queue->fast_path_failed_in_row, 0); spinning_queue_pop(); return ctx; } @@ -257,10 +272,6 @@ static struct thread_context *get_context_fast(struct sysmsg *sysmsg, } if (spinning_queue_remove_first(__export_deep_sleep_timeout)) { - uint32_t nr = atomic_add(&queue->fast_path_failed_in_row, 1); - if (nr >= FAILED_FAST_PATH_LIMIT) { - atomic_store(&queue->fast_path_disalbed_ts, rdtsc()); - } break; } spinloop(); @@ -295,41 +306,29 @@ struct thread_context *get_context(struct sysmsg *sysmsg) { struct context_queue *queue = __export_context_queue_addr; uint32_t nr_active_threads; + struct thread_context *ctx; for (;;) { - struct thread_context *ctx; + atomic_add(&queue->num_spinning_threads, 1); // Change sysmsg thread state just to indicate thread is not asleep. atomic_store(&sysmsg->state, THREAD_STATE_PREP); ctx = queue_get_context(sysmsg); if (ctx) { - atomic_store(&queue->fast_path_failed_in_row, 0); - return ctx; + goto exit; } - uint64_t slow_path_ts = atomic_load(&queue->fast_path_disalbed_ts); - bool fast_path_enabled = true; - - if (!slow_path_ts) { - if (rdtsc() - slow_path_ts > FAILED_FAST_PATH_TIMEOUT) { - atomic_store(&queue->fast_path_failed_in_row, 0); - atomic_store(&queue->fast_path_disalbed_ts, 0); - } else { - fast_path_enabled = false; - } - } - if (atomic_load(&queue->fast_path_disabled) != 0) { - fast_path_enabled = false; - } + bool fast_path_enabled = atomic_load(&queue->fast_path_disabled) == 0; nr_active_threads = NR_IF_THREAD_IS_ACTIVE; if (fast_path_enabled) { ctx = get_context_fast(sysmsg, queue, &nr_active_threads); - if (ctx) return ctx; + if (ctx) goto exit; } if (nr_active_threads == NR_IF_THREAD_IS_ACTIVE) { nr_active_threads = atomic_sub(&queue->num_active_threads, 1); } + atomic_sub(&queue->num_spinning_threads, 1); atomic_store(&sysmsg->state, THREAD_STATE_ASLEEP); uint32_t nr_active_contexts = atomic_load(&queue->num_active_contexts); // We have to make another attempt to get a context here to prevent TOCTTOU @@ -360,6 +359,9 @@ struct thread_context *get_context(struct sysmsg *sysmsg) { } } } +exit: + atomic_sub(&queue->num_spinning_threads, 1); + return ctx; } // switch_context signals the sentry that the old context is ready to be worked @@ -373,6 +375,7 @@ struct thread_context *switch_context(struct sysmsg *sysmsg, atomic_sub(&queue->num_active_contexts, 1); atomic_store(&ctx->thread_id, INVALID_THREAD_ID); atomic_store(&ctx->last_thread_id, sysmsg->thread_id); + atomic_store(&ctx->state_changed_time, rdtsc()); atomic_store(&ctx->state, new_context_state); if (atomic_load(&ctx->sentry_fast_path) == 0) { int ret = sys_futex(&ctx->state, FUTEX_WAKE, 1, NULL, NULL, 0); diff --git a/pkg/sentry/platform/systrap/systrap.go b/pkg/sentry/platform/systrap/systrap.go index 261ed4e86..e5869845c 100644 --- a/pkg/sentry/platform/systrap/systrap.go +++ b/pkg/sentry/platform/systrap/systrap.go @@ -102,6 +102,10 @@ var ( // stubInitialized controls one-time stub initialization. stubInitialized sync.Once + // latencyMonitoring controls one-time initialization of the fastpath + // control goroutine. + latencyMonitoring sync.Once + // archState stores architecture-specific details used in the platform. archState sysmsg.ArchState ) @@ -337,6 +341,10 @@ func New() (*Systrap, error) { initSysmsgThreadPriority() }) + latencyMonitoring.Do(func() { + go controlFastPath() + }) + return &Systrap{memoryFile: mf}, nil } diff --git a/pkg/sentry/platform/systrap/systrap_profiling.go b/pkg/sentry/platform/systrap/systrap_profiling.go new file mode 100644 index 000000000..42760aba4 --- /dev/null +++ b/pkg/sentry/platform/systrap/systrap_profiling.go @@ -0,0 +1,60 @@ +// 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. + +//go:build systrap_profiling +// +build systrap_profiling + +package systrap + +import ( + "gvisor.dev/gvisor/pkg/metric" +) + +// SystrapProfiling is a builder that produces conditionally compiled metrics. +// Metrics made from this are compiled and active at runtime when the +// "systrap_profiling" go-tag is specified at compilation. +var SystrapProfiling = metric.RealMetricBuilder{} + +//go:nosplit +func updateDebugMetrics(stubBoundLat, sentryBoundLat cpuTicks) { + if stubBoundLat == 0 { + } else if stubBoundLat < 2000 { + stubLatWithin1kUS.Increment() + } else if stubBoundLat < 10000 { + stubLatWithin5kUS.Increment() + } else if stubBoundLat < 20000 { + stubLatWithin10kUS.Increment() + } else if stubBoundLat < 40000 { + stubLatWithin20kUS.Increment() + } else if stubBoundLat < 80000 { + stubLatWithin40kUS.Increment() + } else { + stubLatGreater40kUS.Increment() + } + + if sentryBoundLat == 0 { + } else if sentryBoundLat < 2000 { + sentryLatWithin1kUS.Increment() + } else if sentryBoundLat < 10000 { + sentryLatWithin5kUS.Increment() + } else if sentryBoundLat < 20000 { + sentryLatWithin10kUS.Increment() + } else if sentryBoundLat < 40000 { + sentryLatWithin20kUS.Increment() + } else if sentryBoundLat < 80000 { + sentryLatWithin40kUS.Increment() + } else { + sentryLatGreater40kUS.Increment() + } +} diff --git a/pkg/sentry/platform/systrap/systrap_profiling_fake.go b/pkg/sentry/platform/systrap/systrap_profiling_fake.go new file mode 100644 index 000000000..c2b5617a6 --- /dev/null +++ b/pkg/sentry/platform/systrap/systrap_profiling_fake.go @@ -0,0 +1,30 @@ +// 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. + +//go:build !systrap_profiling +// +build !systrap_profiling + +package systrap + +import ( + "gvisor.dev/gvisor/pkg/metric" +) + +// SystrapProfiling is a builder that produces conditionally compiled metrics. +// Metrics made from this are compiled and active at runtime when the +// "systrap_profiling" go-tag is specified at compilation. +var SystrapProfiling = metric.FakeMetricBuilder{} + +//go:nosplit +func updateDebugMetrics(stubBoundLat, sentryBoundLat cpuTicks) {}