Merge pull request #121462 from alexzielenski/apiserver/apiextensions/ratcheting-metrics-actually

KEP-4008: CRDValidationRatcheting Metrics

staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/validation/metrics.go

@@ -0,0 +1,66 @@
+/*
+Copyright 2023 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 validation
+
+import (
+	"time"
+
+	"k8s.io/component-base/metrics"
+	"k8s.io/component-base/metrics/legacyregistry"
+)
+
+const (
+	namespace = "apiextensions_apiserver"
+	subsystem = "validation"
+)
+
+// Interface to stub for tests
+type ValidationMetrics interface {
+	ObserveRatchetingTime(d time.Duration)
+}
+
+var Metrics ValidationMetrics = &validationMetrics{
+	RatchetingTime: metrics.NewHistogram(&metrics.HistogramOpts{
+		Namespace:      namespace,
+		Subsystem:      subsystem,
+		Name:           "ratcheting_seconds",
+		Help:           "Time for comparison of old to new for the purposes of CRDValidationRatcheting during an UPDATE in seconds.",
+		StabilityLevel: metrics.ALPHA,
+		// Start 0.01ms with the last bucket being [~2.5s, +Inf)
+		Buckets: metrics.ExponentialBuckets(0.00001, 4, 10),
+	}),
+}
+
+func init() {
+	legacyregistry.MustRegister(Metrics.(*validationMetrics).RatchetingTime)
+}
+
+type validationMetrics struct {
+	RatchetingTime *metrics.Histogram
+}
+
+// ObserveRatchetingTime records the time spent on ratcheting
+func (m *validationMetrics) ObserveRatchetingTime(d time.Duration) {
+	m.RatchetingTime.Observe(d.Seconds())
+}
+
+// Reset resets the metrics. This is meant to be used for testing. Panics
+// if the metrics cannot be re-registered. Returns all the reset metrics
+func (m *validationMetrics) Reset() []metrics.Registerable {
+	m.RatchetingTime = metrics.NewHistogram(m.RatchetingTime.HistogramOpts)
+	return []metrics.Registerable{m.RatchetingTime}
+}

staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/validation/metrics_test.go

@@ -0,0 +1,298 @@
+/*
+Copyright 2023 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 validation_test
+
+import (
+	"context"
+	"strings"
+	"testing"
+	"time"
+
+	"k8s.io/apiextensions-apiserver/pkg/apis/apiextensions"
+	structuralschema "k8s.io/apiextensions-apiserver/pkg/apiserver/schema"
+	"k8s.io/apiextensions-apiserver/pkg/apiserver/validation"
+	apiextensionsfeatures "k8s.io/apiextensions-apiserver/pkg/features"
+	"k8s.io/apiextensions-apiserver/pkg/registry/customresource"
+	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
+	"k8s.io/apimachinery/pkg/runtime/schema"
+	utilfeature "k8s.io/apiserver/pkg/util/feature"
+	featuregatetesting "k8s.io/component-base/featuregate/testing"
+	"k8s.io/component-base/metrics"
+	"k8s.io/component-base/metrics/testutil"
+)
+
+type fakeMetrics struct {
+	original validation.ValidationMetrics
+	realSum  time.Duration
+}
+
+func (f *fakeMetrics) ObserveRatchetingTime(d time.Duration) {
+	// Hardcode 1 ns duration for testing to exercise all buckets
+	f.original.ObserveRatchetingTime(1 * time.Nanosecond)
+	f.realSum += d
+}
+
+func (f *fakeMetrics) Reset() []metrics.Registerable {
+	f.realSum = 0
+	originalResettable, ok := f.original.(resettable)
+	if !ok {
+		panic("wrapped metrics must implement resettable")
+	}
+	return originalResettable.Reset()
+}
+
+type resettable interface {
+	Reset() []metrics.Registerable
+}
+
+func TestMetrics(t *testing.T) {
+	defer featuregatetesting.SetFeatureGateDuringTest(t, utilfeature.DefaultFeatureGate, apiextensionsfeatures.CRDValidationRatcheting, true)()
+
+	// Wrap metric to keep time constant
+	testMetrics := &fakeMetrics{original: validation.Metrics}
+	validation.Metrics = testMetrics
+	defer func() {
+		validation.Metrics = testMetrics.original
+	}()
+
+	metricNames := []string{
+		"apiextensions_apiserver_validation_ratcheting_seconds",
+	}
+
+	testCases := []struct {
+		desc   string
+		obj    *unstructured.Unstructured
+		old    *unstructured.Unstructured
+		schema apiextensions.JSONSchemaProps
+		iters  int // how many times to validate the same update before checking metric
+		want   string
+	}{
+		{
+			desc: "valid noop update",
+			obj: &unstructured.Unstructured{
+				Object: map[string]interface{}{
+					"foo": "bar",
+				},
+			},
+			old: &unstructured.Unstructured{
+				Object: map[string]interface{}{
+					"foo": "bar",
+				},
+			},
+			schema: apiextensions.JSONSchemaProps{
+				Type: "object",
+				Properties: map[string]apiextensions.JSONSchemaProps{
+					"foo": {
+						Type: "string",
+					},
+				},
+			},
+			want: `
+			# HELP apiextensions_apiserver_validation_ratcheting_seconds [ALPHA] Time for comparison of old to new for the purposes of CRDValidationRatcheting during an UPDATE in seconds.
+        	# TYPE apiextensions_apiserver_validation_ratcheting_seconds histogram
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="1e-05"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="4e-05"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00016"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00064"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00256"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.01024"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.04096"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.16384"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.65536"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="2.62144"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="Inf"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_sum 5e-09
+        	apiextensions_apiserver_validation_ratcheting_seconds_count 5
+			`,
+			iters: 5,
+		},
+		{
+			desc: "valid change yields no metrics",
+			obj: &unstructured.Unstructured{
+				Object: map[string]interface{}{
+					"foo": "bar",
+				},
+			},
+			old: &unstructured.Unstructured{
+				Object: map[string]interface{}{
+					"foo": "barx",
+				},
+			},
+			schema: apiextensions.JSONSchemaProps{
+				Type: "object",
+				Properties: map[string]apiextensions.JSONSchemaProps{
+					"foo": {
+						Type: "string",
+						Enum: []apiextensions.JSON{
+							"barx", "bar",
+						},
+					},
+				},
+			},
+			want: `
+			# HELP apiextensions_apiserver_validation_ratcheting_seconds [ALPHA] Time for comparison of old to new for the purposes of CRDValidationRatcheting during an UPDATE in seconds.
+        	# TYPE apiextensions_apiserver_validation_ratcheting_seconds histogram
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="1e-05"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="4e-05"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00016"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00064"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00256"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.01024"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.04096"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.16384"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.65536"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="2.62144"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="Inf"} 3
+        	apiextensions_apiserver_validation_ratcheting_seconds_sum 3.0000000000000004e-09
+        	apiextensions_apiserver_validation_ratcheting_seconds_count 3
+			`,
+			iters: 3,
+		},
+		{
+			desc: "invalid noop yields no metrics",
+			obj: &unstructured.Unstructured{
+				Object: map[string]interface{}{
+					"foo": "bar",
+				},
+			},
+			old: &unstructured.Unstructured{
+				Object: map[string]interface{}{
+					"foo": "bar",
+				},
+			},
+			schema: apiextensions.JSONSchemaProps{
+				Type: "object",
+				Properties: map[string]apiextensions.JSONSchemaProps{
+					"foo": {
+						Type: "string",
+						Enum: []apiextensions.JSON{
+							"incorrect",
+						},
+					},
+				},
+			},
+			want: `
+			# HELP apiextensions_apiserver_validation_ratcheting_seconds [ALPHA] Time for comparison of old to new for the purposes of CRDValidationRatcheting during an UPDATE in seconds.
+        	# TYPE apiextensions_apiserver_validation_ratcheting_seconds histogram
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="1e-05"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="4e-05"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00016"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00064"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00256"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.01024"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.04096"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.16384"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.65536"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="2.62144"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="Inf"} 10
+        	apiextensions_apiserver_validation_ratcheting_seconds_sum 1.0000000000000002e-08
+        	apiextensions_apiserver_validation_ratcheting_seconds_count 10
+			`,
+			iters: 10,
+		},
+		{
+			desc: "ratcheted change object yields metrics",
+			obj: &unstructured.Unstructured{
+				Object: map[string]interface{}{
+					"foo": "bar",
+				},
+			},
+			old: &unstructured.Unstructured{
+				Object: map[string]interface{}{
+					"foo": "barx",
+				},
+			},
+			schema: apiextensions.JSONSchemaProps{
+				Type: "object",
+				Properties: map[string]apiextensions.JSONSchemaProps{
+					"foo": {
+						Type: "string",
+						Enum: []apiextensions.JSON{
+							"incorrect",
+						},
+					},
+				},
+			},
+			want: `
+			# HELP apiextensions_apiserver_validation_ratcheting_seconds [ALPHA] Time for comparison of old to new for the purposes of CRDValidationRatcheting during an UPDATE in seconds.
+        	# TYPE apiextensions_apiserver_validation_ratcheting_seconds histogram
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="1e-05"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="4e-05"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00016"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00064"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.00256"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.01024"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.04096"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.16384"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="0.65536"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="2.62144"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_bucket{le="Inf"} 5
+        	apiextensions_apiserver_validation_ratcheting_seconds_sum 5e-09
+        	apiextensions_apiserver_validation_ratcheting_seconds_count 5
+			`,
+			iters: 5,
+		},
+	}
+
+	for _, tt := range testCases {
+		t.Run(tt.desc, func(t *testing.T) {
+			testRegistry := metrics.NewKubeRegistry()
+			ms := testMetrics.Reset()
+			testRegistry.MustRegister(ms...)
+
+			schemaValidator, _, err := validation.NewSchemaValidator(&tt.schema)
+			if err != nil {
+				t.Fatal(err)
+				return
+			}
+			sts, err := structuralschema.NewStructural(&tt.schema)
+			if err != nil {
+				t.Fatal(err)
+			}
+			gvk := schema.GroupVersionKind{Group: "example.com", Version: "v1", Kind: "Foo"}
+			tt.obj.SetGroupVersionKind(gvk)
+			tt.old.SetGroupVersionKind(gvk)
+			strategy := customresource.NewStrategy(
+				nil,
+				true,
+				gvk,
+				schemaValidator,
+				nil,
+				sts,
+				nil,
+				nil,
+			)
+
+			iters := 1
+			if tt.iters > 0 {
+				iters = tt.iters
+			}
+			for i := 0; i < iters; i++ {
+				_ = strategy.ValidateUpdate(context.TODO(), tt.obj, tt.old)
+			}
+
+			if err := testutil.GatherAndCompare(testRegistry, strings.NewReader(tt.want), metricNames...); err != nil {
+				t.Errorf("unexpected collecting result:\n%s", err)
+			}
+
+			// Ensure that the real durations is > 0 for all tests
+			if testMetrics.realSum <= 0 {
+				t.Errorf("realSum = %v, want > 0", testMetrics.realSum)
+			}
+		})
+	}
+}

staging/src/k8s.io/apiextensions-apiserver/pkg/registry/customresource/strategy.go

@@ -247,8 +247,9 @@ func (a customResourceStrategy) ValidateUpdate(ctx context.Context, obj, old run
 
 	var options []validation.ValidationOption
 	var celOptions []cel.Option
+	var correlatedObject *common.CorrelatedObject
 	if utilfeature.DefaultFeatureGate.Enabled(apiextensionsfeatures.CRDValidationRatcheting) {
-		correlatedObject := common.NewCorrelatedObject(uNew.Object, uOld.Object, &model.Structural{Structural: a.structuralSchema})
+		correlatedObject = common.NewCorrelatedObject(uNew.Object, uOld.Object, &model.Structural{Structural: a.structuralSchema})
 		options = append(options, validation.WithRatcheting(correlatedObject))
 		celOptions = append(celOptions, cel.WithRatcheting(correlatedObject))
 	}
@@ -274,6 +275,10 @@ func (a customResourceStrategy) ValidateUpdate(ctx context.Context, obj, old run
 		}
 	}
 
+	// No-op if not attached to context
+	if utilfeature.DefaultFeatureGate.Enabled(apiextensionsfeatures.CRDValidationRatcheting) {
+		validation.Metrics.ObserveRatchetingTime(*correlatedObject.Duration)
+	}
 	return errs
 }
 

staging/src/k8s.io/apiserver/pkg/cel/common/equality.go

@@ -18,6 +18,7 @@ package common
 
 import (
 	"reflect"
+	"time"
 )
 
 // CorrelatedObject represents a node in a tree of objects that are being
@@ -42,6 +43,10 @@ type CorrelatedObject struct {
 	// to determine how to correlate the old object.
 	Schema Schema
 
+	// Duration spent on ratcheting validation for this object and all of its
+	// children.
+	Duration *time.Duration
+
 	// Scratch space below, may change during validation
 
 	// Cached comparison result of DeepEqual of `value` and `thunk.oldValue`
@@ -64,10 +69,12 @@ type CorrelatedObject struct {
 }
 
 func NewCorrelatedObject(new, old interface{}, schema Schema) *CorrelatedObject {
+	d := time.Duration(0)
 	return &CorrelatedObject{
 		OldValue: old,
 		Value:    new,
 		Schema:   schema,
+		Duration: &d,
 	}
 }
 
@@ -136,6 +143,13 @@ func (r *CorrelatedObject) correlateOldValueForChildAtNewIndex(index int) interf
 // to validation logic short circuiting and skipping the children, then
 // this function simply defers to reflect.DeepEqual.
 func (r *CorrelatedObject) CachedDeepEqual() (res bool) {
+	start := time.Now()
+	defer func() {
+		if r != nil && r.Duration != nil {
+			*r.Duration += time.Since(start)
+		}
+	}()
+
 	if r == nil {
 		// Uncorrelatable node is not considered equal to its old value
 		return false
@@ -222,6 +236,13 @@ func (r *CorrelatedObject) CachedDeepEqual() (res bool) {
 // value is not correlatable to an old value.
 // If receiver is nil or if the new value is not an object/map, returns nil.
 func (r *CorrelatedObject) Key(field string) *CorrelatedObject {
+	start := time.Now()
+	defer func() {
+		if r != nil && r.Duration != nil {
+			*r.Duration += time.Since(start)
+		}
+	}()
+
 	if r == nil || r.Schema == nil {
 		return nil
 	} else if existing, exists := r.children[field]; exists {
@@ -254,7 +275,12 @@ func (r *CorrelatedObject) Key(field string) *CorrelatedObject {
 		r.children = make(map[interface{}]*CorrelatedObject, len(newAsMap))
 	}
 
-	res := NewCorrelatedObject(newValueForField, oldValueForField, propertySchema)
+	res := &CorrelatedObject{
+		OldValue: oldValueForField,
+		Value:    newValueForField,
+		Schema:   propertySchema,
+		Duration: r.Duration,
+	}
 	r.children[field] = res
 	return res
 }
@@ -264,6 +290,13 @@ func (r *CorrelatedObject) Key(field string) *CorrelatedObject {
 // correlatable to an old value.
 // If receiver is nil or if the new value is not an array, returns nil.
 func (r *CorrelatedObject) Index(i int) *CorrelatedObject {
+	start := time.Now()
+	defer func() {
+		if r != nil && r.Duration != nil {
+			*r.Duration += time.Since(start)
+		}
+	}()
+
 	if r == nil || r.Schema == nil {
 		return nil
 	} else if existing, exists := r.children[i]; exists {
@@ -290,7 +323,12 @@ func (r *CorrelatedObject) Index(i int) *CorrelatedObject {
 		r.children = make(map[interface{}]*CorrelatedObject, len(asList))
 	}
 
-	res := NewCorrelatedObject(asList[i], oldValueForIndex, itemSchema)
+	res := &CorrelatedObject{
+		OldValue: oldValueForIndex,
+		Value:    asList[i],
+		Schema:   itemSchema,
+		Duration: r.Duration,
+	}
 	r.children[i] = res
 	return res
 }