Skip to content

Commit 8eadf2c

Browse files
pohlydims
pohly
authored and
dims
committed
KObj, KObjSlice: format more efficiently as text
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)
1 parent a1638bf commit 8eadf2c

File tree

4 files changed

+84
-24
lines changed

4 files changed

+84
-24
lines changed

‎internal/serialize/keyvalues.go

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,10 @@ import (
2424
"github.com/go-logr/logr"
2525
)
2626

27+
type textWriter interface {
28+
WriteText(*bytes.Buffer)
29+
}
30+
2731
// WithValues implements LogSink.WithValues. The old key/value pairs are
2832
// assumed to be well-formed, the new ones are checked and padded if
2933
// necessary. It returns a new slice.
@@ -175,6 +179,8 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) {
175179
// than plain strings
176180
// (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235).
177181
switch v := v.(type) {
182+
case textWriter:
183+
writeTextWriterValue(b, v)
178184
case fmt.Stringer:
179185
writeStringValue(b, true, StringerToString(v))
180186
case string:
@@ -254,6 +260,16 @@ func ErrorToString(err error) (ret string) {
254260
return
255261
}
256262

263+
func writeTextWriterValue(b *bytes.Buffer, v textWriter) {
264+
b.WriteRune('=')
265+
defer func() {
266+
if err := recover(); err != nil {
267+
fmt.Fprintf(b, `"<panic: %s>"`, err)
268+
}
269+
}()
270+
v.WriteText(b)
271+
}
272+
257273
func writeStringValue(b *bytes.Buffer, quote bool, v string) {
258274
data := []byte(v)
259275
index := bytes.IndexByte(data, '\n')

‎k8s_references.go

Lines changed: 59 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ limitations under the License.
1717
package klog
1818

1919
import (
20+
"bytes"
2021
"fmt"
2122
"reflect"
2223
"strings"
@@ -42,6 +43,20 @@ func (ref ObjectRef) String() string {
4243
return ref.Name
4344
}
4445

46+
func (ref ObjectRef) WriteText(out *bytes.Buffer) {
47+
out.WriteRune('"')
48+
ref.writeUnquoted(out)
49+
out.WriteRune('"')
50+
}
51+
52+
func (ref ObjectRef) writeUnquoted(out *bytes.Buffer) {
53+
if ref.Namespace != "" {
54+
out.WriteString(ref.Namespace)
55+
out.WriteRune('/')
56+
}
57+
out.WriteString(ref.Name)
58+
}
59+
4560
// MarshalLog ensures that loggers with support for structured output will log
4661
// as a struct by removing the String method via a custom type.
4762
func (ref ObjectRef) MarshalLog() interface{} {
@@ -123,31 +138,31 @@ var _ fmt.Stringer = kobjSlice{}
123138
var _ logr.Marshaler = kobjSlice{}
124139

125140
func (ks kobjSlice) String() string {
126-
objectRefs, err := ks.process()
127-
if err != nil {
128-
return err.Error()
141+
objectRefs, errStr := ks.process()
142+
if errStr != "" {
143+
return errStr
129144
}
130145
return fmt.Sprintf("%v", objectRefs)
131146
}
132147

133148
func (ks kobjSlice) MarshalLog() interface{} {
134-
objectRefs, err := ks.process()
135-
if err != nil {
136-
return err.Error()
149+
objectRefs, errStr := ks.process()
150+
if errStr != "" {
151+
return errStr
137152
}
138153
return objectRefs
139154
}
140155

141-
func (ks kobjSlice) process() ([]interface{}, error) {
156+
func (ks kobjSlice) process() (objs []interface{}, err string) {
142157
s := reflect.ValueOf(ks.arg)
143158
switch s.Kind() {
144159
case reflect.Invalid:
145160
// nil parameter, print as nil.
146-
return nil, nil
161+
return nil, ""
147162
case reflect.Slice:
148163
// Okay, handle below.
149164
default:
150-
return nil, fmt.Errorf("<KObjSlice needs a slice, got type %T>", ks.arg)
165+
return nil, fmt.Sprintf("<KObjSlice needs a slice, got type %T>", ks.arg)
151166
}
152167
objectRefs := make([]interface{}, 0, s.Len())
153168
for i := 0; i < s.Len(); i++ {
@@ -157,8 +172,41 @@ func (ks kobjSlice) process() ([]interface{}, error) {
157172
} else if v, ok := item.(KMetadata); ok {
158173
objectRefs = append(objectRefs, KObj(v))
159174
} else {
160-
return nil, fmt.Errorf("<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
175+
return nil, fmt.Sprintf("<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
176+
}
177+
}
178+
return objectRefs, ""
179+
}
180+
181+
var nilToken = []byte("<nil>")
182+
183+
func (ks kobjSlice) WriteText(out *bytes.Buffer) {
184+
s := reflect.ValueOf(ks.arg)
185+
switch s.Kind() {
186+
case reflect.Invalid:
187+
// nil parameter, print as empty slice.
188+
out.WriteString("[]")
189+
return
190+
case reflect.Slice:
191+
// Okay, handle below.
192+
default:
193+
fmt.Fprintf(out, `"<KObjSlice needs a slice, got type %T>"`, ks.arg)
194+
return
195+
}
196+
out.Write([]byte{'['})
197+
defer out.Write([]byte{']'})
198+
for i := 0; i < s.Len(); i++ {
199+
if i > 0 {
200+
out.Write([]byte{' '})
201+
}
202+
item := s.Index(i).Interface()
203+
if item == nil {
204+
out.Write(nilToken)
205+
} else if v, ok := item.(KMetadata); ok {
206+
KObj(v).writeUnquoted(out)
207+
} else {
208+
fmt.Fprintf(out, "<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
209+
return
161210
}
162211
}
163-
return objectRefs, nil
164212
}

‎test/output.go

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -290,14 +290,14 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
290290
&kmeta{Name: "pod-1", Namespace: "kube-system"},
291291
&kmeta{Name: "pod-2", Namespace: "kube-system"},
292292
})},
293-
expectedOutput: `I output.go:<LINE>] "test" pods="[kube-system/pod-1 kube-system/pod-2]"
293+
expectedOutput: `I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
294294
`,
295295
},
296296
"KObjSlice nil arg": {
297297
text: "test",
298298
values: []interface{}{"pods",
299299
klog.KObjSlice(nil)},
300-
expectedOutput: `I output.go:<LINE>] "test" pods="[]"
300+
expectedOutput: `I output.go:<LINE>] "test" pods=[]
301301
`,
302302
},
303303
"KObjSlice int arg": {
@@ -314,14 +314,14 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
314314
&kmeta{Name: "pod-1", Namespace: "kube-system"},
315315
nil,
316316
})},
317-
expectedOutput: `I output.go:<LINE>] "test" pods="[kube-system/pod-1 <nil>]"
317+
expectedOutput: `I output.go:<LINE>] "test" pods=[kube-system/pod-1 <nil>]
318318
`,
319319
},
320320
"KObjSlice ints": {
321321
text: "test",
322322
values: []interface{}{"ints",
323323
klog.KObjSlice([]int{1, 2, 3})},
324-
expectedOutput: `I output.go:<LINE>] "test" ints="<KObjSlice needs a slice of values implementing KMetadata, got type int>"
324+
expectedOutput: `I output.go:<LINE>] "test" ints=[<KObjSlice needs a slice of values implementing KMetadata, got type int>]
325325
`,
326326
},
327327
"regular error types as value": {
@@ -357,7 +357,7 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
357357
"MarshalLog() for nil": {
358358
text: "marshaler nil",
359359
values: []interface{}{"obj", (*klog.ObjectRef)(nil)},
360-
expectedOutput: `I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.String called using nil *ObjectRef pointer>"
360+
expectedOutput: `I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.WriteText called using nil *ObjectRef pointer>"
361361
`,
362362
},
363363
"Error() that panics": {

‎test/zapr.go

Lines changed: 4 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -73,23 +73,19 @@ func ZaprOutputMappingDirect() map[string]string {
7373
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
7474
`,
7575

76-
`I output.go:<LINE>] "test" pods="[kube-system/pod-1 kube-system/pod-2]"
77-
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
78-
`,
79-
80-
`I output.go:<LINE>] "test" pods="[]"
76+
`I output.go:<LINE>] "test" pods=[]
8177
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":null}
8278
`,
8379

8480
`I output.go:<LINE>] "test" pods="<KObjSlice needs a slice, got type int>"
8581
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":"<KObjSlice needs a slice, got type int>"}
8682
`,
8783

88-
`I output.go:<LINE>] "test" ints="<KObjSlice needs a slice of values implementing KMetadata, got type int>"
84+
`I output.go:<LINE>] "test" ints=[<KObjSlice needs a slice of values implementing KMetadata, got type int>]
8985
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"ints":"<KObjSlice needs a slice of values implementing KMetadata, got type int>"}
9086
`,
9187

92-
`I output.go:<LINE>] "test" pods="[kube-system/pod-1 <nil>]"
88+
`I output.go:<LINE>] "test" pods=[kube-system/pod-1 <nil>]
9389
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},null]}
9490
`,
9591

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

143-
`I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.String called using nil *ObjectRef pointer>"
139+
`I output.go:<LINE>] "marshaler nil" obj="<panic: value method k8s.io/klog/v2.ObjectRef.WriteText called using nil *ObjectRef pointer>"
144140
`: `{"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"}
145141
`,
146142

0 commit comments

Comments
 (0)