funcr: Move kvlist sanitization to entry-points #110
Merged
+72
−31
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
pohly
reviewed
Oct 12, 2021
funcr/funcr.go
Outdated
| kvList = append(kvList, "<no-value>") | ||
| } | ||
| for i := 0; i < len(kvList); i += 2 { | ||
| _, ok := kvList[i].(string) |
There was a problem hiding this comment.
This type assertion now needs to be done twice. I was wondering whether this is measurable, so I ran the benchmarks before and after:
$GOPATH/bin/benchstat /tmp/master /tmp/pr
name old time/op new time/op delta
DiscardLogInfoOneArg-36 93.8ns ± 2% 95.1ns ± 2% ~ (p=0.095 n=10+9)
DiscardLogInfoSeveralArgs-36 238ns ± 1% 238ns ± 0% ~ (p=0.984 n=10+9)
DiscardLogInfoWithValues-36 241ns ± 1% 239ns ± 0% -0.69% (p=0.000 n=10+10)
DiscardLogV0Info-36 239ns ± 0% 240ns ± 1% ~ (p=0.062 n=9+10)
DiscardLogV9Info-36 241ns ± 0% 239ns ± 1% -1.07% (p=0.000 n=10+10)
DiscardLogError-36 260ns ± 0% 264ns ± 0% +1.67% (p=0.000 n=10+9)
DiscardWithValues-36 119ns ± 1% 116ns ± 2% -2.91% (p=0.000 n=10+10)
DiscardWithName-36 2.34ns ± 0% 2.34ns ± 0% ~ (p=0.104 n=8+9)
FuncrLogInfoOneArg-36 1.15µs ± 6% 1.14µs ± 3% ~ (p=0.726 n=10+10)
FuncrJSONLogInfoOneArg-36 1.31µs ± 5% 1.32µs ± 4% ~ (p=0.493 n=10+10)
FuncrLogInfoSeveralArgs-36 2.63µs ± 2% 2.63µs ± 5% ~ (p=0.968 n=9+10)
FuncrJSONLogInfoSeveralArgs-36 2.82µs ± 5% 2.82µs ± 3% ~ (p=0.671 n=10+10)
FuncrLogInfoWithValues-36 2.74µs ± 3% 2.77µs ± 4% ~ (p=0.324 n=10+10)
FuncrJSONLogInfoWithValues-36 2.89µs ± 3% 3.03µs ± 1% +4.64% (p=0.000 n=10+9)
FuncrLogV0Info-36 2.59µs ± 6% 2.64µs ± 4% ~ (p=0.315 n=10+10)
FuncrJSONLogV0Info-36 2.81µs ± 6% 2.82µs ± 5% ~ (p=0.549 n=9+10)
FuncrLogV9Info-36 255ns ± 7% 256ns ± 1% ~ (p=0.705 n=9+10)
FuncrJSONLogV9Info-36 237ns ±14% 256ns ± 1% +8.02% (p=0.000 n=10+10)
FuncrLogError-36 2.99µs ± 7% 3.07µs ± 6% ~ (p=0.172 n=10+10)
FuncrJSONLogError-36 3.28µs ± 8% 3.26µs ± 4% ~ (p=0.971 n=10+10)
FuncrWithValues-36 1.33µs ± 3% 1.35µs ± 3% ~ (p=0.109 n=10+10)
FuncrWithName-36 190ns ± 1% 186ns ± 1% -1.93% (p=0.000 n=10+10)
FuncrWithCallDepth-36 178ns ± 1% 178ns ± 1% ~ (p=0.098 n=10+9)
I'm not sure what to make of these numbers. Why are some benchmarks getting better? Looks like noise.
|
I read it as a small slowdown but maybe worth taking a look at again. It's
a good point.
…On Tue, Oct 12, 2021 at 12:40 AM Patrick Ohly ***@***.***> wrote:
***@***.**** commented on this pull request.
------------------------------
In funcr/funcr.go
<#110 (comment)>:
> @@ -493,6 +488,26 @@ func (f Formatter) caller() callerID {
return callerID{filepath.Base(file), line, fn}
}
+// sanitize ensures that a list of key-value pairs has a value for every key
+// (adding a value if needed) and that each key is a string (substituting a key
+// if needed).
+func (f Formatter) sanitize(kvList []interface{}) []interface{} {
+ if len(kvList)%2 != 0 {
+ kvList = append(kvList, "<no-value>")
+ }
+ for i := 0; i < len(kvList); i += 2 {
+ _, ok := kvList[i].(string)
This type assertion now needs to be done twice. I was wondering whether
this is measurable, so I ran the benchmarks before and after:
$GOPATH/bin/benchstat /tmp/master /tmp/pr
name old time/op new time/op delta
DiscardLogInfoOneArg-36 93.8ns ± 2% 95.1ns ± 2% ~ (p=0.095 n=10+9)
DiscardLogInfoSeveralArgs-36 238ns ± 1% 238ns ± 0% ~ (p=0.984 n=10+9)
DiscardLogInfoWithValues-36 241ns ± 1% 239ns ± 0% -0.69% (p=0.000 n=10+10)
DiscardLogV0Info-36 239ns ± 0% 240ns ± 1% ~ (p=0.062 n=9+10)
DiscardLogV9Info-36 241ns ± 0% 239ns ± 1% -1.07% (p=0.000 n=10+10)
DiscardLogError-36 260ns ± 0% 264ns ± 0% +1.67% (p=0.000 n=10+9)
DiscardWithValues-36 119ns ± 1% 116ns ± 2% -2.91% (p=0.000 n=10+10)
DiscardWithName-36 2.34ns ± 0% 2.34ns ± 0% ~ (p=0.104 n=8+9)
FuncrLogInfoOneArg-36 1.15µs ± 6% 1.14µs ± 3% ~ (p=0.726 n=10+10)
FuncrJSONLogInfoOneArg-36 1.31µs ± 5% 1.32µs ± 4% ~ (p=0.493 n=10+10)
FuncrLogInfoSeveralArgs-36 2.63µs ± 2% 2.63µs ± 5% ~ (p=0.968 n=9+10)
FuncrJSONLogInfoSeveralArgs-36 2.82µs ± 5% 2.82µs ± 3% ~ (p=0.671 n=10+10)
FuncrLogInfoWithValues-36 2.74µs ± 3% 2.77µs ± 4% ~ (p=0.324 n=10+10)
FuncrJSONLogInfoWithValues-36 2.89µs ± 3% 3.03µs ± 1% +4.64% (p=0.000 n=10+9)
FuncrLogV0Info-36 2.59µs ± 6% 2.64µs ± 4% ~ (p=0.315 n=10+10)
FuncrJSONLogV0Info-36 2.81µs ± 6% 2.82µs ± 5% ~ (p=0.549 n=9+10)
FuncrLogV9Info-36 255ns ± 7% 256ns ± 1% ~ (p=0.705 n=9+10)
FuncrJSONLogV9Info-36 237ns ±14% 256ns ± 1% +8.02% (p=0.000 n=10+10)
FuncrLogError-36 2.99µs ± 7% 3.07µs ± 6% ~ (p=0.172 n=10+10)
FuncrJSONLogError-36 3.28µs ± 8% 3.26µs ± 4% ~ (p=0.971 n=10+10)
FuncrWithValues-36 1.33µs ± 3% 1.35µs ± 3% ~ (p=0.109 n=10+10)
FuncrWithName-36 190ns ± 1% 186ns ± 1% -1.93% (p=0.000 n=10+10)
FuncrWithCallDepth-36 178ns ± 1% 178ns ± 1% ~ (p=0.098 n=10+9)
I'm not sure what to make of these numbers. Why are some benchmarks
getting better? Looks like noise.
—
You are receiving this because you authored the thread.
Reply to this email directly, view it on GitHub
<#110 (review)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/ABKWAVGGM3P2O3NLD2QTCQTUGPRAFANCNFSM5FZAKYCQ>
.
Triage notifications on the go with GitHub Mobile for iOS
<https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675>
or Android
<https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.
|
|
I think this change makes sense and we should merge this even if there is a small slowdown, I'm just surprised that this isn't showing up as a small slowdown consistently. One more idea: would it make sense to represent a sanitized key/value list differently so that the second type assertion during usage becomes unnecessary? Something like This would make the API in #111 simpler because instead of just documenting that the On the other hand, a slice that is already sane cannot be passed through. We would have to do allocations in all cases. This probably is a showstopper. |
|
Converting slice to struct requires allocation, but I can try it. Taking a
deeper look at benchmarks, it's SUCH a small slowdown, I am not sure it is
worth much. I ran with a longer duration.
before:
```
$ go test -benchtime=5s -bench='Funcr.*LogInfo' ./benchmark/
goos: linux
goarch: amd64
pkg: github.com/go-logr/logr/benchmark
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkFuncrLogInfoOneArg-6 10244180 583.2 ns/op
BenchmarkFuncrJSONLogInfoOneArg-6 8933517 621.9 ns/op
BenchmarkFuncrLogInfoSeveralArgs-6 4890208 1182 ns/op
BenchmarkFuncrJSONLogInfoSeveralArgs-6 4658998 1286 ns/op
BenchmarkFuncrLogInfoWithValues-6 5003335 1212 ns/op
BenchmarkFuncrJSONLogInfoWithValues-6 4454695 1321 ns/op
PASS
ok github.com/go-logr/logr/benchmark 41.649s
```
after this commit:
```
$ go test -benchtime=5s -bench='Funcr.*LogInfo' ./benchmark/
goos: linux
goarch: amd64
pkg: github.com/go-logr/logr/benchmark
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkFuncrLogInfoOneArg-6 10125416 592.0 ns/op
BenchmarkFuncrJSONLogInfoOneArg-6 8820924 689.6 ns/op
BenchmarkFuncrLogInfoSeveralArgs-6 4959550 1211 ns/op
BenchmarkFuncrJSONLogInfoSeveralArgs-6 4623242 1369 ns/op
BenchmarkFuncrLogInfoWithValues-6 4925040 1209 ns/op
BenchmarkFuncrJSONLogInfoWithValues-6 4830463 1271 ns/op
PASS
ok github.com/go-logr/logr/benchmark 42.826s
```
I refactored a bit to avoid the double cast (though the next commit will
have to adapt too, and less obviously easy):
```
$ go test -benchtime=5s -bench='Funcr.*LogInfo' ./benchmark/
goos: linux
goarch: amd64
pkg: github.com/go-logr/logr/benchmark
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkFuncrLogInfoOneArg-6 10163474 601.5 ns/op
BenchmarkFuncrJSONLogInfoOneArg-6 8873766 675.1 ns/op
BenchmarkFuncrLogInfoSeveralArgs-6 5082262 1181 ns/op
BenchmarkFuncrJSONLogInfoSeveralArgs-6 4655140 1291 ns/op
BenchmarkFuncrLogInfoWithValues-6 4930466 1224 ns/op
BenchmarkFuncrJSONLogInfoWithValues-6 4562056 1322 ns/op
PASS
ok github.com/go-logr/logr/benchmark 42.537s
```
So we're quibbling over 10 ns out of 600.
I'll play a bit more when I get time. Let's not merge yet.
…On Tue, Oct 12, 2021 at 8:47 AM Patrick Ohly ***@***.***> wrote:
I think this change makes sense and we should merge this even if there is
a small slowdown, I'm just surprised that this isn't showing up as a small
slowdown consistently.
One more idea: would it make sense to represent a sanitized key/value list
differently so that the second type assertion during usage becomes
unnecessary? Something like []struct {key string; value interface{}}.
This would make the API in #111 <#111>
simpler because instead of just documenting that the []interface{} slice
is sanitized, we can put that into the type.
On the other hand, a slice that is already sane cannot be passed through.
We would have to do allocations in all cases. This probably is a
showstopper.
—
You are receiving this because you authored the thread.
Reply to this email directly, view it on GitHub
<#110 (comment)>, or
unsubscribe
<https://github.com/notifications/unsubscribe-auth/ABKWAVGRW44PU4WYOGDIFPLUGRKCNANCNFSM5FZAKYCQ>
.
Triage notifications on the go with GitHub Mobile for iOS
<https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675>
or Android
<https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.
|
Definitely not worth it. I'm more interested in a sane API (different type, if possible) and understanding the benchmark results: are the results reliable or too noisy? For example, why is |
|
I re-ran with Let's merge once we are happy with the resulting API in PR #111 |
|
I retooled anyway - this is almost as simple in the next commit and marginally better here. Difference is noise. before: after: |
|
ugh, I might have messed up |
thockin
force-pushed
the
funcr-kv-sanitize
branch
from
cc0e654 to
851d45a
Compare
|
OK, fixed messup. before: after: noise. Ready to merge at your whim, IMO. |
pohly
reviewed
Oct 12, 2021
thockin
force-pushed
the
funcr-kv-sanitize
branch
from
851d45a to
b047281
Compare
This is more comprehensible and makes upcoming changes easier. Also include a value snippet in non-string keys.
thockin
force-pushed
the
funcr-kv-sanitize
branch
from
b047281 to
bd1384b
Compare
pohly
approved these changes
Oct 13, 2021
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
This is more comprehensible and makes upcoming changes easier. Also
include a value snippet in non-string keys.
Fixes #106