Merge pull request #322 from pohly/kobjs-performance

replace KObjs with KObjSlice

examples/benchmarks/benchmarks_test.go

@@ -0,0 +1,152 @@
+/*
+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 benchmarks
+
+import (
+	"flag"
+	"fmt"
+	"io"
+	"testing"
+
+	"github.com/go-logr/logr"
+	"github.com/go-logr/zapr"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"k8s.io/klog/v2"
+)
+
+const (
+	verbosityThreshold = 10
+)
+
+func init() {
+	// klog gets configured so that it writes to a single output file that
+	// will be set during tests with SetOutput.
+	klog.InitFlags(nil)
+	flag.Set("v", fmt.Sprintf("%d", verbosityThreshold))
+	flag.Set("log_file", "/dev/null")
+	flag.Set("logtostderr", "false")
+	flag.Set("alsologtostderr", "false")
+	flag.Set("stderrthreshold", "10")
+}
+
+type testcase struct {
+	name     string
+	generate func() interface{}
+}
+
+func BenchmarkOutput(b *testing.B) {
+	// We'll run each benchmark for different output formatting.
+	configs := map[string]struct {
+		init, cleanup func()
+	}{
+		"klog": {
+			init: func() { klog.SetOutput(discard{}) },
+		},
+		"zapr": {
+			init:    func() { klog.SetLogger(newZaprLogger()) },
+			cleanup: func() { klog.ClearLogger() },
+		},
+	}
+
+	// Each benchmark tests formatting of one key/value pair, with
+	// different values. The order is relevant here.
+	var tests []testcase
+	for length := 0; length <= 100; length += 10 {
+		arg := make([]interface{}, length)
+		for i := 0; i < length; i++ {
+			arg[i] = KMetadataMock{Name: "a", NS: "a"}
+		}
+		tests = append(tests, testcase{
+			name: fmt.Sprintf("objects/%d", length),
+			generate: func() interface{} {
+				return klog.KObjSlice(arg)
+			},
+		})
+	}
+
+	// Verbosity checks may influence the result.
+	verbosity := map[string]func(value interface{}){
+		"no-verbosity-check": func(value interface{}) {
+			klog.InfoS("test", "key", value)
+		},
+		"pass-verbosity-check": func(value interface{}) {
+			klog.V(verbosityThreshold).InfoS("test", "key", value)
+		},
+		"fail-verbosity-check": func(value interface{}) {
+			klog.V(verbosityThreshold+1).InfoS("test", "key", value)
+		},
+	}
+
+	for name, config := range configs {
+		b.Run(name, func(b *testing.B) {
+			if config.cleanup != nil {
+				defer config.cleanup()
+			}
+			config.init()
+
+			for name, logCall := range verbosity {
+				b.Run(name, func(b *testing.B) {
+					for _, testcase := range tests {
+						b.Run(testcase.name, func(b *testing.B) {
+							b.ResetTimer()
+							for i := 0; i < b.N; i++ {
+								logCall(testcase.generate())
+							}
+						})
+					}
+				})
+			}
+		})
+	}
+}
+
+func newZaprLogger() logr.Logger {
+	encoderConfig := &zapcore.EncoderConfig{
+		MessageKey:     "msg",
+		CallerKey:      "caller",
+		NameKey:        "logger",
+		EncodeDuration: zapcore.StringDurationEncoder,
+		EncodeCaller:   zapcore.ShortCallerEncoder,
+	}
+	encoder := zapcore.NewJSONEncoder(*encoderConfig)
+	zapV := -zapcore.Level(verbosityThreshold)
+	core := zapcore.NewCore(encoder, zapcore.AddSync(discard{}), zapV)
+	l := zap.New(core, zap.WithCaller(true))
+	logger := zapr.NewLoggerWithOptions(l, zapr.LogInfoLevel("v"), zapr.ErrorKey("err"))
+	return logger
+}
+
+type KMetadataMock struct {
+	Name, NS string
+}
+
+func (m KMetadataMock) GetName() string {
+	return m.Name
+}
+func (m KMetadataMock) GetNamespace() string {
+	return m.NS
+}
+
+type discard struct{}
+
+var _ io.Writer = discard{}
+
+func (discard) Write(p []byte) (int, error) {
+	return len(p), nil
+}

k8s_references.go

@@ -77,6 +77,8 @@ func KRef(namespace, name string) ObjectRef {
 }
 
 // KObjs returns slice of ObjectRef from an slice of ObjectMeta
+//
+// DEPRECATED: Use KObjSlice instead, it has better performance.
 func KObjs(arg interface{}) []ObjectRef {
 	s := reflect.ValueOf(arg)
 	if s.Kind() != reflect.Slice {
@@ -92,3 +94,65 @@ func KObjs(arg interface{}) []ObjectRef {
 	}
 	return objectRefs
 }
+
+// KObjSlice takes a slice of objects that implement the KMetadata interface
+// and returns an object that gets logged as a slice of ObjectRef values or a
+// string containing those values, depending on whether the logger prefers text
+// output or structured output.
+//
+// An error string is logged when KObjSlice is not passed a suitable slice.
+//
+// Processing of the argument is delayed until the value actually gets logged,
+// in contrast to KObjs where that overhead is incurred regardless of whether
+// the result is needed.
+func KObjSlice(arg interface{}) interface{} {
+	return kobjSlice{arg: arg}
+}
+
+type kobjSlice struct {
+	arg interface{}
+}
+
+var _ fmt.Stringer = kobjSlice{}
+var _ logr.Marshaler = kobjSlice{}
+
+func (ks kobjSlice) String() string {
+	objectRefs, err := ks.process()
+	if err != nil {
+		return err.Error()
+	}
+	return fmt.Sprintf("%v", objectRefs)
+}
+
+func (ks kobjSlice) MarshalLog() interface{} {
+	objectRefs, err := ks.process()
+	if err != nil {
+		return err.Error()
+	}
+	return objectRefs
+}
+
+func (ks kobjSlice) process() ([]interface{}, error) {
+	s := reflect.ValueOf(ks.arg)
+	switch s.Kind() {
+	case reflect.Invalid:
+		// nil parameter, print as nil.
+		return nil, nil
+	case reflect.Slice:
+		// Okay, handle below.
+	default:
+		return nil, fmt.Errorf("<KObjSlice needs a slice, got type %T>", ks.arg)
+	}
+	objectRefs := make([]interface{}, 0, s.Len())
+	for i := 0; i < s.Len(); i++ {
+		item := s.Index(i).Interface()
+		if item == nil {
+			objectRefs = append(objectRefs, nil)
+		} else if v, ok := item.(KMetadata); ok {
+			objectRefs = append(objectRefs, KObj(v))
+		} else {
+			return nil, fmt.Errorf("<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
+		}
+	}
+	return objectRefs, nil
+}

klog_test.go

@@ -631,7 +631,7 @@ func BenchmarkHeaderWithDir(b *testing.B) {
 }
 
 // Ensure that benchmarks have side effects to avoid compiler optimization
-var result ObjectRef
+var result interface{}
 var enabled bool
 
 func BenchmarkV(b *testing.B) {
@@ -659,6 +659,29 @@ func BenchmarkKObj(b *testing.B) {
 	result = r
 }
 
+// BenchmarkKObjs measures the (pretty typical) case
+// where KObjs is used in a V(5).InfoS call that never
+// emits a log entry because verbosity is lower than 5.
+// For performance when the result of KObjs gets formatted,
+// see examples/benchmarks.
+func BenchmarkKObjs(b *testing.B) {
+	for length := 0; length <= 100; length += 10 {
+		b.Run(fmt.Sprintf("%d", length), func(b *testing.B) {
+			arg := make([]interface{}, length)
+			for i := 0; i < length; i++ {
+				arg[i] = test.KMetadataMock{Name: "a", NS: "a"}
+			}
+			b.ResetTimer()
+
+			var r interface{}
+			for i := 0; i < b.N; i++ {
+				r = KObjs(arg)
+			}
+			result = r
+		})
+	}
+}
+
 func BenchmarkLogs(b *testing.B) {
 	setFlags()
 	defer logging.swap(logging.newBuffers())

test/output.go

@@ -264,6 +264,47 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 					&kmeta{Name: "pod-2", Namespace: "kube-system"},
 				})},
 			expectedOutput: `I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
+`,
+		},
+		"KObjSlice okay": {
+			text: "test",
+			values: []interface{}{"pods",
+				klog.KObjSlice([]interface{}{
+					&kmeta{Name: "pod-1", Namespace: "kube-system"},
+					&kmeta{Name: "pod-2", Namespace: "kube-system"},
+				})},
+			expectedOutput: `I output.go:<LINE>] "test" pods="[kube-system/pod-1 kube-system/pod-2]"
+`,
+		},
+		"KObjSlice nil arg": {
+			text: "test",
+			values: []interface{}{"pods",
+				klog.KObjSlice(nil)},
+			expectedOutput: `I output.go:<LINE>] "test" pods="[]"
+`,
+		},
+		"KObjSlice int arg": {
+			text: "test",
+			values: []interface{}{"pods",
+				klog.KObjSlice(1)},
+			expectedOutput: `I output.go:<LINE>] "test" pods="<KObjSlice needs a slice, got type int>"
+`,
+		},
+		"KObjSlice nil entry": {
+			text: "test",
+			values: []interface{}{"pods",
+				klog.KObjSlice([]interface{}{
+					&kmeta{Name: "pod-1", Namespace: "kube-system"},
+					nil,
+				})},
+			expectedOutput: `I output.go:<LINE>] "test" pods="[kube-system/pod-1 <nil>]"
+`,
+		},
+		"KObjSlice ints": {
+			text: "test",
+			values: []interface{}{"ints",
+				klog.KObjSlice([]int{1, 2, 3})},
+			expectedOutput: `I output.go:<LINE>] "test" ints="<KObjSlice needs a slice of values implementing KMetadata, got type int>"
 `,
 		},
 		"regular error types as value": {

test/zapr.go

@@ -71,6 +71,26 @@ func ZaprOutputMappingDirect() map[string]string {
 
 		`I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
 `: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
+`,
+
+		`I output.go:<LINE>] "test" pods="[kube-system/pod-1 kube-system/pod-2]"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
+`,
+
+		`I output.go:<LINE>] "test" pods="[]"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":null}
+`,
+
+		`I output.go:<LINE>] "test" pods="<KObjSlice needs a slice, got type int>"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":"<KObjSlice needs a slice, got type int>"}
+`,
+
+		`I output.go:<LINE>] "test" ints="<KObjSlice needs a slice of values implementing KMetadata, got type int>"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"ints":"<KObjSlice needs a slice of values implementing KMetadata, got type int>"}
+`,
+
+		`I output.go:<LINE>] "test" pods="[kube-system/pod-1 <nil>]"
+`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},null]}
 `,
 
 		`I output.go:<LINE>] "test" akey="avalue"