How to do trace logging in Go with very low cost for disabled log statements

Question

It is useful to leave low-level debug/trace logging statements in critical paths so that they can be enabled by runtime configuration. The idea is you never turn such logging on in production (it would cripple performance) but you can turn it on in a production environment (e.g. production system taken offline for debugging or a test system that is set up exactly like the production system.)

This type of logging has a special requirement: the cost of hitting a disabled log statement on a critical path must be very low: ideally a single boolean test.

In C/C++ I would do this with a LOG macro that does not evaluate any of its arguments until it has checked a flag. Only if enabled do we call some helper function to format & deliver the log message.

So how to do this in Go?

Using io.Discard with log.Logger is a non starter: it completely formats the log message every time before throwing it away if disabled.

My first thought is

type EnabledLogger struct { Enabled bool; delegate *log.Logger;... }
// Implement the log.Logger interface methods as:
func (e EnabledLogger) Print(...) { if e.Enabled { e.delegate.Output(...) } }

This is close. If I say:

myEnabledLogger.Printf("foo %v: %v", x, y)

It won't format or log anything if disabled but it will evaluate the arguments x and y. That's OK for basic types or pointers, not OK for arbitrary function calls - e.g. to stringify values that don't have a String() method.

I see two ways around that:

Wrapper types to defer the call:

type Stringify { x *Thing }
func (s Stringify) String() { return someStringFn(s.x) }
enabledLogger.Printf("foo %v", Stringify{&aThing})

Wrap the whole thing in a manual enabled check:

if enabledLog.Enabled {
     enabledLog.Printf("foo %v", someStringFn(x))
}

Both are verbose and error prone, it is too easy for someone to forget a step and quietly introduce a nasty performance regression.

I'm starting to like Go. Please tell me it can solve this problem :)

Answer 1

All arguments in Go are guaranteed to be evaluated, and there's no defined preprocessor macros in the language, so there's only a couple things you can do.

To avoid expensive function calls in the logging arguments, make use of the fmt.Stringer and fmt.GoStringer interfaces to delay formatting until the function is executed. That way you can still pass the plain types to Printf functions. You can extend this pattern yourself with a custom logger that checks for various interfaces as well. This is what you're using in your Stringify example, and you can only really enforce it with code review and unit tests.

type LogFormatter interface {
    LogFormat() string
}

// inside the logger
if i, ok := i.(LogFormatter); ok {
    fmt.Println(i.LogFormat())
}

You can also swap out the entire logger out at runtime via a logger interface, or replace it entirely at build time using build constraints, but still requires ensuring no expensive calls are inserted into the logging arguments.

Another pattern used by some packages like glog is to make the Logger itself a bool. This doesn't eliminate the verbosity completely, but it makes it a little more terse.

type Log bool
func (l Log) Println(args ...interface{}) {
    fmt.Println(args...)
}

var debug Log = false

if debug {
    debug.Println("DEBUGGING")
}

The closest you can get to a macro pre-processing in go is to use code generation. This isn't going to work for runtime configurable tracing, but could at least provide a separate debug build that can be dropped into place when needed. It can be as simple as gofmt -r, building a file using text/template, or full generation by parsing the code and building an AST.

Answer 2

First of all, I should say that I personally would go with the simplest solution and just use an if. But if you really want to do it reliably, you can use anonymous functions:

type verbose bool

func (v verbose) Run(f func()) {
    if v {
        f()
    }
}

Use it like this:

v := verbose(false)
v.Run(func() {
    log.Println("No Print")
})

Playground example with expensive calls: http://play.golang.org/p/9pm2HoQQ8A.