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.

[ChrisHines]

Of course that works @ianthehat , but the slog API does not guide a developer to write code that way and it is not as nice on the eyes as using logger.With, so I think it is ergonomically poor. I think it is very unfortunate to publish an API that results in the most convenient way to use it being the wrong thing to do in common scenarios. The slog.Group("", attrs...) trick is clever, but I don't want to have to repeatedly explain that in code review as either the author or the reviewer.

I think we should strive for much better, especially in the standard library.

[jba]

Making Logger.With cheap enough to use that way is largely independent of whether Logger is a value type or not.

Yes, it's a bit faster if it's a value type. But more fundamentally, it must call Handler.WithAttrs to give the Handler a chance to preformat, and that means the Handler will probably need to do an allocation to keep track of the Attrs and return a clone of itself. We know from Zap that preformatting is an important optimization, and a Handler must do something—presumably an allocation, though maybe there is a clever alternative—to return something that holds the new Attrs and isn't aliased to another Logger's Handler.

So I don't see Logger.With approaching the speed of building a []Attr.

[pohly]

I feel that this particular code example is distracting from the underlying question: in cases where Logger.With is useful, can we make it faster by copying by value? Not doing so seems like a missed opportunity to avoid some overhead.

If the argument is that "Logger.With is slow anyway because the handler must do something", then let's look at a potential future Logger.WithCallDepth: that is a call that will be implemented entirely in slog because that is where stack unwinding is done, so the handler will be the same in the original Logger and the modified one.

[jba]

Another argument against making Logger a value: it would be much harder to add to it in the future. For example, here I discuss adding a Helper function to Logger, like testing.T.Helper. That is unlikely to happen, but if it did, then Logger would need a mutex and a map. It would be impossible to add the mutex if Logger was a value type (you can't copy mutexes). That's just an example of how making it a value would constrain us.

Whether it's worth it just to speed up Logger.With is still not clear to me. I intend to write a benchmark that matches what I think is its typical use: one call to Logger.With followed by, say, four calls to Logger.LogAttrs, using a built-in handler writing to io.Discard. I suspect the performance gain will be small in that scenario. I will try to get to that this week.

[pohly]

it would be much harder to add to it in the future

Ack.

what I think is its typical use

That's the problem - estimating what "typical usage" is...

By choosing pointer over value slog discourages contextual logging where a modified logger gets passed down a call chain. 🤷

[rsc]

Discouraging overuse of fluent APIs doesn't seem like a bad thing to me. I believe we should stick with the pointers. The potential future growth of the logger, as raised by @jba, is another important concern. When we needed to add monotonic time info to time.Time (a pure value struct) we had to work hard to keep it from growing.

Also, the benchmark does not match real-world usage. In real usage, when a logger is passed to a small, analyzable routine, the compiler will see that it does not escape, and logger.With will be inlined, and the allocation will be made on the stack. The benchmark is going out of its way to avoid the stack allocation. And when the logger is passed to a large function, chances are that allocation is in the noise.

[ianthehat]

A counter argument (that does not involve fluent APIs).
To me, the point of the package is to make all the possible logging front ends and back ends interoperate, and Handler is the heart of that.
Logger is just a cosmetic layer, everything that Logger does could just have easily been a free function that takes a handler as it's first argument, Logger exists because myLogger.Info("my message") is fractionally prettier than slog.Info(myHandler, "my message"), and I think that is an important property.
I also expect that many packages will choose a different cosmetic layer, and I am good with that, so long as all the cosmetic layers use a Handler underneath, we get a healthy ecosystem.
The problem with passing Logger by pointer is that every time you hit a cosmetic layer boundary (like when you invoke a package that wants a different cosmetic layer to the one you are using) you need to write code like slog.New(logger.Handler()) to get a slog.Logger from whatever cosmetic logger you are using. That is the allocation I want to avoid.

[jba]

I benchmarked logger.With("a", 1, "b", 2) followed by 0 to 4 calls to logger.Info("msg", "c", 3), using a TextHandler writing to io.Discard.

Using a value Logger was about 7% faster with 0 calls, but by 2 calls it was 1.5% faster and by 4 calls the difference was statistically negligible.

[pohly]

I also expect that many packages will choose a different cosmetic layer, and I am good with that, so long as all the cosmetic layers use a Handler underneath, we get a healthy ecosystem.

This looks increasingly like what I'll propose for Kubernetes. A lot of code there is built around the go-logr/logr.Logger API and (as discussed here and elsewhere) slog.Logger is not a full replacement. Instead of going through a long and painful transition where we remove features, we can instead make it trivial for someone to create a logr.Logger for a slog.Handler and then Kubernetes packages will work well in the wider ecosystem.

The problem with passing Logger by pointer is that every time you hit a cosmetic layer boundary (like when you invoke a package that wants a different cosmetic layer to the one you are using) you need to write code like slog.New(logger.Handler()) to get a slog.Logger from whatever cosmetic logger you are using.

This only affects the "non-slog.Logger to slog.Logger" transition, but for that it is a valid point. The other API might construct a logger value and then doesn't need to allocate - logr does that.

[rsc]

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]

time.Time was mentioned above. Speaking as someone who has had to extend time.Time over time and been quite constrained by needing to keep it small to make being a value reasonable, changing Logger to be a struct will limit us considerably in the future. It does not seem worth painting ourselves into that corner.

[ianthehat]

I don't think it would paint you into a corner, if you really needed additional fields, you just make Logger point to an intermediate that held the handler and the extra fields, which would essentially put you right back where we are now in terms of allocations and cost.

[jba]

That would result in shared state on a copy, which might be wrong.

[pohly]

My two cents: as seen in the proposal to add WithCallDepth, Logger is meant to be just a thin convenience layer around Handler. It seems very unlikely that this will change, whereas the use case from #59126 (comment) with constructing a new Logger from an existing Handler seems more likely. So which use case should the implementation prefer?

Having said that, I'm fine with whatever gets decided.

[rsc]

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

[rsc]

No change in consensus, so declined.
— rsc for the proposal review group