log: optimize SetOutput(io.Discard)

[Deleplace]

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.

[Deleplace]

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

[Deleplace]

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]

cc @robpike

[rittneje]

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]

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]

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

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]

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

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

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]

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)