Add timing ratio histograms

Following is the result of benchmarking the two kinds of histograms on my laptop. % go test -benchmem -run=^$ -bench Histogram . goos: darwin goarch: amd64 pkg: k8s.io/apiserver/pkg/util/flowcontrol/metrics cpu: Intel(R) Core(TM) i9-9880H CPU @ 2.30GHz BenchmarkSampleAndWaterMarkHistogramsVecEltSafeEarly-16 980143 1230 ns/op 0 B/op 0 allocs/op BenchmarkSampleAndWaterMarkHistogramsVecEltSafeLate-16 932380 1216 ns/op 0 B/op 0 allocs/op BenchmarkTimingRatioHistogram-16 12665247 94.13 ns/op 0 B/op 0 allocs/op BenchmarkTimingRatioHistogramVecElementSimple-16 11015806 100.4 ns/op 0 B/op 0 allocs/op BenchmarkTimingRatioHistogramVecElementSafeEarly-16 7142589 172.0 ns/op 0 B/op 0 allocs/op BenchmarkTimingRatioHistogramVecElementSafeLate-16 11487517 96.67 ns/op 0 B/op 0 allocs/op PASS ok k8s.io/apiserver/pkg/util/flowcontrol/metrics 7.718s
2025-07-31 07:20:13 +00:00 · 2022-05-18 02:30:06 -04:00 · 2022-05-18 02:30:06 -04:00 · 8039f9d600
commit 8039f9d600
parent 5503bb0570
3 changed files with 533 additions and 0 deletions
--- 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
+	}
+}
--- 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
@ -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()
+}
--- 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
@ -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
+	}
+}