Skip to content

Commit

Permalink
KObj, KObjSlice: format more efficiently as text
Browse files Browse the repository at this point in the history 
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)
  • Loading branch information
@pohly
pohly committed Dec 23, 2022
1 parent 82f7e19 commit a1eb2d7
Show file tree
Hide file tree
Showing 4 changed files with 84 additions and 24 deletions.
16 changes: 16 additions & 0 deletions internal/serialize/keyvalues.go
View file
Expand Up @@ -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.
Expand Down Expand Up @@ -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:
Expand Down Expand Up @@ -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, `"<panic: %s>"`, err)
}
}()
v.WriteText(b)
}

func writeStringValue(b *bytes.Buffer, quote bool, v string) {
data := []byte(v)
index := bytes.IndexByte(data, '\n')
Expand Down
70 changes: 59 additions & 11 deletions k8s_references.go
View file
Expand Up @@ -17,6 +17,7 @@ limitations under the License.
package klog

import (
"bytes"
"fmt"
"reflect"
"strings"
Expand All @@ -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{} {
Expand Down Expand Up @@ -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("<KObjSlice needs a slice, got type %T>", ks.arg)
return nil, fmt.Sprintf("<KObjSlice needs a slice, got type %T>", ks.arg)
}
objectRefs := make([]interface{}, 0, s.Len())
for i := 0; i < s.Len(); i++ {
Expand All @@ -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("<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
return nil, fmt.Sprintf("<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
}
}
return objectRefs, ""
}

var nilToken = []byte("<nil>")

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, `"<KObjSlice needs a slice, got type %T>"`, 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, "<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
return
}
}
return objectRefs, nil
}
10 changes: 5 additions & 5 deletions test/output.go
View file
Expand Up @@ -290,14 +290,14 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
&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]"
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="[]"
expectedOutput: `I output.go:<LINE>] "test" pods=[]
`,
},
"KObjSlice int arg": {
Expand All @@ -314,14 +314,14 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
&kmeta{Name: "pod-1", Namespace: "kube-system"},
nil,
})},
expectedOutput: `I output.go:<LINE>] "test" pods="[kube-system/pod-1 <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>"
expectedOutput: `I output.go:<LINE>] "test" ints=[<KObjSlice needs a slice of values implementing KMetadata, got type int>]
`,
},
"regular error types as value": {
Expand Down Expand Up @@ -357,7 +357,7 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
"MarshalLog() for nil": {
text: "marshaler nil",
values: []interface{}{"obj", (*klog.ObjectRef)(nil)},
expectedOutput: `I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.String called using nil *ObjectRef pointer>"
expectedOutput: `I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.WriteText called using nil *ObjectRef pointer>"
`,
},
"Error() that panics": {
Expand Down
12 changes: 4 additions & 8 deletions test/zapr.go
View file
Expand Up @@ -73,23 +73,19 @@ func ZaprOutputMappingDirect() map[string]string {
`: `{"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="[]"
`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>"
`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>]"
`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]}
`,

Expand Down Expand Up @@ -140,7 +136,7 @@ I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
{"caller":"test/output.go:<LINE>","msg":"both odd","basekey1":"basevar1","v":0,"akey":"avalue"}
`,

`I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.String called using nil *ObjectRef pointer>"
`I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.WriteText called using nil *ObjectRef pointer>"
`: `{"caller":"test/output.go:<LINE>","msg":"marshaler nil","v":0,"objError":"PANIC=value method k8s.io/klog/v2.ObjectRef.MarshalLog called using nil *ObjectRef pointer"}
`,

Expand Down

0 comments on commit a1eb2d7

Please sign in to comment.