You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
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:
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:
funcdoStuff(logger*zap.Logger, useful, args) {
logger=logger.With(
zap.Any("super expensive thing", useful),
zap.Any("and", "often more"))
logger.Debug("doing stuff")
// enrich itlogger=logger.With(zap.Any("yet", "more"))
// do more stuff, log progresslogger.Debug("more stuff")
// and do it all like 50x, it's a big functionifthing {
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.
... 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.
The text was updated successfully, but these errors were encountered:
Groxx
changed the title
Add Fields to a logger, to be encoded lazily only if a log is produced later
Feature request: Add Fields to a logger, to be encoded lazily only if a log is produced later
Jun 25, 2022
tbh my first thought is to make *Logger.With clone that does not immediately wrap the cores, but just defers it. And then in that deferred structure, actually-wrap and cache the cores the first time a Check succeeds...
... which does change semantics somewhat. And it means a Core can't change its Check behavior based on Fields, for good or bad. That can be partially patched by re-checking Check after wrapping for real (may be necessary anyway, given Core.Check documentation), but that'd only let Fields fail a Check, not pass it. Dunno if that's sufficient, and it's a bit of a weird ability imbalance.
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)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 newLazyField
type.Unfortunately
zapcore.Core
can't change its interface, and we probably can't change semantics aboutCheck
andWrite
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 toWith(...)
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
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 "doesdoThing
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:
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:
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
... 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 bothWith
andWhatever
might lead them to question what the difference is, which is a good spot to teach them about when encoding occurs.The text was updated successfully, but these errors were encountered: