Title describes much of it on its own, and a bigger explanation is below in the "additional context" section, but basically:
*Logger.Info("msg", zap.Object("key", value)) checks if the log-level is enabled before serializing its Fields, which can be a significant cost-savings. Particularly for debug-oriented logs, which are sometimes extremely frequently produced, and may include very large objects, both of which may be unreasonable in production environments.
Unfortunately it also requires repeating the fields every time it is used. And it re-encodes everything every time.
*Logger.With(zap.Something(...)) is extremely convenient for adding default fields for convenience, consistency, and enriching logs without changing the things that actually do the logging, and doing the encoding up-front means it is only done once. But its "serialize Fields immediately" behavior is unnecessary and undesirable if a log is never actually produced.
So I'd love a *Logger.WithLazy(...) method, or lazy.Object(...) fields, or something to be able to defer that encoding until it is actually necessary, ideally also preventing duplicate serialization.
Or maybe log-level-oriented fields like With(info.Object(...))? ...though that runs into issues if the level is changed after With(...).
I dunno. Let's discuss options!
Is this a breaking change?
If added to *(Sugared)Logger as a new method, probably not.
Field may be non-breaking as well... but it might need some questionable contortions because it's used as a value everywhere, not a pointer. And it's extremely simple and everything on it is public currently, and it may be a shame to lose that. Field is also used practically everywhere, so we likely can't introduce a new LazyField type.
Unfortunately zapcore.Core can't change its interface, and we probably can't change semantics about Check and Write in this way, so all associated behavior likely has to be implemented before handing off behavior to cores.
Alternatives
A zapcore.Core could implement this, it just needs to save the fields passed to With(...) instead of immediately encoding them like *ioCore does... but the savings are questionable if it's not shared across all cores. And some(?) existing cores probably cannot change their default behavior either, if users are relying on the current performance characteristics.
So an "external" implementation could be much more impactful, and something visible at user-level callsites can also allow users to be clear about their intent.
Additional context
I have three primary motivations, the first being the most recent:
Improving users' func signatures
func doThing(logger *zap.Logger, useful, args, thingOnlyUsedForLogging) {
for /* 100 times */ {
if oneInABillionUnlikelyThingOccurs {
logger.Warn("stuff", zap.Any("key", thingUsedOnlyForLogging))
}
}
}
Since thingOnlyUsedForLogging is passed into the func, it's hard to know what the func is going to do with it (including after future changes), so it raises unnecessary questions like "does doThing modify field Y or compare it with useful-arg-1?". In this case they're easy to check and say "nope", but it still hurts to look at and question every time, and sometimes it's far from simple.
So I'd really like to remove it, and end up with a func signature like this:
doThing(logger.With(...), useful, args)
which makes the intent and information boundaries clear.
Unfortunately, With eagerly encodes the fields it's passed, which is 1) almost always unnecessary, and 2) sometimes costly enough to be deemed unusable (it's a big object, but very useful for troubleshooting... and this func is called many times per second, constantly). For this case, it's bad enough that we essentially cannot do that currently.
A lazily-encoded With/Field/??? of some kind would give us the best of both worlds: no encoding in the majority case, and no duplicate-encoding in a particularly unlucky case that hits that branch multiple times...
... which is often more frequent than plain statistics would imply, since problems sometimes correlate with other problems. We might have no logs for hours, and then a single call hits it 30x in a row.
Ergonomics for heavily repeated but prod-unused data
Another semi-common scenario I've seen is code like:
func doStuff(logger *zap.Logger, useful, args) {
logger = logger.With(
zap.Any("super expensive thing", useful),
zap.Any("and", "often more"))
logger.Debug("doing stuff")
// enrich it
logger = logger.With(zap.Any("yet", "more"))
// do more stuff, log progress
logger.Debug("more stuff")
// and do it all like 50x, it's a big function
if thing {
logger = logger.With(zap.Any("you get", "the picture"))
}
// ...
}
where With is being used as a pretty-significant ergonomics and consistency improvement over repeating potentially a dozen or more sometimes-conditional fields all over the place.
Unfortunately your CPU hates this one weird trick clean up your code.
Safer(?) copypasta for people who don't read docs
func (s *self) yolo(args) {
s.logger.
With(zap.Any("argh", args)).
With(zap.String("sure", "why not").
Debug("message")
}
... a pattern which has led to unused logging consuming nearly half of the CPU of multiple systems I've looked at. I suspect this primarily originates from experience with other logging frameworks, and survives off laziness.
We probably can't change With to become lazy everywhere, but sample code could be changed, which may eventually change enough habits to stem the tide. And exposure to both With and Whatever might lead them to question what the difference is, which is a good spot to teach them about when encoding occurs.
Title describes much of it on its own, and a bigger explanation is below in the "additional context" section, but basically:
*Logger.Info("msg", zap.Object("key", value))checks if the log-level is enabled before serializing its Fields, which can be a significant cost-savings. Particularly for debug-oriented logs, which are sometimes extremely frequently produced, and may include very large objects, both of which may be unreasonable in production environments.Unfortunately it also requires repeating the fields every time it is used. And it re-encodes everything every time.
*Logger.With(zap.Something(...))is extremely convenient for adding default fields for convenience, consistency, and enriching logs without changing the things that actually do the logging, and doing the encoding up-front means it is only done once. But its "serialize Fields immediately" behavior is unnecessary and undesirable if a log is never actually produced.So I'd love a
*Logger.WithLazy(...)method, orlazy.Object(...)fields, or something to be able to defer that encoding until it is actually necessary, ideally also preventing duplicate serialization.Or maybe log-level-oriented fields like
With(info.Object(...))? ...though that runs into issues if the level is changed afterWith(...).I dunno. Let's discuss options!
Is this a breaking change?
If added to
*(Sugared)Loggeras a new method, probably not.Fieldmay be non-breaking as well... but it might need some questionable contortions because it's used as a value everywhere, not a pointer. And it's extremely simple and everything on it is public currently, and it may be a shame to lose that.Fieldis also used practically everywhere, so we likely can't introduce a newLazyFieldtype.Unfortunately
zapcore.Corecan't change its interface, and we probably can't change semantics aboutCheckandWritein this way, so all associated behavior likely has to be implemented before handing off behavior to cores.Alternatives
A
zapcore.Corecould implement this, it just needs to save the fields passed toWith(...)instead of immediately encoding them like*ioCoredoes... but the savings are questionable if it's not shared across all cores. And some(?) existing cores probably cannot change their default behavior either, if users are relying on the current performance characteristics.So an "external" implementation could be much more impactful, and something visible at user-level callsites can also allow users to be clear about their intent.
Additional context
I have three primary motivations, the first being the most recent:
Improving users' func signatures
Since
thingOnlyUsedForLoggingis passed into the func, it's hard to know what the func is going to do with it (including after future changes), so it raises unnecessary questions like "doesdoThingmodify field Y or compare it with useful-arg-1?". In this case they're easy to check and say "nope", but it still hurts to look at and question every time, and sometimes it's far from simple.So I'd really like to remove it, and end up with a func signature like this:
which makes the intent and information boundaries clear.
Unfortunately,
Witheagerly encodes the fields it's passed, which is 1) almost always unnecessary, and 2) sometimes costly enough to be deemed unusable (it's a big object, but very useful for troubleshooting... and this func is called many times per second, constantly). For this case, it's bad enough that we essentially cannot do that currently.A lazily-encoded
With/Field/???of some kind would give us the best of both worlds: no encoding in the majority case, and no duplicate-encoding in a particularly unlucky case that hits that branch multiple times...... which is often more frequent than plain statistics would imply, since problems sometimes correlate with other problems. We might have no logs for hours, and then a single call hits it 30x in a row.
Ergonomics for heavily repeated but prod-unused data
Another semi-common scenario I've seen is code like:
where
Withis being used as a pretty-significant ergonomics and consistency improvement over repeating potentially a dozen or more sometimes-conditional fields all over the place.Unfortunately your CPU hates this one weird trick clean up your code.
Safer(?) copypasta for people who don't read docs
... a pattern which has led to unused logging consuming nearly half of the CPU of multiple systems I've looked at. I suspect this primarily originates from experience with other logging frameworks, and survives off laziness.
We probably can't change
Withto become lazy everywhere, but sample code could be changed, which may eventually change enough habits to stem the tide. And exposure to bothWithandWhatevermight lead them to question what the difference is, which is a good spot to teach them about when encoding occurs.