[go: nahoru, domu]

Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Feature request: Add Fields to a logger, to be encoded lazily only if a log is produced later #1121

Open
Groxx opened this issue Jun 25, 2022 · 1 comment
Labels

Comments

@Groxx
Copy link
Groxx commented Jun 25, 2022

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.

@Groxx 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
@Groxx
Copy link
Author
Groxx commented 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Development

No branches or pull requests

2 participants