Logging at disabled level is far from free

[forax]

I've written a simple JMH test that test log4j, logback, java.util.logging ang flogger (with the system backend).

When the logging is disable, Flogger is faster than log4j and logback but slower than java.util.logging.
Did i have done something wrong ?

[hagbard]

As with all benchmarks, it depends greatly on what you are measuring and how.

Flogger's claims around "cheap disabled log statements" relate to logger usage where you pass multiple parameters. Consider:
jdkLogger.fine(String.format("Hello %s", world))
jdkLogger.fine("Hello " + world)

Which both do work at the call site to construct and copy a string that's never used.
logger.atFine().log("Hello %s", world)
allocates no objects and does only a minimal amount of work to check the log level.

Obviously it's hard to beat:
jdkLogger.fine("constant string");
since that should be a volatile read, level check and branch, but that's not what the average log statement looks like (at least not in Google).

Avoiding allocation is particularly important, since fine logging is typically hit orders of magnitude more often than the normally enabled levels. Even if it's fast at the log site, if it allocates memory it increases garbage collector pressure (more frequent GC events, more object churn etc...).

If you have your benchmarks available, I'd be happy to take a look.

[forax]

I've only tested
logger.fine("constant string");

see https://github.com/forax/beautiful_logger/blob/master/src/test/java/com.github.forax.beautifullogger.perf/com/github/forax/beautifullogger/perf/LoggerDisabledBenchMark.java#L238

what if there was a way to really pay no cost (no volatile read, no branch) ?

[hagbard]

We have worked hard for the (still internal) Android version of Flogger to make sure that tools like Proguard can identify disabled log statements and completely remove them (including loggers and variable setup). However this requires bytecode rewriting and would probably not really help much on servers with hotspot compilation anyway (and it obviously doesn't let you re-enable logging at run time either). Unfortunately this is still not quite ready to be open-sourced for frustrating technical reasons I can't really go into.

As for the server side code, the log context is deliberately bi-morphic (only 2 specific subtypes per logger; the real context and the no-op one). This is helpful because virtual method dispatch to bi-morphic types is special cased by most hotspot VMs. Thus if a log statement is seen to be "always disabled" then the fast-path generated by the hot-spot compiler will be very fast (it's likely to rewrite the call to hoist the logging check into the calling code). Essentially it's as fast as well can make it with our benchmarks (and we've tried all sorts of tricks).

Obviously if you can see any way to improve performance for disabled log statement I'd be very interested, but most of the win already comes from the API design in avoiding varags and auto-boxing (rather than super optimized code).

I'll close this for now since I don't plan on changing anything at the moment, but feel free to re-open if you have ideas.

[forax]

Since Java 7, you can create your own inlining cache in Java code (like the bimorphic inlining cache of hotspot) using the java.lang.invoke API. This API also comes with a way to trigger code de-optimization (j.l.i.SwitchPoint) so instead of having a volatile read, you can trigger the de-optimization of the logging code when the configuration change making a call to a logger that doesn't log really free.

You may not believe me so there is a simple test:
get jar of the logger from https://github.com/forax/beautiful_logger (the jar is on JitPack) and write a simple JMH test that compare the speed of flogger with that logger, you will see that when there is nothing to log, this logger is faster that flogger, in fact it's as fast as having an empty method.

Note: the code is a little complex because it is Java 8 to 11 compatible and the way to get the caller class in 8 and 9 has changed.