Rearch for performance: BREAKING CHANGES

[thockin]

Playing with ideas from Russ Cox.

xref #40

Before:

$ go test -bench='.' ./benchmark/
goos: linux
goarch: amd64
pkg: github.com/go-logr/logr/benchmark
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkInfoOneArg-6             483949              2420 ns/op
BenchmarkInfoSeveralArgs-6        359826              3302 ns/op
BenchmarkV0Info-6                 352570              3399 ns/op
BenchmarkV9Info-6                9096120               130.3 ns/op
BenchmarkError-6                  366549              3280 ns/op
BenchmarkWithValues-6            9936550               120.1 ns/op
BenchmarkWithName-6             22592770                53.38 ns/op

After:

$ go test -bench='.' ./benchmark/
goos: linux
goarch: amd64
pkg: github.com/go-logr/logr/benchmark
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkInfoOneArg-6             514122              2291 ns/op
BenchmarkInfoSeveralArgs-6        380796              3153 ns/op
BenchmarkV0Info-6                 376472              3150 ns/op
BenchmarkV9Info-6               15167118                79.13 ns/op
BenchmarkError-6                  358990              3336 ns/op
BenchmarkWithValues-6            7674392               155.9 ns/op
BenchmarkWithName-6             23391848                50.33 ns/op

Logs that actually write are dominated by the cost of preparing the
message. Logs which do not write (e.g. V(9)) are much faster here
(thog glog raw is much faster still). The main difference is the
variadic slice setup. This is a candidate for Go to optimize - it now
knows that the args are only used inside the conditional (Enabled()),
and when that path is not executed, it can elide that work.

The real rub is that this is a breaking change for implementors (but not for consumers). We haven't declared 1.0 yet, but I know we have some users out there. @wojas

[thockin]

@wojas @DirectXMan12

It's been a crazy few months. If you (or others) have time to look at this (specifically the last commit) it would be super helpful

[wojas]

I will have a look at it. This is a rather big breaking change, I need some time to digest it.

[wojas]

I need some more time to digest the implications.

I like that the change is mostly transparent to log callers, it just affects backends and log initialization code.

The concrete type also provides more possibilities for extending the interface in the future. For example, when adding a new method like WithFoo:

• The LogSink interface could be kept the same to not break existing backends
• The Logger concrete type can safely add the new receiver
• This new function would test if the sink implements the new interface and provide some sensible fallback behavior for older backends.

[wojas]

At this moment it's only the level, but perhaps we would like to pull some other information into the concrete Logger in the future, which would require breaking changes to pass it to the Logger.

One alternative would be to pass it in a struct:

type LogContext struct {
    level int
}

And then change the interface to:

Enabled(logctx LogContext) bool
Info(logctx LogContext, msg string, keysAndValues ...interface{})
...

[wojas]

Perhaps this LogContext can also contain the number of stack frames added by the log stack. This would allow the creation of middleware-like log sinks that delegate to other sinks, while keeping the call stack count correct.

[thockin]

Perhaps this LogContext can also contain the number of stack frames added by the log stack. This would allow the creation of middleware-like log sinks that delegate to other sinks, while keeping the call stack count correct.

This is what WithCallDepth() is for. I agree that assuming literal 1 in the LogSink is kind of a mess, though. Passing it to every call to Info() feels a bit silly - it's not going to change, like the levels. It almost feels like logr.CallFrameCount() (simple, ugly) or something like:

logr.New(sink) calls sink.Init(numCallFrames), (probably a struct) which can choose to store that info if it needs.

[thockin]

On compat: There are some things that are just awkward after this, like DiscardLogger (the type) no longer making sense (it's a LogSink). We could jump thru hoops to make things work (make DiscardLogger a struct that embeds a Logger?) or we could just make this conversion a big breaking change. MOST clients will be fine with a recompile, and a small number will hit edge cases.

If we do that, we can EOL InfoLogger and a few other vestigial things.

[DirectXMan12]

I like that it appears to be non-breaking to most uses, except for custom implementations. The perf improvement for the V logger is nice. Theoretically, this could cause more work for immutable logging-level implementations (if you have an implementation that returns NullLogger from V()` if it's disabled, we now have an extra check every time), but practically I'm not sure I'm concerned about that as much (and many of the logging implementations don't have that property for various reasons, anyway).

With the style of optional implementations you've got (extra potentially nil field in the concrete logger), if we grow several optional interfaces, this could cause an increase in the size of concrete Logger struct and I'd be curious to see if that has perf implications.

[thockin]

Added 2 new commits.

1. Add a LogSink.Init() which receives info like call depth.
2. Remove back-compat.

I'm feeling pretty good about this overall. I propose we adopt this PR, call it our last intentional breaking change, and call it 1.0.0. Maybe bolster the docs and tests a bit before that.

$ GO111MODULE=off go test -bench=. ./benchmark/
goos: linux
goarch: amd64
pkg: github.com/go-logr/logr/benchmark
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkDiscardInfoOneArg-6        	19445642	        55.71 ns/op
BenchmarkDiscardInfoSeveralArgs-6   	 7857495	       156.5 ns/op
BenchmarkDiscardV0Info-6            	 7795311	       160.5 ns/op
BenchmarkDiscardV9Info-6            	 7694216	       158.0 ns/op
BenchmarkDiscardError-6             	 7300124	       163.9 ns/op
BenchmarkDiscardWithValues-6        	17942917	        78.88 ns/op
BenchmarkDiscardWithName-6          	278674214	         3.797 ns/op
BenchmarkFuncrInfoOneArg-6          	 2485114	       495.4 ns/op
BenchmarkFuncrInfoSeveralArgs-6     	  894175	      1311 ns/op
BenchmarkFuncrV0Info-6              	  925024	      1255 ns/op
BenchmarkFuncrV9Info-6              	 7969364	       161.1 ns/op
BenchmarkFuncrError-6               	  961226	      1412 ns/op
BenchmarkFuncrWithValues-6          	 4106169	       293.7 ns/op
BenchmarkFuncrWithName-6            	92719092	        12.27 ns/op
PASS
ok  	github.com/go-logr/logr/benchmark	21.148s

[thockin]

OK, I am taking silence as consent.

I will look at docs and tests and call this v1.0.0-rc1

[cbandy]

Should this be returning l2?

[cbandy]

Just spotted #47. Sorry for the noise.

[thockin]

Good eyes :)

…

On Sat, May 29, 2021, 12:41 PM Chris Bandy ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In funcr/funcr.go <#42 (comment)>: > } - l.prefix += name + l2.prefix += name return l Just spotted #47 <#47>. Sorry for the noise. — You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub <#42 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABKWAVHJCUPDHOZSJHKS7MDTQE7PRANCNFSM42JRPMIQ> .