logoalt Hacker News

layer8 • yesterday at 7:32 PM • 2 replies • view on HN

All common logging backends create a LogEvent or similar object for each logging call, and logging calls also typically construct new strings, which usually means a new StringBuilder object, its internal array (multiple ones if it grows), the final array it is copied to, and the String object that wraps that array.

These are typically short-lived objects and therefore cheap. Nevertheless, continually creating many such objects increases GC pressure, in particular if the logging happens in code that doesn't otherwise create many objects.

Replies

cogman10 • yesterday at 7:40 PM

Cheap, not free, and even pretty simple to accidentally fool the GC on the lifetime of these objects.

Consider, for example, if you have a log message like this

    logger.info("Hello {}", myOldObject);
if "myOldObject" is large enough or contains references to large things or has just been around for a while, it may be a part of OldGen at this point. And if that's the case, the LogEvent objects will end up automatically promoted to OldGen. Meaning the only time those can be be claimed is in an expensive major collection. The end result is that these things will ultimately fill up old gen and trigger more of the expensive old gen collections.

That's why it can be faster in some circumstances to write the more wordy

    if (logger.isInfoEnabled()) {
      logger.info("Hello {}", myOldObject.toString());
    }
Nothing saves you, however, if your string being logged is too long. It can be autopromoted to old gen if you are trying to log a 10mb string.
➕ show 1 reply
well_ackshually • yesterday at 7:38 PM

> All common logging backends create a LogEvent or similar object for each logging call, and logging calls also typically construct new strings, which usually means a new StringBuilder object, its internal array (multiple ones if it grows), the final array it is copied to, and the String object that wraps that array.

Which then gets discarded because that was a Log.verbose and your minimum log level in production is WARN.

Which is why many libraries have moved towards making your log message returned by a lambda. One constant lambda allocation (so, not a lot, an invokedynamic is absolutely fuck all.) that allows you to straight up skip allocating a full string that most likely is interpolating things and attempting to reach for context present on other threads is strictly better in 99.9% of the cases. The GC pressure is kept minimal and most importantly, constant.

➕ show 1 reply