proposal: log/slog: copy Logger by value instead of pointer

[pohly]

At the moment, https://pkg.go.dev/golang.org/x/exp/slog passes Logger around by pointer. The implication is that functions like Logger.With need one additional allocation, for the new Logger instance.

The alternative is to pass it as value, like go-logr does. This improves performance for With (see https://github.com/golang/exp/compare/master...pohly:exp:logger-as-value?expand=1) and others (not tested yet):

name                                    old time/op    new time/op    delta
With/Text_discard/no_parameters-36         165ns ±18%     135ns ±25%     ~     (p=0.222 n=5+5)
With/Text_discard/1_key/value_pair-36      397ns ± 2%     356ns ± 1%  -10.39%  (p=0.008 n=5+5)
With/Text_discard/5_key/value_pairs-36    1.64µs ± 1%    1.54µs ± 1%   -6.26%  (p=0.008 n=5+5)
With/JSON_discard/no_parameters-36         210ns ± 4%     175ns ± 5%  -16.38%  (p=0.008 n=5+5)
With/JSON_discard/1_key/value_pair-36      435ns ± 1%     404ns ± 3%   -7.02%  (p=0.008 n=5+5)
With/JSON_discard/5_key/value_pairs-36    2.03µs ± 1%    1.97µs ± 1%   -3.06%  (p=0.008 n=5+5)

name                                    old alloc/op   new alloc/op   delta
With/Text_discard/no_parameters-36          169B ± 0%      153B ± 0%   -9.47%  (p=0.008 n=5+5)
With/Text_discard/1_key/value_pair-36       290B ± 0%      274B ± 0%     ~     (p=0.079 n=4+5)
With/Text_discard/5_key/value_pairs-36    1.00kB ± 0%    0.98kB ± 0%   -1.70%  (p=0.008 n=5+5)
With/JSON_discard/no_parameters-36          169B ± 0%      153B ± 0%   -9.47%  (p=0.008 n=5+5)
With/JSON_discard/1_key/value_pair-36       307B ± 0%      290B ± 0%   -5.54%  (p=0.008 n=5+5)
With/JSON_discard/5_key/value_pairs-36    1.26kB ± 0%    1.24kB ± 0%   -1.35%  (p=0.008 n=5+5)

name                                    old allocs/op  new allocs/op  delta
With/Text_discard/no_parameters-36          3.00 ± 0%      2.00 ± 0%  -33.33%  (p=0.008 n=5+5)
With/Text_discard/1_key/value_pair-36       6.00 ± 0%      5.00 ± 0%  -16.67%  (p=0.008 n=5+5)
With/Text_discard/5_key/value_pairs-36      12.0 ± 0%      11.0 ± 0%   -8.33%  (p=0.008 n=5+5)
With/JSON_discard/no_parameters-36          3.00 ± 0%      2.00 ± 0%  -33.33%  (p=0.008 n=5+5)
With/JSON_discard/1_key/value_pair-36       7.00 ± 0%      6.00 ± 0%  -14.29%  (p=0.008 n=5+5)
With/JSON_discard/5_key/value_pairs-36      12.0 ± 0%      11.0 ± 0%   -8.33%  (p=0.008 n=5+5)

The downside is that the size of Logger should not grow indefinitely in the future. But that is true anyway (because these calls must clone it) and also seems unlikely.

Related to this is the question whether calling any of the methods for the null Logger should be valid. Currently they panic because Logger.handler will be nil. I think this is the right choice given that they are performance-sensitive, but I wanted to ask anyway...

[pohly]

cc @jba

[jba]

Hmm, I thought I benchmarked this and the allocation was eliminated. I'll try to replicate your benchmarks.

[pohly]

Regarding zero Logger: in go-logr, methods panicked initially like they do now in slog. We got convinced in go-logr/logr#153 to handle this by discarding log output.

[jba]

Oh, I see, the "With" benchmarks are your addition.

I didn't care about Logger.With because I don't see it as being on the critical path. I believe people will call With to set up a Logger, which you'll then use a lot. Am I wrong about that? (I know @ChrisHines thinks I am.) What is your experience?

Logger was a value type for a while because I thought a pointer type would allocate even for output methods (Logger.Info and so on). I was wrong about that, because of inlining. Using a pointer is more idiomatic; on the other hand, Loggers are immutable so a value type makes sense too.

[pohly]

Am I wrong about that?

That depends on how users do contextual logging.

One school of thought says that a logger should extract additional values from the context. Then the critical path only does context.WithValue.

The other school of thought (me including) points out that this only works in monolithic code bases where the logger configuration knows about all context keys. There also cannot be many of those, otherwise each log invocation would have to do many different context.Context.Value calls, of which most don't return anything. Then it makes more sense to create a new logger through With and pass that down into the call chain.

IMHO it would be good if slog supported both approaches equally well. Note that a future WithCallDepth (#59145) would have the same performance impact when using a pointer. In the case of WithCallDepth there's no question that this is going to be called often (= each time such a helper function gets called).

[ChrisHines]

@jba Code I've been reviewing the last few days using a different structured logging package has a flow like:

level := info
if cond1 {
    level = error
}
if cond2 {
    logger = logger.With(attr1)
}
if cond3 {
    logger = logger.With(attr2)
}
logger.Log(level, attr3, attr4, attr5)

[jba]

@ChrisHines, that code could easily be rewritten with an Attr variable, or in general with a []Attr. A more fundamental use of Logger.With in my mind is when some component takes a Logger, and you want to set some attributes for all log output from that component:

Process(filename, logger.With("file", filename))

[ChrisHines]

@jba Yes, it could be written as you suggest, but in my experience it it tends to be less convenient and noisier code. Maybe you have some idea that I haven't thought of, could you show how you would write it?

[pohly]

Loggers are immutable so a value type makes sense too.

I agree. time.Time is another example in the stdlib.

So do we have consensus that passing by value is the way to go? API design seems to allow both, and by value is more efficient.

[ianthehat]

@ChrisHines how about

level := info
var attrs []slog.Attr
if cond1 {
    level = error
}
if cond2 {
    attrs = append(attrs, attr1)
}
if cond3 {
    attrs = append(attrs, attr2)
}
logger.Log(level, slog.Group("", attrs...), attr3, attr4, attr5)

which should be much faster and only 1 extra line.

I do think that Logger should pass by value, but I think that Logger.With is a much larger hammer that should only be used for cases where you are going to re-use the logger, not for single message construction.