Merge pull request #60536 from immutableT/transformer_metrics

Automatic merge from submit-queue (batch tested with PRs 62748, 60536, 62300, 62661, 62731). If you want to cherry-pick this change to another branch, please follow the instructions <a href="https://github.com/kubernetes/community/blob/master/contributors/devel/cherry-picks.md">here</a>.

Instrument transformer.go with latency metrics.

**What this PR does / why we need it**:
Instrument transformer.go with latency metrics - allowing to measure performance impact of adding KMS Providers.
**Which issue(s) this PR fixes** *(optional, in `fixes #<issue number>(, fixes #<issue_number>, ...)` format, will close the issue(s) when PR gets merged)*:
Fixes #

**Special notes for your reviewer**:

**Release note**:

```release-note
"NONE"
```

staging/src/k8s.io/apiserver/pkg/storage/value/BUILD

@@ -14,8 +14,12 @@ go_test(
 
 go_library(
     name = "go_default_library",
-    srcs = ["transformer.go"],
+    srcs = [
+        "metrics.go",
+        "transformer.go",
+    ],
     importpath = "k8s.io/apiserver/pkg/storage/value",
+    deps = ["//vendor/github.com/prometheus/client_golang/prometheus:go_default_library"],
 )
 
 filegroup(

staging/src/k8s.io/apiserver/pkg/storage/value/metrics.go

@@ -0,0 +1,57 @@
+/*
+Copyright 2017 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 value
+
+import (
+	"sync"
+	"time"
+
+	"github.com/prometheus/client_golang/prometheus"
+)
+
+var (
+	transformerLatencies = prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Namespace: "apiserver",
+			Subsystem: "storage",
+			Name:      "transformation_latencies_microseconds",
+			Help:      "Latencies in microseconds of value transformation operations.",
+			// In-process transformations (ex. AES CBC) complete on the order of 20 microseconds. However, when
+			// external KMS is involved latencies may climb into milliseconds.
+			Buckets: prometheus.ExponentialBuckets(5, 2, 14),
+		},
+		[]string{"transformation_type"},
+	)
+)
+
+var registerMetrics sync.Once
+
+func RegisterMetrics() {
+	registerMetrics.Do(func() {
+		prometheus.MustRegister(transformerLatencies)
+	})
+}
+
+func RecordTransformation(transformationType string, start time.Time) {
+	since := sinceInMicroseconds(start)
+	transformerLatencies.WithLabelValues(transformationType).Observe(float64(since))
+}
+
+func sinceInMicroseconds(start time.Time) int64 {
+	elapsedNanoseconds := time.Since(start).Nanoseconds()
+	return elapsedNanoseconds / int64(time.Microsecond)
+}

staging/src/k8s.io/apiserver/pkg/storage/value/transformer.go

@@ -21,8 +21,13 @@ import (
 	"bytes"
 	"fmt"
 	"sync"
+	"time"
 )
 
+func init() {
+	RegisterMetrics()
+}
+
 // Context is additional information that a storage transformation may need to verify the data at rest.
 type Context interface {
 	// AuthenticatedData should return an array of bytes that describes the current value. If the value changes,
@@ -80,12 +85,14 @@ func (t *MutableTransformer) Set(transformer Transformer) {
 }
 
 func (t *MutableTransformer) TransformFromStorage(data []byte, context Context) (out []byte, stale bool, err error) {
+	defer RecordTransformation("from_storage", time.Now())
 	t.lock.RLock()
 	transformer := t.transformer
 	t.lock.RUnlock()
 	return transformer.TransformFromStorage(data, context)
 }
 func (t *MutableTransformer) TransformToStorage(data []byte, context Context) (out []byte, err error) {
+	defer RecordTransformation("to_storage", time.Now())
 	t.lock.RLock()
 	transformer := t.transformer
 	t.lock.RUnlock()

test/integration/master/BUILD

@@ -181,6 +181,7 @@ go_library(
         "//test/integration/framework:go_default_library",
         "//vendor/github.com/coreos/etcd/clientv3:go_default_library",
         "//vendor/github.com/ghodss/yaml:go_default_library",
+        "//vendor/github.com/prometheus/client_golang/prometheus:go_default_library",
         "//vendor/k8s.io/api/core/v1:go_default_library",
         "//vendor/k8s.io/apimachinery/pkg/apis/meta/v1:go_default_library",
         "//vendor/k8s.io/apiserver/pkg/server/options/encryptionconfig:go_default_library",

test/integration/master/secrets_transformation_test.go

@@ -124,6 +124,7 @@ func runBenchmark(b *testing.B, transformerConfig string) {
 	b.StartTimer()
 	test.benchmark(b)
 	b.StopTimer()
+	test.printMetrics()
 }
 
 func unSealWithGCMTransformer(cipherText []byte, ctx value.Context,

test/integration/master/transformation_testcase.go

@@ -29,6 +29,7 @@ import (
 
 	"github.com/coreos/etcd/clientv3"
 	"github.com/ghodss/yaml"
+	"github.com/prometheus/client_golang/prometheus"
 
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -42,11 +43,12 @@ import (
 )
 
 const (
-	secretKey                = "api_key"
-	secretVal                = "086a7ffc-0225-11e8-ba89-0ed5f89f718b"
-	encryptionConfigFileName = "encryption.conf"
-	testNamespace            = "secret-encryption-test"
-	testSecret               = "test-secret"
+	secretKey                   = "api_key"
+	secretVal                   = "086a7ffc-0225-11e8-ba89-0ed5f89f718b"
+	encryptionConfigFileName    = "encryption.conf"
+	testNamespace               = "secret-encryption-test"
+	testSecret                  = "test-secret"
+	latencySummaryMetricsFamily = "apiserver_storage_transformation_latencies_microseconds"
 )
 
 type unSealSecret func(cipherText []byte, ctx value.Context, config encryptionconfig.ProviderConfig) ([]byte, error)
@@ -237,3 +239,31 @@ func (e *transformTest) readRawRecordFromETCD(path string) (*clientv3.GetRespons
 
 	return response, nil
 }
+
+func (e *transformTest) printMetrics() error {
+	e.logger.Logf("Transformation Metrics:")
+	metrics, err := prometheus.DefaultGatherer.Gather()
+	if err != nil {
+		return fmt.Errorf("failed to gather metrics: %s", err)
+	}
+
+	metricsOfInterest := []string{latencySummaryMetricsFamily}
+	for _, mf := range metrics {
+		if contains(metricsOfInterest, *mf.Name) {
+			for _, metric := range mf.GetMetric() {
+				e.logger.Logf("%v", metric)
+			}
+		}
+	}
+
+	return nil
+}
+
+func contains(s []string, e string) bool {
+	for _, a := range s {
+		if a == e {
+			return true
+		}
+	}
+	return false
+}