Merge pull request #324 from pohly/trim-duplicates

Trim duplicates

internal/serialize/keyvalues.go

@@ -93,6 +93,51 @@ func TrimDuplicates(kvLists ...[]interface{}) [][]interface{} {
 	return outs
 }
 
+// MergeKVs deduplicates elements provided in two key/value slices.
+//
+// Keys in each slice are expected to be unique, so duplicates can only occur
+// when the first and second slice contain the same key. When that happens, the
+// key/value pair from the second slice is used. The first slice must be well-formed
+// (= even key/value pairs). The second one may have a missing value, in which
+// case the special "missing value" is added to the result.
+func MergeKVs(first, second []interface{}) []interface{} {
+	maxLength := len(first) + (len(second)+1)/2*2
+	if maxLength == 0 {
+		// Nothing to do at all.
+		return nil
+	}
+
+	if len(first) == 0 && len(second)%2 == 0 {
+		// Nothing to be overridden, second slice is well-formed
+		// and can be used directly.
+		return second
+	}
+
+	// Determine which keys are in the second slice so that we can skip
+	// them when iterating over the first one. The code intentionally
+	// favors performance over completeness: we assume that keys are string
+	// constants and thus compare equal when the string values are equal. A
+	// string constant being overridden by, for example, a fmt.Stringer is
+	// not handled.
+	overrides := map[interface{}]bool{}
+	for i := 0; i < len(second); i += 2 {
+		overrides[second[i]] = true
+	}
+	merged := make([]interface{}, 0, maxLength)
+	for i := 0; i+1 < len(first); i += 2 {
+		key := first[i]
+		if overrides[key] {
+			continue
+		}
+		merged = append(merged, key, first[i+1])
+	}
+	merged = append(merged, second...)
+	if len(merged)%2 != 0 {
+		merged = append(merged, missingValue)
+	}
+	return merged
+}
+
 const missingValue = "(MISSING)"
 
 // KVListFormat serializes all key/value pairs into the provided buffer.

internal/serialize/keyvalues_test.go

