New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
log: optimize SetOutput(io.Discard) #47164
Comments
There are in GitHub ~10K occurrences of |
I had considered a sentinel value I don't think it offers much benefits, compared to the |
cc @robpike |
I feel like people usually have some threshold-based logger (i.e., debug, info, warn, error, etc.) surrounding the actual log.Logger method calls, in which case the entire log call is skipped by the threshold test in the event that logging is disabled. In those cases, using a nil log.Logger to mean "discard" wouldn't increase performance. Also, while calling methods on nil is technically permissible, I think it would just lead to subtle bugs where for example someone forgets to assign to a struct field, and unless they go and check their logs they won't notice that nothing is happening, whereas if the code panics (the current behavior), it's pretty clear what's wrong. Another possible solution to your problem would be to make an interface around log.Logger (or at least the subset of methods you care about), and then define another implementation that no-ops all the methods. There would still be some overhead of the method dispatch, but it might still be enough of a performance gain for you. The other possibility is to just surround the calls to the log.Logger method with an |
I think a better option would be for |
@seankhliao Unfortunately in the current design, checking This would still bear an expensive synchronization cost (the mutex) in the Discard case, and would actually make existing programs slower in the general non-Discard case, because of the extra mutex cost. One substantial advantage of |
I wonder how the performance would compare if |
@Deleplace you can try build log.go package main
func main() {
Debug("it's expensive")
if Dev {
log.Println("we are in develop mode")
}
} log_debug.go //+build debug
package main
import (
"log"
)
const Dev = true
func Debug(a ...interface{}) {
log.Println(a...)
} log_release.go //+build !debug
package main
const Dev = false
func Debug(a ...interface{}) {} If you want to debug code |
@mengzhuo Unfortunately, disabling debug logs at compile-time pretty much makes it impossible to quickly enable debug log verbosity for troubleshooting a production problem. As a general rule, it is quicker to change a flag for a deployment than it is to build a new binary, package it for release, then get it up and running. |
Some interesting considerations are out of scope of the current proposal:
|
In my proposal, As a possible gotcha, and data race hazard, I realize that
would not be equivalent to
|
This proposal has been added to the active column of the proposals project |
Based on the discussion above, this proposal seems like a likely accept. |
@rsc I'd like to suggest a boolean field on type Logger struct {
isDiscard bool
...
}
var Discard = &Logger{isDiscard: true}
func (l *Logger) Output(calldepth int, s string) error {
if l.isDiscard {
return nil
}
...
} This should give the same performance benefit as allowing the receiver to be It also leads to, I think, clearer code on the client side. Otherwise people will have to know that a You could also invert the bool if you want the struct's zero value to be the no-op Logger. |
I like that idea, @rittneje. If made available through the interface, not just at construction time, one could disable logging dynamically, which could be handy when debugging a program that uses libraries that log too much but are not the problem. One small point: Prefer positive names over negative true. I suggest calling this Enable, defaulting to true. That works because Logger does not have a useful zero value. (However, Discard is a known name, so that has advantages as well.) |
An important note about what happens in It is crucial to check the condition early inside |
We have a few strong candidates here, which don't have the exact same costs in performance gain and in burden on the client code: A) a valid It is important to be able to disable logging dynamically, however (D) would incur a performance penalty by requiring all calls to (*Logger).Print to also call (E) would cause a burden on the user to do some external synchronization, which is unexpected because all other methods are thread-safe via (A), (B), (C) are performant and it is more obvious for the user that they only need proper synchronization on their Turn logger off Turn logger on, by creation Turn logger on, by reuse |
@Deleplace I just wanted to point out that for (D), you could also have a |
It does seem like not reusing nil would help catch some mistakes. As @rittneje points out, the flag can be an atomic boolean, so then the overhead on the printing path (and the discarding path) is a single atomic word read. That seems like it is probably cheap enough. Being able to toggle the whole logger has the benefit of not having to find all the different places you might have passed the logger and overwrite them all. I wonder if SetOutput(io.Discard) should be the discard signal? |
Retitled, will leave for a week but seems headed for likely accept with the new scoping. |
Here is a summary of the performance delta between "initial scoping" vs "new scoping" Original proposal:
New scoping:
As I'm not very familiar with atomics, could we please agree on these list of concerns for the new scoping?
I'm very happy with the "likely accept" prospect for some form of this proposal. Thank you all for the support. |
@Deleplace, in 7, the SetOutput call would check out == io.Discard and then set an atomic boolean (in an int32), which the 'is muted' check would use in calls like log.Printf. |
Based on the discussion above, this proposal seems like a likely accept. |
Yes. Way cheaper, as the number of CPU cores in use grows: acquiring a
|
No change in consensus, so accepted. 🎉 |
Change https://golang.org/cl/348741 mentions this issue: |
Edit: as discussed in the comments, the proposal is not anymore about using a
nil
receiver. It is still about making it cheaper to call a disabled (muted) Logger.What
Make this
nil
pointer variablea valid Logger, where all the calls to
nilLogger.Print
, etc. are valid (do not crash), and do not produce any actual logs.This would serve as an adequate replacement of, and almost equivalent to:
Why
Performance.
This is an important concern because logging is often expensive, and it is a reasonable expectation that it becomes free (or very cheap) when logging is turned off. Currently,
discardLogger
comes with a quite expensive overhead:discardLogger.Print
variadic arguments are evaluated, even if they are not really needed;(*Logger).Print
is executedfmt.Sprint
is called, which incurs some memory allocation, and some work to use the variadic arguments in order to produce a strings
;discardLogger.mu
isLock
ed, then laterUnlock
ed;s
is copied to the internal bufferdiscardLogger.buf
;discardLogger.out.Write
, which resolves toio.discard.Write
.The proposed implementation consists of checking for nil receiver inside all of the exported methods and returning immediately, thus avoiding steps 3, 4, 5, 6.
In the proposed implementation, the steps 1, 2 still happen, as the arguments are still evaluated. In theory this could be mitigated in some side-effect-free cases, with advanced escape analysis and inlining. This mitigation is out of reach of the current inlining system, and out of scope of the current proposal.
Benefits
In a sample benchmark,
nilLogger.Printf
is 35x faster with anint
arg, and 320x faster with amap
arg, thandiscardLogger.Printf
.The speedup would be higher with more arguments, or more complex arguments.
As a side effect, the zero value for the pointer type
*log.Logger
becomes useful and safe, without initialization.Backwards compatibility
nil
*log.Logger instances.log.New(io.Discard, "", 0)
still works.nilLogger.Print
would not panic anymore. A program relying on the panic behavior would break. It is however not a promise (no guarantee) from the log package to havenilLogger.Print
panic.nilLogger.Print
would not callfmt.Sprint
anymore, resulting in some customString
methods to not be called. A program relying the side effects of custom String methods would break. It is however not a promise (no guarantee) from the log package to have valid Loggers always callfmt.Sprint
.l.SetOutput(w)
to always succeeds for any valid loggerl
. Such a program would break.l.SetPrefix(prefix)
to force the subsequent value returned byl.Prefix()
, for any valid loggerl
. Such a program would break.l.SetFlags(flag)
to force the subsequent value returned byl.Flags()
, for any valid loggerl
. Such a program would break.Concurrency
It is my understanding that the proposed implementation does not introduce any new risks of data races.
For a
nil
receiver, all of thePrint
methods are thread-safe, and do not require a mutex.Detailed behavior of each method
When the receiver
l
isnil
:(l *Logger).Fatal(v ...interface{})
(l *Logger).Fatalf(format string, v ...interface{})
(l *Logger).Fatalln(v ...interface{})
:os.Exit(1)
.(l *Logger).Flags() int
:0
.(l *Logger).Output(calldepth int, s string) error
:nil
.(l *Logger).Panic(v ...interface{})
(l *Logger).Panicf(format string, v ...interface{})
(l *Logger).Panicln(v ...interface{})
:s
and callpanic(s)
.(l *Logger).Prefix() string
:""
.(l *Logger).Print(v ...interface{})
(l *Logger).Printf(format string, v ...interface{})
(l *Logger).Println(v ...interface{})
:(l *Logger).SetFlags(flag int)
:(l *Logger).SetOutput(w io.Writer)
:w
to be subsequently used, which is not possible.(l *Logger).SetPrefix(prefix string)
:(l *Logger).Writer() io.Writer
:nil
.The text was updated successfully, but these errors were encountered: