Skip to content
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

Closed
Deleplace opened this issue Jul 13, 2021 · 26 comments
Closed

log: optimize SetOutput(io.Discard) #47164

Deleplace opened this issue Jul 13, 2021 · 26 comments

Comments

@Deleplace
Copy link
Contributor

Deleplace commented Jul 13, 2021

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 variable

var nilLogger *log.Logger

a 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:

var discardLogger = log.New(io.Discard, "", 0)

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:

  1. all of the discardLogger.Print variadic arguments are evaluated, even if they are not really needed;
  2. a non-inlined function call to (*Logger).Printis executed
  3. fmt.Sprint is called, which incurs some memory allocation, and some work to use the variadic arguments in order to produce a string s;
  4. the mutex discardLogger.mu is Locked, then later Unlocked;
  5. s is copied to the internal buffer discardLogger.buf;
  6. a dynamic function dispatch is executed for discardLogger.out.Write, which resolves to io.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 an int arg, and 320x faster with a map arg, than discardLogger.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

  • No changes to all the non-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 have nilLogger.Print panic.
  • nilLogger.Print would not call fmt.Sprint anymore, resulting in some custom String 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 call fmt.Sprint.
  • A program may expect l.SetOutput(w) to always succeeds for any valid logger l. Such a program would break.
  • A program may expect l.SetPrefix(prefix) to force the subsequent value returned by l.Prefix(), for any valid logger l. Such a program would break.
  • A program may expect l.SetFlags(flag) to force the subsequent value returned by l.Flags(), for any valid logger l. 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 the Print methods are thread-safe, and do not require a mutex.

Detailed behavior of each method

When the receiver l is nil:

  • (l *Logger).Fatal(v ...interface{})
  • (l *Logger).Fatalf(format string, v ...interface{})
  • (l *Logger).Fatalln(v ...interface{}):
    • don't log anything. Call os.Exit(1).
  • (l *Logger).Flags() int:
    • return 0.
  • (l *Logger).Output(calldepth int, s string) error:
    • do nothing. Return nil.
  • (l *Logger).Panic(v ...interface{})
  • (l *Logger).Panicf(format string, v ...interface{})
  • (l *Logger).Panicln(v ...interface{}):
    • don't log anything. Build the string s and call panic(s).
  • (l *Logger).Prefix() string:
    • return "".
  • (l *Logger).Print(v ...interface{})
  • (l *Logger).Printf(format string, v ...interface{})
  • (l *Logger).Println(v ...interface{}):
    • do nothing.
  • (l *Logger).SetFlags(flag int):
    • do nothing.
  • (l *Logger).SetOutput(w io.Writer):
    • panic. The caller would expect w to be subsequently used, which is not possible.
  • (l *Logger).SetPrefix(prefix string):
    • do nothing.
  • (l *Logger).Writer() io.Writer:
    • return nil.
@gopherbot gopherbot added this to the Proposal milestone Jul 13, 2021
@Deleplace
Copy link
Contributor Author

There are in GitHub ~10K occurrences of log.New(ioutil.Discard, ..., ...) and just a few occurrences of log.New(io.Discard, ..., ...).

@Deleplace
Copy link
Contributor Author

I had considered a sentinel value log.nopLogger of type *log.Logger, non-nil.

I don't think it offers much benefits, compared to the nil proposal.

@seankhliao seankhliao changed the title Proposal: fast no-op *log.Logger proposal: log: add a no-op logger Jul 13, 2021
@seankhliao
Copy link
Member

cc @robpike

@ianlancetaylor ianlancetaylor added this to Incoming in Proposals (old) Jul 13, 2021
@rittneje
Copy link

rittneje commented Jul 13, 2021

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 if logger != nil check.

@seankhliao
Copy link
Member

I think a better option would be for log.Logger to detect that output is set to io.Discard and short circuit as necessary. This wouldn't break anything and would speed up existing programs.

@Deleplace
Copy link
Contributor Author

Deleplace commented Jul 13, 2021

@seankhliao Unfortunately in the current design, checking (*Logger).out==io.Discard would require first (*Logger).mu.Locking, then (*Logger).mu.Unlocking before calling the exported method (*Logger).Output.

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 nil is that it can't hold any state, thus it's unlikely to cause data races, and does not require any mutex overhead.

@rittneje
Copy link

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.

I wonder how the performance would compare if log.Logger used sync/atomic for its fields instead of a mutex?

@mengzhuo
Copy link
Contributor

@Deleplace you can try build debug flag and the compiler will elide those "deadcode".

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 go build -tags "debug".
ref (Chinese): https://mzh.io/golang-build-tags-for-debug/

@vatine
Copy link

vatine commented Jul 14, 2021

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

@Deleplace
Copy link
Contributor Author

Some interesting considerations are out of scope of the current proposal:

  • compile-time flipping OFF/ON of the logging (or level value)
  • what we can achieve by wrapping (*log).Logger in other value types or interface types

@Deleplace
Copy link
Contributor Author

Deleplace commented Jul 14, 2021

In my proposal, myLogger = nil would be equivalent to myLogger = log.New(io.Discard, "", 0).

As a possible gotcha, and data race hazard, I realize that

myLogger = nil

would not be equivalent to

myLogger.SetOutput(io.Discard)
  • If several copies of the myLogger pointer are passed around, the latter (SetOutput) disables them all, while the former disables only one of them;
  • The latter (SetOutput) is always thread-safe (protected by myLogger.mu), while the former needs extra external synchronization if several goroutines are using myLogger;
  • The latter (SetOutput) keeps the flags and prefix intact, while the former "forgets" about them (which is easy to fix if needed)

@rsc rsc changed the title proposal: log: add a no-op logger proposal: log: define nil *Logger is valid, discards all output Jul 28, 2021
@rsc
Copy link
Contributor

rsc commented Jul 28, 2021

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

@rsc rsc moved this from Incoming to Active in Proposals (old) Jul 28, 2021
@rsc rsc moved this from Active to Likely Accept in Proposals (old) Aug 4, 2021
@rsc
Copy link
Contributor

rsc commented Aug 4, 2021

Based on the discussion above, this proposal seems like a likely accept.
— rsc for the proposal review group

@rittneje
Copy link

rittneje commented Aug 4, 2021

@rsc I'd like to suggest a boolean field on Logger rather than allowing the receiver to be nil.

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 nil, without the concern that someone unintentionally left a struct field nil. And since that field is immutable, you don't have to worry about any thread-safety while reading it.

It also leads to, I think, clearer code on the client side. Otherwise people will have to know that a nil Logger is valid (which, while valid Go, is fairly unusual).

You could also invert the bool if you want the struct's zero value to be the no-op Logger.

@robpike
Copy link
Contributor

robpike commented Aug 4, 2021

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

@Deleplace
Copy link
Contributor Author

Deleplace commented Aug 5, 2021

An important note about what happens in (*Logger).Output: it is okay to check a condition in the body of Output (as it's an exported method, we should at least consider it). But for the performance concern, when Output is called it is already too late as (3) fmt.Sprint has already been called, has already allocated memory, and has possibly called the custom expensive String method of its arguments.

It is crucial to check the condition early inside (*Logger).Printf, (*Logger).Print, (*Logger).Println.

@Deleplace
Copy link
Contributor Author

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 nil pointer
B) a sentinel value log.nopLogger of type *log.Logger
C) a bool field Logger.isDiscard, immutable
D) a bool field Logger.isDiscard, mutable, where (*Logger).SetDiscard(bool) is thread-safe by calling (*Logger).mu.Lock
E) a bool field Logger.isDiscard, mutable, where (*Logger).SetDiscard(bool) is not thread-safe

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 (*Logger).mu.Lock. The point of the proposal is to avoid as much unnecessary work and sync as possible in the disabled case.

(E) would cause a burden on the user to do some external synchronization, which is unexpected because all other methods are thread-safe via (*Locker).mu.

(A), (B), (C) are performant and it is more obvious for the user that they only need proper synchronization on their (*Logger) pointer variable itself. E.g.:

Turn logger off
mylogger = log.Discard

Turn logger on, by creation
myLogger = log.New(w, prefix, flag)

Turn logger on, by reuse
myLogger = savedLogger

@rittneje
Copy link

rittneje commented Aug 6, 2021

@Deleplace I just wanted to point out that for (D), you could also have a uint32 flag that is accessed via atomic.LoadUint32 and atomic.StoreUint32, similar to how sync.Once works.

@rsc
Copy link
Contributor

rsc commented Aug 11, 2021

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?
(Instead of a separate new API call. That would work for old versions too, just not as fast, so it would be safe to use in newer code without breaking older code.)

@rsc rsc moved this from Likely Accept to Active in Proposals (old) Aug 11, 2021
@rsc rsc changed the title proposal: log: define nil *Logger is valid, discards all output proposal: log: optimize SetOutput(io.Discard) Aug 18, 2021
@rsc
Copy link
Contributor

rsc commented Aug 18, 2021

Retitled, will leave for a week but seems headed for likely accept with the new scoping.

@Deleplace
Copy link
Contributor Author

Here is a summary of the performance delta between "initial scoping" vs "new scoping"

Original proposal:

  • save the expensive calls to fmt.Sprint and fmt.Sprintf
  • save the expensive synchronization costs of calling (*Logger).mu.Lock and (*Logger).mu.Unlock

New scoping:

  • save the expensive calls to fmt.Sprint and fmt.Sprintf
  • replace the expensive synchronization costs of (*Logger).mu.Lock and (*Logger).mu.Unlock with cheaper calls to atomic.LoadUint32 and atomic.StoreUint32

As I'm not very familiar with atomics, could we please agree on these list of concerns for the new scoping?

  1. The new scoping would automagically bring performance benefits to the thousands of projects already using ioutil.Discard/io.Discard for muting a *Logger (that would be fantastic!)
  2. Atomics are cheaper for our use case than the general-purpose sync.Mutex already contained in log.Logger
  3. Zero change will be needed in the exported API of the log package
  4. We are reasonably confident in our ability to mix 2 synchronization devices (Mutex + Atomics) in the log package implementation without introducing new data race hazards
  5. In the usual non-muted case, we are not introducing too much of overhead (maybe 1 extra call to atomic.LoadUint32?)
  6. The advantages of the new scoping overweight the cost of still paying some synchronization cost in the muted case. The target goal shifts from "Calling a muted logger is essentially free" to "Calling muted logger is cheap".
  7. The "is muted" check would be implemented as l.out == io.Discard or as l.isDiscard (to be determined)

I'm very happy with the "likely accept" prospect for some form of this proposal. Thank you all for the support.

@rsc
Copy link
Contributor

rsc commented Aug 25, 2021

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

@rsc
Copy link
Contributor

rsc commented Aug 25, 2021

Based on the discussion above, this proposal seems like a likely accept.
— rsc for the proposal review group

@rsc rsc moved this from Active to Likely Accept in Proposals (old) Aug 25, 2021
@bcmills
Copy link
Contributor

bcmills commented Aug 25, 2021

  1. Atomics are cheaper for our use case than the general-purpose sync.Mutex already contained in log.Logger

Yes. Way cheaper, as the number of CPU cores in use grows: acquiring a sync.Mutex invalidates the cache line containing the mutex, whereas an atomic load (that does not modify the value) doesn't invalidate anything in the steady state.

  1. We are reasonably confident in our ability to mix 2 synchronization devices (Mutex + Atomics) in the log package implementation without introducing new data race hazards

sync.Map already aggressively mixes synchronization primitives. It's fine. 😅

@rsc rsc moved this from Likely Accept to Accepted in Proposals (old) Sep 1, 2021
@rsc
Copy link
Contributor

rsc commented Sep 1, 2021

No change in consensus, so accepted. 🎉
This issue now tracks the work of implementing the proposal.
— rsc for the proposal review group

@rsc rsc changed the title proposal: log: optimize SetOutput(io.Discard) log: optimize SetOutput(io.Discard) Sep 1, 2021
@rsc rsc modified the milestones: Proposal, Backlog Sep 1, 2021
@gopherbot
Copy link

Change https://golang.org/cl/348741 mentions this issue: log: don't format if writing to io.Discard

@dmitshur dmitshur modified the milestones: Backlog, Go1.18 Oct 25, 2021
@golang golang locked and limited conversation to collaborators Oct 25, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
No open projects
Development

No branches or pull requests

10 participants