From 103ce8a342ef0db3a696d1d9c27b4f248cbf387e Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 10 May 2022 09:34:42 +0200 Subject: [PATCH] use faster MergeKVs 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. --- klogr.go | 8 +++---- klogr/klogr.go | 28 ++++++++++++---------- klogr/klogr_test.go | 44 ++++++++++++++++++---------------- ktesting/testinglogger.go | 10 ++++---- ktesting/testinglogger_test.go | 4 ++-- test/output.go | 16 +++++-------- test/zapr.go | 4 ++++ textlogger/textlogger.go | 5 ++-- 8 files changed, 60 insertions(+), 59 deletions(-) diff --git a/klogr.go b/klogr.go index 351d7a740..027a4014a 100644 --- a/klogr.go +++ b/klogr.go @@ -43,11 +43,11 @@ 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 { @@ -55,11 +55,11 @@ func (l klogger) Enabled(level int) bool { } 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 diff --git a/klogr/klogr.go b/klogr/klogr.go index 48cb65815..c94e551ed 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -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) @@ -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...) } } @@ -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...) } } diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 7e95b9056..22ec1dc30 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -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" `, @@ -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" `, @@ -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" `, @@ -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" `, @@ -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" `, @@ -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)" `, @@ -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)" `, @@ -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="<&>" `, @@ -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)" `, @@ -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" `, @@ -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" `, @@ -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" diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index 5269f89d2..d796f60aa 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -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) } @@ -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) } diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index cc19c3b32..6c7ae187d 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -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": { diff --git a/test/output.go b/test/output.go index bec12018d..4dd7ad407 100644 --- a/test/output.go +++ b/test/output.go @@ -212,16 +212,12 @@ I output.go:] "test" firstKey=1 secondKey=3 expectedOutput: `I output.go:] "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:] "test" akey="avalue" akey="avalue2" - // `, - // }, + "print duplicate keys in arguments": { + text: "test", + values: []interface{}{"akey", "avalue", "akey", "avalue2"}, + expectedOutput: `I output.go:] "test" akey="avalue" akey="avalue2" +`, + }, "preserve order of key/value pairs": { withValues: []interface{}{"akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"}, text: "test", diff --git a/test/zapr.go b/test/zapr.go index 20b118aad..5612d763f 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -35,6 +35,10 @@ func ZaprOutputMappingDirect() map[string]string { `I output.go:] "helper" akey="avalue" `: `{"caller":"test/output.go:","msg":"helper","v":0,"akey":"avalue"} +`, + + `I output.go:] "test" akey="avalue" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue","akey":"avalue2"} `, `I output.go:] "hello/world: test" akey="avalue" diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 2c0ec88ff..17c7584f6 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -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') }