@@ -19,6 +19,7 @@ package serialize_test
 import (
 	"bytes"
 	"fmt"
+	"reflect"
 	"testing"
 	"time"
 
@@ -149,3 +150,180 @@ No whitespace.`,
 		}
 	}
 }
+
+func TestDuplicates(t *testing.T) {
+	for name, test := range map[string]struct {
+		first, second   []interface{}
+		expectedTrimmed [][]interface{}
+		expectedMerged  []interface{}
+	}{
+		"empty": {
+			expectedTrimmed: [][]interface{}{{}, {}},
+		},
+		"no-duplicates": {
+			first:  makeKV("a", 3),
+			second: makeKV("b", 3),
+			expectedTrimmed: [][]interface{}{
+				makeKV("a", 3),
+				makeKV("b", 3),
+			},
+			expectedMerged: append(makeKV("a", 3), makeKV("b", 3)...),
+		},
+		"all-duplicates": {
+			first:  makeKV("a", 3),
+			second: makeKV("a", 3),
+			expectedTrimmed: [][]interface{}{
+				{},
+				makeKV("a", 3),
+			},
+			expectedMerged: makeKV("a", 3),
+		},
+		"start-duplicate": {
+			first:  append([]interface{}{"x", 1}, makeKV("a", 3)...),
+			second: append([]interface{}{"x", 2}, makeKV("b", 3)...),
+			expectedTrimmed: [][]interface{}{
+				makeKV("a", 3),
+				append([]interface{}{"x", 2}, makeKV("b", 3)...),
+			},
+			expectedMerged: append(append(makeKV("a", 3), "x", 2), makeKV("b", 3)...),
+		},
+		"subset-first": {
+			first:  append([]interface{}{"x", 1}, makeKV("a", 3)...),
+			second: append([]interface{}{"x", 2}, makeKV("a", 3)...),
+			expectedTrimmed: [][]interface{}{
+				{},
+				append([]interface{}{"x", 2}, makeKV("a", 3)...),
+			},
+			expectedMerged: append([]interface{}{"x", 2}, makeKV("a", 3)...),
+		},
+		"subset-second": {
+			first:  append([]interface{}{"x", 1}, makeKV("a", 1)...),
+			second: append([]interface{}{"x", 2}, makeKV("b", 2)...),
+			expectedTrimmed: [][]interface{}{
+				makeKV("a", 1),
+				append([]interface{}{"x", 2}, makeKV("b", 2)...),
+			},
+			expectedMerged: append(append(makeKV("a", 1), "x", 2), makeKV("b", 2)...),
+		},
+		"end-duplicate": {
+			first:  append(makeKV("a", 3), "x", 1),
+			second: append(makeKV("b", 3), "x", 2),
+			expectedTrimmed: [][]interface{}{
+				makeKV("a", 3),
+				append(makeKV("b", 3), "x", 2),
+			},
+			expectedMerged: append(makeKV("a", 3), append(makeKV("b", 3), "x", 2)...),
+		},
+		"middle-duplicate": {
+			first:  []interface{}{"a-0", 0, "x", 1, "a-1", 2},
+			second: []interface{}{"b-0", 0, "x", 2, "b-1", 2},
+			expectedTrimmed: [][]interface{}{
+				{"a-0", 0, "a-1", 2},
+				{"b-0", 0, "x", 2, "b-1", 2},
+			},
+			expectedMerged: []interface{}{"a-0", 0, "a-1", 2, "b-0", 0, "x", 2, "b-1", 2},
+		},
+		"internal-duplicates": {
+			first:  []interface{}{"a", 0, "x", 1, "a", 2},
+			second: []interface{}{"b", 0, "x", 2, "b", 2},
+			expectedTrimmed: [][]interface{}{
+				{"a", 2},
+				{"x", 2, "b", 2},
+			},
+			// This is the case where Merged keeps key/value pairs
+			// that were already duplicated inside the slices, for
+			// performance.
+			expectedMerged: []interface{}{"a", 0, "a", 2, "b", 0, "x", 2, "b", 2},
+		},
+	} {
+		t.Run(name, func(t *testing.T) {
+			t.Run("TrimDuplicates", func(t *testing.T) {
+				actual := serialize.TrimDuplicates(test.first, test.second)
+				expectEqual(t, "trimmed key/value pairs", test.expectedTrimmed, actual)
+			})
+
+			t.Run("Merged", func(t *testing.T) {
+				actual := serialize.MergeKVs(test.first, test.second)
+				expectEqual(t, "merged key/value pairs", test.expectedMerged, actual)
+			})
+		})
+	}
+}
+
+// BenchmarkTrimDuplicates checks performance when TrimDuplicates is called with two slices.
+// In practice that is how the function is used.
+func BenchmarkTrimDuplicates(b *testing.B) {
+	for firstLength := 0; firstLength < 10; firstLength++ {
+		firstA := makeKV("a", firstLength)
+		for secondLength := 0; secondLength < 10; secondLength++ {
+			secondA := makeKV("a", secondLength)
+			secondB := makeKV("b", secondLength)
+			b.Run(fmt.Sprintf("%dx%d", firstLength, secondLength), func(b *testing.B) {
+				// This is the most common case: all key/value pairs are kept.
+				b.Run("no-duplicates", func(b *testing.B) {
+					expected := append(firstA, secondB...)
+					benchTrimDuplicates(b, expected, firstA, secondB)
+				})
+
+				// Fairly unlikely...
+				b.Run("all-duplicates", func(b *testing.B) {
+					var expected []interface{}
+					if firstLength > secondLength {
+						expected = firstA[secondLength*2:]
+					}
+					expected = append(expected, secondA...)
+					benchTrimDuplicates(b, expected, firstA, secondA)
+				})
+
+				// First entry is the same.
+				b.Run("start-duplicate", func(b *testing.B) {
+					first := []interface{}{"x", 1}
+					first = append(first, firstA...)
+					second := []interface{}{"x", 1}
+					second = append(second, secondB...)
+					expected := append(firstA, second...)
+					benchTrimDuplicates(b, expected, first, second)
+				})
+
+				// Last entry is the same.
+				b.Run("end-duplicate", func(b *testing.B) {
+					first := firstA[:]
+					first = append(first, "x", 1)
+					second := secondB[:]
+					second = append(second, "x", 1)
+					expected := append(firstA, second...)
+					benchTrimDuplicates(b, expected, first, second)
+				})
+			})
+		}
+	}
+}
+
+func makeKV(prefix string, length int) []interface{} {
+	if length == 0 {
+		return []interface{}{}
+	}
+	kv := make([]interface{}, 0, length*2)
+	for i := 0; i < length; i++ {
+		kv = append(kv, fmt.Sprintf("%s-%d", prefix, i), i)
+	}
+	return kv
+}
+
+func benchTrimDuplicates(b *testing.B, expected []interface{}, first, second []interface{}) {
+	if len(expected) == 0 {
+		expected = nil
+	}
+	actual := serialize.MergeKVs(first, second)
+	expectEqual(b, "trimmed key/value pairs", expected, actual)
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		serialize.MergeKVs(first, second)
+	}
+}
+
+func expectEqual(tb testing.TB, what string, expected, actual interface{}) {
+	if !reflect.DeepEqual(expected, actual) {
+		tb.Fatalf("Did not get correct %s. Expected:\n    %v\nActual:\n    %v", what, expected, actual)
+	}
+}

klogr.go

@@ -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

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...)
 	}
 }