Skip to content

Commit

Permalink
use faster MergeKVs
Browse files Browse the repository at this point in the history 
Performance is better. This slightly changes the output of the traditional
klogr format:
- all key/value pairs gets sorted, not just each slice (an improvement?)
- a single space is printed where previously two were printed

klog no longer de-duplicates when the same key is passed twice in the same
call (WithValues, InfoS, etc.). That should not occur in practice and can be
prevented via code review and/or static code analysis, so we don't need to pay
the price of checking for it at runtime.
  • Loading branch information
@pohly
pohly committed May 10, 2022
1 parent 3473ee7 commit 6b623e9
Show file tree
Hide file tree
Showing 8 changed files with 60 additions and 59 deletions.
8 changes: 4 additions & 4 deletions klogr.go
View file
Expand Up @@ -43,23 +43,23 @@ func (l *klogger) Init(info logr.RuntimeInfo) {
}

func (l klogger) Info(level int, msg string, kvList ...interface{}) {
trimmed := serialize.TrimDuplicates(l.values, kvList)
merged := serialize.MergeKVs(l.values, kvList)
if l.prefix != "" {
msg = l.prefix + ": " + msg
}
V(Level(level)).InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...)
V(Level(level)).InfoSDepth(l.callDepth+1, msg, merged...)
}

func (l klogger) Enabled(level int) bool {
return V(Level(level)).Enabled()
}

func (l klogger) Error(err error, msg string, kvList ...interface{}) {
trimmed := serialize.TrimDuplicates(l.values, kvList)
merged := serialize.MergeKVs(l.values, kvList)
if l.prefix != "" {
msg = l.prefix + ": " + msg
}
ErrorSDepth(l.callDepth+1, err, msg, append(trimmed[0], trimmed[1]...)...)
ErrorSDepth(l.callDepth+1, err, msg, merged...)
}

// WithName returns a new logr.Logger with the specified name appended. klogr
Expand Down
28 changes: 15 additions & 13 deletions klogr/klogr.go
View file
Expand Up @@ -85,7 +85,11 @@ func flatten(kvList ...interface{}) string {
if i+1 < len(kvList) {
v = kvList[i+1]
}
keys = append(keys, k)
// Only print each key once...
if _, seen := vals[k]; !seen {
keys = append(keys, k)
}
// ... with the latest value.
vals[k] = v
}
sort.Strings(keys)
Expand Down Expand Up @@ -119,16 +123,15 @@ func (l klogger) Info(level int, msg string, kvList ...interface{}) {
switch l.format {
case FormatSerialize:
msgStr := flatten("msg", msg)
trimmed := serialize.TrimDuplicates(l.values, kvList)
fixedStr := flatten(trimmed[0]...)
userStr := flatten(trimmed[1]...)
klog.V(klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
merged := serialize.MergeKVs(l.values, kvList)
kvStr := flatten(merged...)
klog.V(klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", kvStr)
case FormatKlog:
trimmed := serialize.TrimDuplicates(l.values, kvList)
merged := serialize.MergeKVs(l.values, kvList)
if l.prefix != "" {
msg = l.prefix + ": " + msg
}
klog.V(klog.Level(level)).InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...)
klog.V(klog.Level(level)).InfoSDepth(l.callDepth+1, msg, merged...)
}
}

Expand All @@ -145,16 +148,15 @@ func (l klogger) Error(err error, msg string, kvList ...interface{}) {
switch l.format {
case FormatSerialize:
errStr := flatten("error", loggableErr)
trimmed := serialize.TrimDuplicates(l.values, kvList)
fixedStr := flatten(trimmed[0]...)
userStr := flatten(trimmed[1]...)
klog.ErrorDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr)
merged := serialize.MergeKVs(l.values, kvList)
kvStr := flatten(merged...)
klog.ErrorDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", errStr, " ", kvStr)
case FormatKlog:
trimmed := serialize.TrimDuplicates(l.values, kvList)
merged := serialize.MergeKVs(l.values, kvList)
if l.prefix != "" {
msg = l.prefix + ": " + msg
}
klog.ErrorSDepth(l.callDepth+1, err, msg, append(trimmed[0], trimmed[1]...)...)
klog.ErrorSDepth(l.callDepth+1, err, msg, merged...)
}
}

