From d0328df04e06384a0456606c708e5b62ec18d9c2 Mon Sep 17 00:00:00 2001 From: Alexander Zielenski Date: Wed, 18 Oct 2023 19:31:39 -0700 Subject: [PATCH 1/2] add time tracking to CorrelatedObject --- .../apiserver/pkg/cel/common/equality.go | 42 ++++++++++++++++++- 1 file changed, 40 insertions(+), 2 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/cel/common/equality.go b/staging/src/k8s.io/apiserver/pkg/cel/common/equality.go index a271cae795e..9289637a395 100644 --- a/staging/src/k8s.io/apiserver/pkg/cel/common/equality.go +++ b/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 } From 4bb7dc224c526993991f060124c440ce09d71793 Mon Sep 17 00:00:00 2001 From: Alexander Zielenski Date: Thu, 26 Oct 2023 15:18:32 -0700 Subject: [PATCH 2/2] metrics: publish metrics from ratcheting across a request --- .../pkg/apiserver/validation/metrics.go | 66 ++++ .../pkg/apiserver/validation/metrics_test.go | 298 ++++++++++++++++++ .../pkg/registry/customresource/strategy.go | 7 +- 3 files changed, 370 insertions(+), 1 deletion(-) create mode 100644 staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/validation/metrics.go create mode 100644 staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/validation/metrics_test.go diff --git a/staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/validation/metrics.go b/staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/validation/metrics.go new file mode 100644 index 00000000000..7dcc7938e08 --- /dev/null +++ b/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} +} diff --git a/staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/validation/metrics_test.go b/staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/validation/metrics_test.go new file mode 100644 index 00000000000..56775866cca --- /dev/null +++ b/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) + } + }) + } +} diff --git a/staging/src/k8s.io/apiextensions-apiserver/pkg/registry/customresource/strategy.go b/staging/src/k8s.io/apiextensions-apiserver/pkg/registry/customresource/strategy.go index 3852125c23d..3713627ed87 100644 --- a/staging/src/k8s.io/apiextensions-apiserver/pkg/registry/customresource/strategy.go +++ b/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 }