diff --git a/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/sample_and_watermark_test.go b/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/sample_and_watermark_test.go index b26ada1d028..30150e38454 100644 --- a/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/sample_and_watermark_test.go +++ b/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/sample_and_watermark_test.go @@ -120,3 +120,71 @@ func getHistogramCount(registry compbasemetrics.KubeRegistry, metricName string) } return 0, errMetricNotFound } + +func BenchmarkSampleAndWaterMarkHistogramsVecEltSafeEarly(b *testing.B) { + b.StopTimer() + now := time.Now() + clk := testclock.NewFakePassiveClock(now) + thv := NewSampleAndWaterMarkHistogramsVec(clk, time.Millisecond, + &compbasemetrics.HistogramOpts{ + Namespace: "testns", + Subsystem: "testsubsys", + Name: "samplehist", + Help: "Me", + Buckets: []float64{1, 2, 4, 8, 16, 32}, + }, + &compbasemetrics.HistogramOpts{ + Namespace: "testns", + Subsystem: "testsubsys", + Name: "markhist", + Help: "Me", + Buckets: []float64{1, 2, 4, 8, 16, 32}, + }, + []string{"labelname"}) + th := thv.NewForLabelValuesSafe(0, 3, []string{"labelvalue"}) + registry := compbasemetrics.NewKubeRegistry() + registry.MustRegister(thv.metrics()...) + var x int + b.StartTimer() + for i := 0; i < b.N; i++ { + delta := (i % 6) + 1 + now = now.Add(time.Duration(delta) * time.Millisecond) + clk.SetTime(now) + th.Set(float64(x)) + x = (x + i) % 60 + } +} + +func BenchmarkSampleAndWaterMarkHistogramsVecEltSafeLate(b *testing.B) { + b.StopTimer() + now := time.Now() + clk := testclock.NewFakePassiveClock(now) + thv := NewSampleAndWaterMarkHistogramsVec(clk, time.Millisecond, + &compbasemetrics.HistogramOpts{ + Namespace: "testns", + Subsystem: "testsubsys", + Name: "samplehist", + Help: "Me", + Buckets: []float64{1, 2, 4, 8, 16, 32}, + }, + &compbasemetrics.HistogramOpts{ + Namespace: "testns", + Subsystem: "testsubsys", + Name: "markhist", + Help: "Me", + Buckets: []float64{1, 2, 4, 8, 16, 32}, + }, + []string{"labelname"}) + registry := compbasemetrics.NewKubeRegistry() + registry.MustRegister(thv.metrics()...) + th := thv.NewForLabelValuesSafe(0, 3, []string{"labelvalue"}) + var x int + b.StartTimer() + for i := 0; i < b.N; i++ { + delta := (i % 6) + 1 + now = now.Add(time.Duration(delta) * time.Millisecond) + clk.SetTime(now) + th.Set(float64(x)) + x = (x + i) % 60 + } +} diff --git a/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/timing_ratio_histogram.go b/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/timing_ratio_histogram.go new file mode 100644 index 00000000000..09baf434059 --- /dev/null +++ b/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/timing_ratio_histogram.go @@ -0,0 +1,223 @@ +/* +Copyright 2022 The Kubernetes 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 metrics + +import ( + "context" + "sync" + "time" + + compbasemetrics "k8s.io/component-base/metrics" + "k8s.io/klog/v2" +) + +// TimingRatioHistogram is essentially a gauge for a ratio where the client +// independently controls the numerator and denominator. +// When scraped it produces a histogram of samples of the ratio +// taken at the end of every nanosecond. +// `*TimingRatioHistogram` implements both Registerable and RatioedGauge. +type TimingRatioHistogram struct { + // The implementation is layered on TimingHistogram, + // adding the division by an occasionally adjusted denominator. + + // Registerable is the registerable aspect. + // That is the registerable aspect of the underlying TimingHistogram. + compbasemetrics.Registerable + + // timingRatioHistogramInner implements the RatioedGauge aspect. + timingRatioHistogramInner +} + +// TimingRatioHistogramOpts is the constructor parameters of a TimingRatioHistogram. +// The `TimingHistogramOpts.InitialValue` is the initial numerator. +type TimingRatioHistogramOpts struct { + compbasemetrics.TimingHistogramOpts + InitialDenominator float64 +} + +// timingRatioHistogramInner implements the instrumentation aspect +type timingRatioHistogramInner struct { + nowFunc func() time.Time + getGaugeOfRatio func() Gauge + sync.Mutex + // access only with mutex locked + numerator, denominator float64 +} + +var _ RatioedGauge = &timingRatioHistogramInner{} +var _ RatioedGauge = &TimingRatioHistogram{} +var _ compbasemetrics.Registerable = &TimingRatioHistogram{} + +// NewTimingHistogram returns an object which is TimingHistogram-like. However, nothing +// will be measured until the histogram is registered in at least one registry. +func NewTimingRatioHistogram(opts *TimingRatioHistogramOpts) *TimingRatioHistogram { + return NewTestableTimingRatioHistogram(time.Now, opts) +} + +// NewTestableTimingHistogram adds injection of the clock +func NewTestableTimingRatioHistogram(nowFunc func() time.Time, opts *TimingRatioHistogramOpts) *TimingRatioHistogram { + ratioedOpts := opts.TimingHistogramOpts + ratioedOpts.InitialValue /= opts.InitialDenominator + th := compbasemetrics.NewTestableTimingHistogram(nowFunc, &ratioedOpts) + return &TimingRatioHistogram{ + Registerable: th, + timingRatioHistogramInner: timingRatioHistogramInner{ + nowFunc: nowFunc, + getGaugeOfRatio: func() Gauge { return th }, + numerator: opts.InitialValue, + denominator: opts.InitialDenominator, + }} +} + +func (trh *timingRatioHistogramInner) Set(numerator float64) { + trh.Lock() + defer trh.Unlock() + trh.numerator = numerator + ratio := numerator / trh.denominator + trh.getGaugeOfRatio().Set(ratio) +} + +func (trh *timingRatioHistogramInner) Add(deltaNumerator float64) { + trh.Lock() + defer trh.Unlock() + numerator := trh.numerator + deltaNumerator + trh.numerator = numerator + ratio := numerator / trh.denominator + trh.getGaugeOfRatio().Set(ratio) +} + +func (trh *timingRatioHistogramInner) Sub(deltaNumerator float64) { + trh.Add(-deltaNumerator) +} + +func (trh *timingRatioHistogramInner) Inc() { + trh.Add(1) +} + +func (trh *timingRatioHistogramInner) Dec() { + trh.Add(-1) +} + +func (trh *timingRatioHistogramInner) SetToCurrentTime() { + trh.Set(float64(trh.nowFunc().Sub(time.Unix(0, 0)))) +} + +func (trh *timingRatioHistogramInner) SetDenominator(denominator float64) { + trh.Lock() + defer trh.Unlock() + trh.denominator = denominator + ratio := trh.numerator / denominator + trh.getGaugeOfRatio().Set(ratio) +} + +// WithContext allows the normal TimingHistogram metric to pass in context. +// The context is no-op at the current level of development. +func (trh *timingRatioHistogramInner) WithContext(ctx context.Context) RatioedGauge { + return trh +} + +// TimingRatioHistogramVec is a collection of TimingRatioHistograms that differ +// only in label values. +// `*TimingRatioHistogramVec` implements both Registerable and RatioedGaugeVec. +type TimingRatioHistogramVec struct { + // promote only the Registerable methods + compbasemetrics.Registerable + // delegate is TimingHistograms of the ratio + delegate compbasemetrics.GaugeVecMetric +} + +var _ RatioedGaugeVec = &TimingRatioHistogramVec{} +var _ compbasemetrics.Registerable = &TimingRatioHistogramVec{} + +// NewTimingHistogramVec constructs a new vector. +// `opts.InitialValue` is the initial ratio, but this applies +// only for the tiny period of time until NewForLabelValuesSafe sets +// the ratio based on the given initial numerator and denominator. +// Thus there is a tiny splinter of time during member construction when +// its underlying TimingHistogram is given the initial numerator rather than +// the initial ratio (which is obviously a non-issue when both are zero). +// Note the difficulties associated with extracting a member +// before registering the vector. +func NewTimingRatioHistogramVec(opts *compbasemetrics.TimingHistogramOpts, labelNames ...string) *TimingRatioHistogramVec { + return NewTestableTimingRatioHistogramVec(time.Now, opts, labelNames...) +} + +// NewTestableTimingHistogramVec adds injection of the clock. +func NewTestableTimingRatioHistogramVec(nowFunc func() time.Time, opts *compbasemetrics.TimingHistogramOpts, labelNames ...string) *TimingRatioHistogramVec { + delegate := compbasemetrics.NewTestableTimingHistogramVec(nowFunc, opts, labelNames) + return &TimingRatioHistogramVec{ + Registerable: delegate, + delegate: delegate, + } +} + +func (v *TimingRatioHistogramVec) metrics() Registerables { + return Registerables{v} +} + +// NewForLabelValuesChecked will return an error if this vec is not hidden and not yet registered +// or there is a syntactic problem with the labelValues. +func (v *TimingRatioHistogramVec) NewForLabelValuesChecked(initialNumerator, initialDenominator float64, labelValues []string) (RatioedGauge, error) { + underMember, err := v.delegate.WithLabelValuesChecked(labelValues...) + if err != nil { + return noopRatioed{}, err + } + underMember.Set(initialNumerator / initialDenominator) + return &timingRatioHistogramInner{ + getGaugeOfRatio: func() Gauge { return underMember }, + numerator: initialNumerator, + denominator: initialDenominator, + }, nil +} + +// NewForLabelValuesSafe is the same as NewForLabelValuesChecked in cases where that does not +// return an error. When the unsafe version returns an error due to the vector not being +// registered yet, the safe version returns an object that implements its methods +// by looking up the relevant vector member in each call (thus getting a non-noop after registration). +// In the other error cases the object returned here is a noop. +func (v *TimingRatioHistogramVec) NewForLabelValuesSafe(initialNumerator, initialDenominator float64, labelValues []string) RatioedGauge { + tro, err := v.NewForLabelValuesChecked(initialNumerator, initialDenominator, labelValues) + if err == nil { + return tro + } + if !compbasemetrics.ErrIsNotRegistered(err) { + klog.ErrorS(err, "Failed to extract TimingRatioHistogramVec member, using noop instead", "vectorname", v.FQName(), "labelValues", labelValues) + return tro + } + // At this point we know v.NewForLabelValuesChecked(..) returns a permanent noop, + // which we precisely want to avoid using. Instead, make our own gauge that + // fetches the element on every Set. + return &timingRatioHistogramInner{ + getGaugeOfRatio: func() Gauge { return v.delegate.WithLabelValues(labelValues...) }, + numerator: initialNumerator, + denominator: initialDenominator, + } +} + +type noopRatioed struct{} + +func (noopRatioed) Set(float64) {} +func (noopRatioed) Add(float64) {} +func (noopRatioed) Sub(float64) {} +func (noopRatioed) Inc() {} +func (noopRatioed) Dec() {} +func (noopRatioed) SetToCurrentTime() {} +func (noopRatioed) SetDenominator(float64) {} + +func (v *TimingRatioHistogramVec) Reset() { + v.delegate.Reset() +} diff --git a/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/timing_ratio_histogram_test.go b/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/timing_ratio_histogram_test.go new file mode 100644 index 00000000000..faa6433539a --- /dev/null +++ b/staging/src/k8s.io/apiserver/pkg/util/flowcontrol/metrics/timing_ratio_histogram_test.go @@ -0,0 +1,242 @@ +/* +Copyright 2022 The Kubernetes 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 metrics + +import ( + "math/rand" + "testing" + "time" + + compbasemetrics "k8s.io/component-base/metrics" + "k8s.io/klog/v2" + testclock "k8s.io/utils/clock/testing" +) + +func TestTimingRatioHistogramVecElementSimple(t *testing.T) { + testHistogramName := "vec_element_simple" + t0 := time.Now() + clk := testclock.NewFakePassiveClock(t0) + buckets := []float64{0, 1} + vec := NewTestableTimingRatioHistogramVec(clk.Now, + &compbasemetrics.TimingHistogramOpts{Name: testHistogramName, Buckets: buckets}, + "alabel", + ) + toRegister := vec.metrics() + registry := compbasemetrics.NewKubeRegistry() + for _, reg := range toRegister { + registry.MustRegister(reg) + } + tro, err := vec.NewForLabelValuesChecked(0, 1, []string{"avalue"}) + if err != nil { + t.Error(err) + } + exerciseTimingRatioHistogram(t, testHistogramName, t0, clk, registry, tro) +} + +func TestTimingRatioHistogramVecElementSafeEarly(t *testing.T) { + testHistogramName := "vec_element_safe_early" + t0 := time.Now() + clk := testclock.NewFakePassiveClock(t0) + buckets := []float64{0, 1} + vec := NewTestableTimingRatioHistogramVec(clk.Now, + &compbasemetrics.TimingHistogramOpts{Name: testHistogramName, Buckets: buckets}, + "alabel", + ) + tro := vec.NewForLabelValuesSafe(0, 1, []string{"avalue"}) + toRegister := vec.metrics() + registry := compbasemetrics.NewKubeRegistry() + for _, reg := range toRegister { + registry.MustRegister(reg) + } + exerciseTimingRatioHistogram(t, testHistogramName, t0, clk, registry, tro) +} + +func TestTimingRatioHistogramVecElementSafeLate(t *testing.T) { + testHistogramName := "vec_element_safe_late" + t0 := time.Now() + clk := testclock.NewFakePassiveClock(t0) + buckets := []float64{0, 1} + vec := NewTestableTimingRatioHistogramVec(clk.Now, + &compbasemetrics.TimingHistogramOpts{Name: testHistogramName, Buckets: buckets}, + "alabel", + ) + toRegister := vec.metrics() + registry := compbasemetrics.NewKubeRegistry() + for _, reg := range toRegister { + registry.MustRegister(reg) + } + tro := vec.NewForLabelValuesSafe(0, 1, []string{"avalue"}) + exerciseTimingRatioHistogram(t, testHistogramName, t0, clk, registry, tro) +} + +// exerciseTimingRatioHistogram does a rough behavioral test of a +// RatioedObserver. A fake clock is used, and the exercise consists +// of repeatedly changing that fake clock by an amount of time chosen +// uniformly at random from a range that goes from a little negative +// to somewhat more than two milliseconds. The negative changes are +// included because small negative changes have been observed in real +// monotonic clock readings (see issue #96459) and we want to test +// that they are properly tolerated. The designed toleration is to +// pretend that the clock did not change, until it resumes net forward +// progress. The exercise checks that the count in the observer is +// correct at each step. The observer is expected to get one +// observation at the end of each nanosecond. +func exerciseTimingRatioHistogram(t *testing.T, histogramName string, t0 time.Time, clk *testclock.FakePassiveClock, registry compbasemetrics.KubeRegistry, tro RatioedGauge) { + samplingPeriod := time.Nanosecond + steppingPeriod := time.Millisecond + tro.Set(1) + // `dt` is the admitted cumulative difference in fake time + // since the start of the test. "admitted" means this is + // never allowed to decrease, which matches the designed + // toleration for negative monotonic clock changes. + var dt time.Duration + // `t1` is the current fake time + t1 := t0.Add(dt) + klog.Infof("Expect about %v warnings about time going backwards; this is fake time deliberately misbehaving.", (numIterations*ddtOffsetCentiPeriods)/ddtRangeCentiPeriods) + t.Logf("t0=%s", t0) + for i := 0; i < numIterations; i++ { + // `ddt` is the next step to take in fake time + ddt := time.Duration(rand.Intn(ddtRangeCentiPeriods)-ddtOffsetCentiPeriods) * steppingPeriod / 100 + t1 = t1.Add(ddt) + diff := t1.Sub(t0) + if diff > dt { + dt = diff + } + clk.SetTime(t1) + tro.Set(1) + expectedCount := int64(dt / samplingPeriod) + actualCount, err := getHistogramCount(registry, histogramName) + if err != nil && !(err == errMetricNotFound && expectedCount == 0) { + t.Fatalf("For t0=%s, t1=%s, failed to getHistogramCount: %#+v", t0, t1, err) + } + t.Logf("For i=%d, ddt=%s, t1=%s, diff=%s, dt=%s, count=%d", i, ddt, t1, diff, dt, actualCount) + if expectedCount != actualCount { + t.Errorf("For i=%d, t0=%s, ddt=%s, t1=%s, expectedCount=%d, actualCount=%d", i, t0, ddt, t1, expectedCount, actualCount) + } + } +} + +func BenchmarkTimingRatioHistogram(b *testing.B) { + b.StopTimer() + now := time.Now() + clk := testclock.NewFakePassiveClock(now) + th := NewTestableTimingRatioHistogram(clk.Now, + &TimingRatioHistogramOpts{ + compbasemetrics.TimingHistogramOpts{ + Namespace: "testns", + Subsystem: "testsubsys", + Name: "testhist", + Help: "Me", + Buckets: []float64{1, 2, 4, 8, 16, 32}, + }, + 1}) + registry := compbasemetrics.NewKubeRegistry() + registry.MustRegister(th) + var x int + b.StartTimer() + for i := 0; i < b.N; i++ { + delta := (i % 6) + 1 + now = now.Add(time.Duration(delta) * time.Millisecond) + clk.SetTime(now) + th.Set(float64(x)) + x = (x + i) % 60 + } +} + +func BenchmarkTimingRatioHistogramVecElementSimple(b *testing.B) { + b.StopTimer() + now := time.Now() + clk := testclock.NewFakePassiveClock(now) + thv := NewTestableTimingRatioHistogramVec(clk.Now, + &compbasemetrics.TimingHistogramOpts{ + Namespace: "testns", + Subsystem: "testsubsys", + Name: "testhist", + Help: "Me", + Buckets: []float64{1, 2, 4, 8, 16, 32}, + }, + "labelname") + registry := compbasemetrics.NewKubeRegistry() + registry.MustRegister(thv.metrics()...) + th, err := thv.NewForLabelValuesChecked(0, 3, []string{"labelvalue"}) + if err != nil { + b.Error(err) + } + var x int + b.StartTimer() + for i := 0; i < b.N; i++ { + delta := (i % 6) + 1 + now = now.Add(time.Duration(delta) * time.Millisecond) + clk.SetTime(now) + th.Set(float64(x)) + x = (x + i) % 60 + } +} + +func BenchmarkTimingRatioHistogramVecElementSafeEarly(b *testing.B) { + b.StopTimer() + now := time.Now() + clk := testclock.NewFakePassiveClock(now) + thv := NewTestableTimingRatioHistogramVec(clk.Now, + &compbasemetrics.TimingHistogramOpts{ + Namespace: "testns", + Subsystem: "testsubsys", + Name: "testhist", + Help: "Me", + Buckets: []float64{1, 2, 4, 8, 16, 32}, + }, + "labelname") + th := thv.NewForLabelValuesSafe(0, 3, []string{"labelvalue"}) + registry := compbasemetrics.NewKubeRegistry() + registry.MustRegister(thv.metrics()...) + var x int + b.StartTimer() + for i := 0; i < b.N; i++ { + delta := (i % 6) + 1 + now = now.Add(time.Duration(delta) * time.Millisecond) + clk.SetTime(now) + th.Set(float64(x)) + x = (x + i) % 60 + } +} + +func BenchmarkTimingRatioHistogramVecElementSafeLate(b *testing.B) { + b.StopTimer() + now := time.Now() + clk := testclock.NewFakePassiveClock(now) + thv := NewTestableTimingRatioHistogramVec(clk.Now, + &compbasemetrics.TimingHistogramOpts{ + Namespace: "testns", + Subsystem: "testsubsys", + Name: "testhist", + Help: "Me", + Buckets: []float64{1, 2, 4, 8, 16, 32}, + }, + "labelname") + registry := compbasemetrics.NewKubeRegistry() + registry.MustRegister(thv.metrics()...) + th := thv.NewForLabelValuesSafe(0, 3, []string{"labelvalue"}) + var x int + b.StartTimer() + for i := 0; i < b.N; i++ { + delta := (i % 6) + 1 + now = now.Add(time.Duration(delta) * time.Millisecond) + clk.SetTime(now) + th.Set(float64(x)) + x = (x + i) % 60 + } +}