From 4e938720996edad4b3f4e5375301e122955d5cdd Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 22 Dec 2022 18:19:13 +0100 Subject: [PATCH] KObj, KObjSlice: format more efficiently as text MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The klog text format avoids some string allocation by calling WriteText instead of String when encountering such values. A positive side effect is that KObjSlice now gets logged like KObjs, i.e. pods=[namespace1/name1 namespace2/name2] Previously, it was written as a quoted string. To achieve the best performance, WriteText is passed a bytes.Buffer pointer instead of a io.Writer. This avoids an interface allocation for the parameter and provides access to the underlying methods. Benchmarks involving these types benefit while other are the same as before: name old time/op new time/op delta KlogOutput/KObj-36 12.7µs ±10% 13.1µs ± 1% ~ (p=0.151 n=5+5) KlogOutput/KObjs-36 13.4µs ± 7% 14.0µs ± 5% ~ (p=0.310 n=5+5) KlogOutput/KObjSlice_okay-36 14.8µs ± 4% 13.0µs ± 3% -12.33% (p=0.008 n=5+5) KlogOutput/KObjSlice_int_arg-36 14.0µs ± 6% 12.3µs ±10% -12.60% (p=0.008 n=5+5) KlogOutput/KObjSlice_ints-36 15.5µs ± 4% 12.8µs ± 6% -17.85% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_entry-36 14.2µs ±13% 12.6µs ± 3% -11.39% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_arg-36 12.6µs ± 6% 12.9µs ± 3% ~ (p=0.690 n=5+5) name old alloc/op new alloc/op delta KlogOutput/KObj-36 2.47kB ± 0% 2.41kB ± 0% -2.29% (p=0.008 n=5+5) KlogOutput/KObjs-36 2.65kB ± 0% 2.65kB ± 0% ~ (all equal) KlogOutput/KObjSlice_okay-36 2.82kB ± 0% 2.45kB ± 0% -13.37% (p=0.008 n=5+5) KlogOutput/KObjSlice_int_arg-36 2.67kB ± 0% 2.45kB ± 0% -8.42% (p=0.029 n=4+4) KlogOutput/KObjSlice_ints-36 2.90kB ± 0% 2.49kB ± 0% -14.37% (p=0.000 n=4+5) KlogOutput/KObjSlice_nil_entry-36 2.62kB ± 0% 2.43kB ± 0% -7.34% (p=0.000 n=4+5) KlogOutput/KObjSlice_nil_arg-36 2.41kB ± 0% 2.40kB ± 0% -0.66% (p=0.016 n=5+4) name old allocs/op new allocs/op delta KlogOutput/KObj-36 34.0 ± 0% 32.0 ± 0% -5.88% (p=0.008 n=5+5) KlogOutput/KObjs-36 38.0 ± 0% 38.0 ± 0% ~ (all equal) KlogOutput/KObjSlice_okay-36 42.0 ± 0% 32.0 ± 0% -23.81% (p=0.008 n=5+5) KlogOutput/KObjSlice_int_arg-36 37.0 ± 0% 32.0 ± 0% -13.51% (p=0.008 n=5+5) KlogOutput/KObjSlice_ints-36 39.0 ± 0% 33.0 ± 0% -15.38% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_entry-36 38.0 ± 0% 32.0 ± 0% -15.79% (p=0.008 n=5+5) KlogOutput/KObjSlice_nil_arg-36 35.0 ± 0% 32.0 ± 0% -8.57% (p=0.008 n=5+5) --- internal/serialize/keyvalues.go | 16 ++++++++ k8s_references.go | 70 +++++++++++++++++++++++++++------ test/output.go | 10 ++--- test/zapr.go | 12 ++---- 4 files changed, 84 insertions(+), 24 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index 0bff64d04..f9558c3d2 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -24,6 +24,10 @@ import ( "github.com/go-logr/logr" ) +type textWriter interface { + WriteText(*bytes.Buffer) +} + // WithValues implements LogSink.WithValues. The old key/value pairs are // assumed to be well-formed, the new ones are checked and padded if // necessary. It returns a new slice. @@ -175,6 +179,8 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) { // than plain strings // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). switch v := v.(type) { + case textWriter: + writeTextWriterValue(b, v) case fmt.Stringer: writeStringValue(b, true, StringerToString(v)) case string: @@ -254,6 +260,16 @@ func ErrorToString(err error) (ret string) { return } +func writeTextWriterValue(b *bytes.Buffer, v textWriter) { + b.WriteRune('=') + defer func() { + if err := recover(); err != nil { + fmt.Fprintf(b, `""`, err) + } + }() + v.WriteText(b) +} + func writeStringValue(b *bytes.Buffer, quote bool, v string) { data := []byte(v) index := bytes.IndexByte(data, '\n') diff --git a/k8s_references.go b/k8s_references.go index a6436b5d1..ecd3f8b69 100644 --- a/k8s_references.go +++ b/k8s_references.go @@ -17,6 +17,7 @@ limitations under the License. package klog import ( + "bytes" "fmt" "reflect" "strings" @@ -42,6 +43,20 @@ func (ref ObjectRef) String() string { return ref.Name } +func (ref ObjectRef) WriteText(out *bytes.Buffer) { + out.WriteRune('"') + ref.writeUnquoted(out) + out.WriteRune('"') +} + +func (ref ObjectRef) writeUnquoted(out *bytes.Buffer) { + if ref.Namespace != "" { + out.WriteString(ref.Namespace) + out.WriteRune('/') + } + out.WriteString(ref.Name) +} + // MarshalLog ensures that loggers with support for structured output will log // as a struct by removing the String method via a custom type. func (ref ObjectRef) MarshalLog() interface{} { @@ -123,31 +138,31 @@ var _ fmt.Stringer = kobjSlice{} var _ logr.Marshaler = kobjSlice{} func (ks kobjSlice) String() string { - objectRefs, err := ks.process() - if err != nil { - return err.Error() + objectRefs, errStr := ks.process() + if errStr != "" { + return errStr } return fmt.Sprintf("%v", objectRefs) } func (ks kobjSlice) MarshalLog() interface{} { - objectRefs, err := ks.process() - if err != nil { - return err.Error() + objectRefs, errStr := ks.process() + if errStr != "" { + return errStr } return objectRefs } -func (ks kobjSlice) process() ([]interface{}, error) { +func (ks kobjSlice) process() (objs []interface{}, err string) { s := reflect.ValueOf(ks.arg) switch s.Kind() { case reflect.Invalid: // nil parameter, print as nil. - return nil, nil + return nil, "" case reflect.Slice: // Okay, handle below. default: - return nil, fmt.Errorf("", ks.arg) + return nil, fmt.Sprintf("", ks.arg) } objectRefs := make([]interface{}, 0, s.Len()) for i := 0; i < s.Len(); i++ { @@ -157,8 +172,41 @@ func (ks kobjSlice) process() ([]interface{}, error) { } else if v, ok := item.(KMetadata); ok { objectRefs = append(objectRefs, KObj(v)) } else { - return nil, fmt.Errorf("", item) + return nil, fmt.Sprintf("", item) + } + } + return objectRefs, "" +} + +var nilToken = []byte("") + +func (ks kobjSlice) WriteText(out *bytes.Buffer) { + s := reflect.ValueOf(ks.arg) + switch s.Kind() { + case reflect.Invalid: + // nil parameter, print as empty slice. + out.WriteString("[]") + return + case reflect.Slice: + // Okay, handle below. + default: + fmt.Fprintf(out, `""`, ks.arg) + return + } + out.Write([]byte{'['}) + defer out.Write([]byte{']'}) + for i := 0; i < s.Len(); i++ { + if i > 0 { + out.Write([]byte{' '}) + } + item := s.Index(i).Interface() + if item == nil { + out.Write(nilToken) + } else if v, ok := item.(KMetadata); ok { + KObj(v).writeUnquoted(out) + } else { + fmt.Fprintf(out, "", item) + return } } - return objectRefs, nil } diff --git a/test/output.go b/test/output.go index 99aedb6e7..00f846172 100644 --- a/test/output.go +++ b/test/output.go @@ -290,14 +290,14 @@ I output.go:] "test" firstKey=1 secondKey=3 &kmeta{Name: "pod-1", Namespace: "kube-system"}, &kmeta{Name: "pod-2", Namespace: "kube-system"}, })}, - expectedOutput: `I output.go:] "test" pods="[kube-system/pod-1 kube-system/pod-2]" + expectedOutput: `I output.go:] "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:] "test" pods="[]" + expectedOutput: `I output.go:] "test" pods=[] `, }, "KObjSlice int arg": { @@ -314,14 +314,14 @@ I output.go:] "test" firstKey=1 secondKey=3 &kmeta{Name: "pod-1", Namespace: "kube-system"}, nil, })}, - expectedOutput: `I output.go:] "test" pods="[kube-system/pod-1 ]" + expectedOutput: `I output.go:] "test" pods=[kube-system/pod-1 ] `, }, "KObjSlice ints": { text: "test", values: []interface{}{"ints", klog.KObjSlice([]int{1, 2, 3})}, - expectedOutput: `I output.go:] "test" ints="" + expectedOutput: `I output.go:] "test" ints=[] `, }, "regular error types as value": { @@ -357,7 +357,7 @@ I output.go:] "test" firstKey=1 secondKey=3 "MarshalLog() for nil": { text: "marshaler nil", values: []interface{}{"obj", (*klog.ObjectRef)(nil)}, - expectedOutput: `I output.go:] "marshaler nil" obj="" + expectedOutput: `I output.go:] "marshaler nil" obj="" `, }, "Error() that panics": { diff --git a/test/zapr.go b/test/zapr.go index 9f6cd8b4c..ce4737892 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -73,11 +73,7 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]} `, - `I output.go:] "test" pods="[kube-system/pod-1 kube-system/pod-2]" -`: `{"caller":"test/output.go:","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]} -`, - - `I output.go:] "test" pods="[]" + `I output.go:] "test" pods=[] `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":null} `, @@ -85,11 +81,11 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":""} `, - `I output.go:] "test" ints="" + `I output.go:] "test" ints=[] `: `{"caller":"test/output.go:","msg":"test","v":0,"ints":""} `, - `I output.go:] "test" pods="[kube-system/pod-1 ]" + `I output.go:] "test" pods=[kube-system/pod-1 ] `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},null]} `, @@ -140,7 +136,7 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" {"caller":"test/output.go:","msg":"both odd","basekey1":"basevar1","v":0,"akey":"avalue"} `, - `I output.go:] "marshaler nil" obj="" + `I output.go:] "marshaler nil" obj="" `: `{"caller":"test/output.go:","msg":"marshaler nil","v":0,"objError":"PANIC=value method k8s.io/klog/v2.ObjectRef.MarshalLog called using nil *ObjectRef pointer"} `,