Skip to content

Commit

Permalink
keep original key/value pair during de-duplicatation
Browse files Browse the repository at this point in the history 
Suppose the same key/value pair gets logged multiple times:

  WithValues("sameKey", 1).WithValues("newKey", 2).WithValues("sameKey", 1)

Previously, the de-duplication code would have emitted it near the end:

    "hello world" newKey=2 sameKey=1

Now, it gets emitted at the place where it first appeared:

    "hello world" sameKey=1 newKey=2

This makes log entries more consistent when some repeat the key/value pair and
others don't.

Performance is about the same as before.

    goos: linux
    goarch: amd64
    pkg: k8s.io/klog/examples/benchmarks
    cpu: Intel(R) Core(TM) i9-7980XE CPU @ 2.60GHz
                                                                            │    after1    │                after2                │
                                                                            │    sec/op    │    sec/op      vs base               │
    ...
    geomean                                                                   3.442µ          3.445µ         +0.09%

    pkg: k8s.io/klog/examples/output_test
    geomean                                                                    5.646µ         5.631µ        -0.26%

    pkg: k8s.io/klog/v2
    geomean                                                                     260.6n          260.5n        -0.07%

    pkg: k8s.io/klog/v2/textlogger

    TextloggerOutput/odd_WithValues-36                                               6.956µ ±  4%   7.263µ ±  4%  +4.42% (p=0.041 n=6)
    ...
    TextloggerOutput/log_with_multiple_names_and_values-36                           3.353µ ±  4%   3.172µ ±  2%  -5.40% (p=0.002 n=6)
    ...
    TextloggerOutput/duplicates-36                                                   17.06µ ±  4%   17.16µ ±  9%       ~ (p=0.937 n=6)
    ...
    TextloggerOutput/mixed_duplicates-36                                             19.59µ ±  7%   20.35µ ±  5%       ~ (p=0.065 n=6)
    ...
    TextloggerOutput/print_duplicate_keys_in_arguments-36                            2.388µ ±  6%   2.218µ ±  7%  -7.12% (p=0.026 n=6)
    ...
    geomean                                                                          2.860µ         2.849µ        -0.38%
  • Loading branch information
@pohly
pohly committed Nov 21, 2024
1 parent 449cffc commit fb1339a
Show file tree
Hide file tree
Showing 3 changed files with 25 additions and 16 deletions.
29 changes: 19 additions & 10 deletions internal/serialize/keyvalues.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import (
"bytes"
"encoding/json"
"fmt"
"slices"
"strconv"

"github.com/go-logr/logr"
Expand Down Expand Up @@ -144,16 +145,24 @@ func (f Formatter) formatKVs(b *bytes.Buffer, kvs ...[]interface{}) {
e.end = b.Len()
i := findObsoleteEntry(existing, e.key)
if i >= 0 {
// The old entry gets obsoleted. This ensures
// that if the more recent one has a different value,
// that value remains. If the value is the same,
// then we could also keep the old entry. That
// would lead to a more natural order of key/value
// pairs in the output (shared key/value in multiple
// log entries always at the beginning) but at the
// cost of another memory comparison.
obsolete = append(obsolete, existing[i].interval)
existing[i].interval = e.interval
data := b.Bytes()
if bytes.Compare(data[existing[i].start:existing[i].end], data[e.start:e.end]) == 0 {
// The new entry gets obsoleted because it's identical.
// This has the advantage that key/value pairs from
// a WithValues call always come first, even if the same
// pair gets added again later. This makes different log
// entries more consistent.
//
// The new entry has a higher start index and thus can be appended.
obsolete = append(obsolete, e.interval)
} else {
// The old entry gets obsoleted because it's value is different.
//
// Sort order is not guaranteed, we have to insert at the right place.
index, _ := slices.BinarySearchFunc(obsolete, existing[i].interval, func(a, b interval) int { return a.start - b.start })
obsolete = slices.Insert(obsolete, index, existing[i].interval)
existing[i].interval = e.interval
}
} else {
// Instead of appending at the end and doing a
// linear search in findEntry, we could keep
Expand Down
4 changes: 2 additions & 2 deletions test/output.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -446,9 +446,9 @@ I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="
text: "duplicates",

expectedOutput: `I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1
I output.go:<LINE>] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718"
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 b=2 span="1112131415161718"
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1
I output.go:<LINE>] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 c=3 span="2122232425262728" d=4
`,
},
}
Expand Down
8 changes: 4 additions & 4 deletions test/zapr.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -275,9 +275,9 @@ I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="
`,

`I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1
I output.go:<LINE>] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718"
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 b=2 span="1112131415161718"
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1
I output.go:<LINE>] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 c=3 span="2122232425262728" d=4
`: `{"caller":"test/output.go:<LINE>","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"v":0}
{"caller":"test/output.go:<LINE>","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"b":2,"trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718","v":0}
{"caller":"test/output.go:<LINE>","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"v":0}
Expand Down Expand Up @@ -383,9 +383,9 @@ I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="
`,

`I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1
I output.go:<LINE>] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718"
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 b=2 span="1112131415161718"
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1
I output.go:<LINE>] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4
I output.go:<LINE>] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 c=3 span="2122232425262728" d=4
`: `{"caller":"test/output.go:<LINE>","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1}
{"caller":"test/output.go:<LINE>","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"b":2,"trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718"}
{"caller":"test/output.go:<LINE>","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1}
Expand Down

0 comments on commit fb1339a

Please sign in to comment.