Expand Down
44 changes: 23 additions & 21 deletions klogr/klogr_test.go
View file
Expand Up @@ -41,7 +41,7 @@ func testOutput(t *testing.T, format string) {
klogr: new().V(0),
text: "test",
keysAndValues: []interface{}{"akey", "avalue"},
expectedOutput: ` "msg"="test" "akey"="avalue"
expectedOutput: ` "msg"="test" "akey"="avalue"
`,
expectedKlogOutput: `"test" akey="avalue"
`,
Expand All @@ -50,7 +50,7 @@ func testOutput(t *testing.T, format string) {
klogr: new().V(0).WithName("me"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue"},
expectedOutput: `me "msg"="test" "akey"="avalue"
expectedOutput: `me "msg"="test" "akey"="avalue"
`,
expectedKlogOutput: `"me: test" akey="avalue"
`,
Expand All @@ -59,34 +59,34 @@ func testOutput(t *testing.T, format string) {
klogr: new().V(0).WithName("hello").WithName("world"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue"},
expectedOutput: `hello/world "msg"="test" "akey"="avalue"
expectedOutput: `hello/world "msg"="test" "akey"="avalue"
`,
expectedKlogOutput: `"hello/world: test" akey="avalue"
`,
},
"should not print duplicate keys with the same value": {
"may print duplicate keys with the same value": {
klogr: new().V(0),
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
expectedOutput: ` "msg"="test" "akey"="avalue"
expectedOutput: ` "msg"="test" "akey"="avalue"
`,
expectedKlogOutput: `"test" akey="avalue"
expectedKlogOutput: `"test" akey="avalue" akey="avalue"
`,
},
"should only print the last duplicate key when the values are passed to Info": {
"may print duplicate keys when the values are passed to Info": {
klogr: new().V(0),
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
expectedOutput: ` "msg"="test" "akey"="avalue2"
expectedOutput: ` "msg"="test" "akey"="avalue2"
`,
expectedKlogOutput: `"test" akey="avalue2"
expectedKlogOutput: `"test" akey="avalue" akey="avalue2"
`,
},
"should only print the duplicate key that is passed to Info if one was passed to the logger": {
klogr: new().WithValues("akey", "avalue"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue"},
expectedOutput: ` "msg"="test" "akey"="avalue"
expectedOutput: ` "msg"="test" "akey"="avalue"
`,
expectedKlogOutput: `"test" akey="avalue"
`,
Expand All @@ -95,7 +95,7 @@ func testOutput(t *testing.T, format string) {
klogr: new().WithValues("akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"),
text: "test",
keysAndValues: []interface{}{"akey5", "avalue5", "akey4", "avalue4"},
expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey8"="avalue8" "akey9"="avalue9" "akey4"="avalue4" "akey5"="avalue5"
expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey4"="avalue4" "akey5"="avalue5" "akey8"="avalue8" "akey9"="avalue9"
`,
expectedKlogOutput: `"test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4"
`,
Expand All @@ -104,7 +104,7 @@ func testOutput(t *testing.T, format string) {
klogr: new().WithValues("akey", "avalue"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue2"},
expectedOutput: ` "msg"="test" "akey"="avalue2"
expectedOutput: ` "msg"="test" "akey"="avalue2"
`,
expectedKlogOutput: `"test" akey="avalue2"
`,
Expand All @@ -113,7 +113,7 @@ func testOutput(t *testing.T, format string) {
klogr: new(),
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)"
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)"
`,
expectedKlogOutput: `"test" akey="avalue" akey2="(MISSING)"
`,
Expand All @@ -122,7 +122,8 @@ func testOutput(t *testing.T, format string) {
klogr: new().WithValues("keyWithoutValue"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
expectedOutput: ` "msg"="test" "keyWithoutValue"="(MISSING)" "akey"="avalue" "akey2"="(MISSING)"
// klogr format sorts all key/value pairs.
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "keyWithoutValue"="(MISSING)"
`,
expectedKlogOutput: `"test" keyWithoutValue="(MISSING)" akey="avalue" akey2="(MISSING)"
`,
Expand All @@ -131,7 +132,7 @@ func testOutput(t *testing.T, format string) {
klogr: new(),
text: "test",
keysAndValues: []interface{}{"akey", "<&>"},
expectedOutput: ` "msg"="test" "akey"="<&>"
expectedOutput: ` "msg"="test" "akey"="<&>"
`,
expectedKlogOutput: `"test" akey="<&>"
`,
Expand All @@ -140,7 +141,8 @@ func testOutput(t *testing.T, format string) {
klogr: new().WithValues("basekey1", "basevar1", "basekey2"),
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
expectedOutput: ` "msg"="test" "basekey1"="basevar1" "basekey2"="(MISSING)" "akey"="avalue" "akey2"="(MISSING)"
// klogr format sorts all key/value pairs.
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "basekey1"="basevar1" "basekey2"="(MISSING)"
`,
expectedKlogOutput: `"test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
`,
Expand All @@ -149,7 +151,7 @@ func testOutput(t *testing.T, format string) {
klogr: new().V(0),
text: "test",
keysAndValues: []interface{}{"err", errors.New("whoops")},
expectedOutput: ` "msg"="test" "err"="whoops"
expectedOutput: ` "msg"="test" "err"="whoops"
`,
expectedKlogOutput: `"test" err="whoops"
`,
Expand All @@ -158,7 +160,7 @@ func testOutput(t *testing.T, format string) {
klogr: new().V(0),
text: "test",
keysAndValues: []interface{}{"err", &customErrorJSON{"whoops"}},
expectedOutput: ` "msg"="test" "err"="WHOOPS"
expectedOutput: ` "msg"="test" "err"="WHOOPS"
`,
expectedKlogOutput: `"test" err="whoops"
`,
Expand All @@ -168,9 +170,9 @@ func testOutput(t *testing.T, format string) {
text: "test",
err: errors.New("whoops"),
// The message is printed to three different log files (info, warning, error), so we see it three times in our output buffer.
expectedOutput: ` "msg"="test" "error"="whoops"
"msg"="test" "error"="whoops"
"msg"="test" "error"="whoops"
expectedOutput: ` "msg"="test" "error"="whoops"
"msg"="test" "error"="whoops"
"msg"="test" "error"="whoops"
`,
expectedKlogOutput: `"test" err="whoops"
"test" err="whoops"
Expand Down
10 changes: 4 additions & 6 deletions ktesting/testinglogger.go
View file
Expand Up @@ -81,9 +81,8 @@ func (l *tlogger) GetCallStackHelper() func() {
func (l *tlogger) Info(level int, msg string, kvList ...interface{}) {
l.t.Helper()
buffer := &bytes.Buffer{}
trimmed := serialize.TrimDuplicates(l.values, kvList)
serialize.KVListFormat(buffer, trimmed[0]...)
serialize.KVListFormat(buffer, trimmed[1]...)
merged := serialize.MergeKVs(l.values, kvList)
serialize.KVListFormat(buffer, merged...)
l.log("INFO", msg, buffer)
}

Expand All @@ -97,9 +96,8 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) {
if err != nil {
serialize.KVListFormat(buffer, "err", err)
}
trimmed := serialize.TrimDuplicates(l.values, kvList)
serialize.KVListFormat(buffer, trimmed[0]...)
serialize.KVListFormat(buffer, trimmed[1]...)
merged := serialize.MergeKVs(l.values, kvList)
serialize.KVListFormat(buffer, merged...)
l.log("ERROR", msg, buffer)
}

Expand Down
4 changes: 2 additions & 2 deletions ktesting/testinglogger_test.go
View file
Expand Up @@ -46,13 +46,13 @@ func TestInfo(t *testing.T) {
"should not print duplicate keys with the same value": {
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
expectedOutput: `INFO test akey="avalue"
expectedOutput: `INFO test akey="avalue" akey="avalue"
`,
},
"should only print the last duplicate key when the values are passed to Info": {
text: "test",
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
expectedOutput: `INFO test akey="avalue2"
expectedOutput: `INFO test akey="avalue" akey="avalue2"
`,
},
"should only print the duplicate key that is passed to Info if one was passed to the logger": {
Expand Down
16 changes: 6 additions & 10 deletions test/output.go
View file
Expand Up @@ -212,16 +212,12 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
expectedOutput: `I output.go:<LINE>] "test"
`,
},
// TODO: unify behavior of loggers.
// klog doesn't deduplicate, klogr and textlogger do. We can ensure via static code analysis
// that this doesn't occur, so we shouldn't pay the runtime overhead for deduplication here
// and remove that from klogr and textlogger (https://github.com/kubernetes/klog/issues/286).
// "print duplicate keys in arguments": {
// text: "test",
// values: []interface{}{"akey", "avalue", "akey", "avalue2"},
// expectedOutput: `I output.go:<LINE>] "test" akey="avalue" akey="avalue2"
// `,
// },
"print duplicate keys in arguments": {
text: "test",
values: []interface{}{"akey", "avalue", "akey", "avalue2"},
expectedOutput: `I output.go:<LINE>] "test" akey="avalue" akey="avalue2"
`,
},
"preserve order of key/value pairs": {
withValues: []interface{}{"akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"},
text: "test",
Expand Down
4 changes: 4 additions & 0 deletions test/zapr.go
View file
Expand Up @@ -35,6 +35,10 @@ func ZaprOutputMappingDirect() map[string]string {

`I output.go:<LINE>] "helper" akey="avalue"
`: `{"caller":"test/output.go:<LINE>","msg":"helper","v":0,"akey":"avalue"}
`,

`I output.go:<LINE>] "test" akey="avalue" akey="avalue2"
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"akey":"avalue","akey":"avalue2"}
`,

`I output.go:<LINE>] "hello/world: test" akey="avalue"
Expand Down
5 changes: 2 additions & 3 deletions textlogger/textlogger.go
View file
Expand Up @@ -132,9 +132,8 @@ func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []int
if err != nil {
serialize.KVListFormat(&b.Buffer, "err", err)
}
trimmed := serialize.TrimDuplicates(l.values, kvList)
serialize.KVListFormat(&b.Buffer, trimmed[0]...)
serialize.KVListFormat(&b.Buffer, trimmed[1]...)
merged := serialize.MergeKVs(l.values, kvList)
serialize.KVListFormat(&b.Buffer, merged...)
if b.Len() == 0 || b.Bytes()[b.Len()-1] != '\n' {
b.WriteByte('\n')
}
Expand Down

0 comments on commit 6b623e9

Please sign in to comment.