Skip to content

Commit 10111a0

Browse files
craig[bot]iskettaneh
andcommitted
Merge #158474
158474: schedulerlatency: Increase the go scheduler latency metric time coverage r=iskettaneh a=iskettaneh Before this commit, the go scheduler latency metric was publish once every 10 seconds, and it was based on 2.5 seconds worth of data. That meant that there was 75% blind spot in that metric. This is especially important for short-lived overload that might not have been detected with this metric. This commit builds on the current interval at which we measure the scheduler latency (100ms), and keeps adding these 100ms measurements into a histogram that gets published (and cleared) every 10s. The figure below shows the Before/After metric on 2 clusters with the old and the new metric when running the following command: `while true; do timeout 3.5 roachprod run $CLUSTER:4 -- './cockroach workload run kv --concurrency=256 --read-percent=95 --duration=120m {pgurl:1}'; sleep 57.5; done` <img width="1920" height="1440" alt="schedLatencyBefAft" src="https://github.com/user-attachments/assets/608994df-6f19-4e0c-ab36-a88f31caacec" /> You can see that in the Before figure, many of these spikes are missed. While they are visible in the new metric. Release note: None Fixes: #158475 Co-authored-by: iskettaneh <173953022+iskettaneh@users.noreply.github.com>
2 parents 4f6dd5c + a7f78bc commit 10111a0

File tree

1 file changed

+40
-11
lines changed

1 file changed

+40
-11
lines changed

pkg/util/schedulerlatency/sampler.go

Lines changed: 40 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -98,12 +98,11 @@ func StartSampler(
9898
case <-stopper.ShouldQuiesce():
9999
return
100100
case <-ticker.C:
101-
lastIntervalHistogram := s.lastIntervalHistogram()
102-
if lastIntervalHistogram == nil {
101+
schedulingLatenciesHistogram := s.getAndClearLastStatsHistogram()
102+
if schedulingLatenciesHistogram == nil {
103103
continue
104104
}
105-
106-
schedulerLatencyHistogram.update(lastIntervalHistogram)
105+
schedulerLatencyHistogram.update(schedulingLatenciesHistogram)
107106
}
108107
}
109108
})
@@ -149,8 +148,10 @@ type sampler struct {
149148
listener LatencyObserver
150149
mu struct {
151150
syncutil.Mutex
152-
ringBuffer ring.Buffer[*metrics.Float64Histogram]
153-
lastIntervalHistogram *metrics.Float64Histogram
151+
ringBuffer ring.Buffer[*metrics.Float64Histogram]
152+
// schedulerLatencyAccumulator accumulates per-sample histogram deltas of
153+
// the go scheduler latencies.
154+
schedulerLatencyAccumulator *metrics.Float64Histogram
154155
}
155156
}
156157

@@ -170,7 +171,7 @@ func (s *sampler) setPeriodAndDuration(period, duration time.Duration) {
170171
numSamples = 1 // we need at least one sample to compare (also safeguards against integer division)
171172
}
172173
s.mu.ringBuffer.Resize(numSamples)
173-
s.mu.lastIntervalHistogram = nil
174+
s.mu.schedulerLatencyAccumulator = nil
174175
}
175176

176177
// sampleOnTickAndInvokeCallbacks samples scheduler latency stats as the ticker
@@ -179,16 +180,32 @@ func (s *sampler) sampleOnTickAndInvokeCallbacks(period time.Duration) {
179180
s.mu.Lock()
180181
defer s.mu.Unlock()
181182

183+
// Capture the previous sample before adding the new one.
184+
var prevSample *metrics.Float64Histogram
185+
if s.mu.ringBuffer.Len() > 0 {
186+
prevSample = s.mu.ringBuffer.GetFirst()
187+
}
188+
182189
latestCumulative := sample()
183190
oldestCumulative, ok := s.recordLocked(latestCumulative)
184191
if !ok {
185192
return
186193
}
187-
s.mu.lastIntervalHistogram = sub(latestCumulative, oldestCumulative)
188-
p99 := time.Duration(int64(percentile(s.mu.lastIntervalHistogram, 0.99) * float64(time.Second.Nanoseconds())))
194+
195+
// Compute the delta since the previous sample for stats accumulation.
196+
if prevSample != nil {
197+
sampleDelta := sub(latestCumulative, prevSample)
198+
if s.mu.schedulerLatencyAccumulator == nil {
199+
s.mu.schedulerLatencyAccumulator = sampleDelta
200+
} else {
201+
s.mu.schedulerLatencyAccumulator = add(s.mu.schedulerLatencyAccumulator, sampleDelta)
202+
}
203+
}
189204

190205
// Perform the callback if there's a listener.
191206
if s.listener != nil {
207+
p99 := time.Duration(int64(percentile(sub(latestCumulative, oldestCumulative),
208+
0.99) * float64(time.Second.Nanoseconds())))
192209
s.listener.SchedulerLatency(p99, period)
193210
}
194211
}
@@ -204,10 +221,12 @@ func (s *sampler) recordLocked(
204221
return oldest, oldest != nil
205222
}
206223

207-
func (s *sampler) lastIntervalHistogram() *metrics.Float64Histogram {
224+
func (s *sampler) getAndClearLastStatsHistogram() *metrics.Float64Histogram {
208225
s.mu.Lock()
209226
defer s.mu.Unlock()
210-
return s.mu.lastIntervalHistogram
227+
res := s.mu.schedulerLatencyAccumulator
228+
s.mu.schedulerLatencyAccumulator = nil
229+
return res
211230
}
212231

213232
// sample the cumulative (since process start) scheduler latency histogram from
@@ -249,6 +268,16 @@ func sub(a, b *metrics.Float64Histogram) *metrics.Float64Histogram {
249268
return res
250269
}
251270

271+
// add adds the counts of one histogram to another, assuming the bucket
272+
// boundaries are the same.
273+
func add(a, b *metrics.Float64Histogram) *metrics.Float64Histogram {
274+
res := clone(a)
275+
for i := 0; i < len(res.Counts); i++ {
276+
res.Counts[i] += b.Counts[i]
277+
}
278+
return res
279+
}
280+
252281
// percentile computes a specific percentile value of the given histogram.
253282
//
254283
// TODO(irfansharif): Deduplicate this with the quantile computation in

0 commit comments

Comments
 (0)