Reduced logging overhead by deferred string building

[Markus KARG]

Like any non-trivial program, the Babbler library makes strong use of logging. Most logged information in fact is not intended to be presented to the end user, but is merely existing for tracing purposes in case of failure. Rather most logging code is dealing with messages never ever being actually logged in production environment, hence are logged with levels of FINE.

While this is absolutely correct use of the Java Logging API, it bears potential of unnecessary code execution, resulting in effects like processing overhead (i. e. inappropriate power consumption), cache locality desturbance, and heap fragmentation: In case message strings are built at runtime, i. e. concatenated from one or more template literals concatenated with one or more parameters. The reason simply is that lines like LOGGER.log(Level.FINE, String.format("Problem '%s' at line %d!", error, line)); will execute string-building even in case the provided logging level is not being handled by any handler or not being logged by any logger! As we all learned in the early days of Java programming, String concatenation is expensive, because each concatenation implies the technical need to do a full copy of both concatenated terms, hence multiple concatenations copy over and over again the same bytes (and, remember, Java's UNICODE String class implies two bytes in memory per single character). String.format() is an optimization, but cannot reduce the fact that it provides at least one full copy, still.

There are two effective and highly advised solutions:

• Before Java 8

  Let the Java Logging API build the string for you. It is guaranteed that it will do this only in case the logging level is active: LOGGER.log(Level.FINE, "Problem '{0}' at line {0}!", error, line);

• Since Java 8

  Provide a supplier to the Logging API. It is guaranteed that it will be requested to provide a message string only in case the logging level is active: LOGGER.log(Level.FINE, () -> String.format("Problem '{0}' at line {0}!", error, line));

[Christian Schudt]

I love your issue descriptions :-) Didn't know about the {0} trick... Checked the code and logging with String concatenation or String.format is only performed at one place. Unfortunately there's no var-args log() method for more than 1 param (as you suggested).

What about if(logger.isLoggable(Level.FINE)) before actually logging? I guess it's a valid alternative, too.

[Christian Schudt]

Ok, found a few more, but they all take a Throwable, too. JUL failed to provide a method for a parameterized string AND a Throwable.

Will keep this open until on Java 8

[Markus KARG]

Funny, so I stumbled about just the sole place when I thought I should tell you that trick. :-)

Yes, it was more an idea for a Java 8 overhaul. I wrote it down so I don't forget it later. Maybe we should have a "Java8" Tag for tickets like this?

[Christian Schudt]

I don't think bitbucket's issue tracker allows "tags".

[Christian Schudt]

Reduce logging overhead by deferred string building.

Fixes Issue #25.

→ <<cset be755ec1bf7e>>