Overhead reduction of conditional trace/logging calls

Question

For tracing and debugging my Java code, I am using a simple Util class rather than a full-blown logging framework:

public class Util {
    public static int debugLevel;

    public static void info(String msg) {
      //  code for logfile output
      //  handling of unprintable characters
      //  etc. omitted 
      System.out.println(msg);
    }

    public static void info4(String msg) {
        if (debugLevel >= 4) {
           info(msg);
        }
    }
}

This allows compact single-line statements like the following:

info4(String.format("%16s: ", host) + Util.toHex(sidNetto));

Using a debugLevel variable, I can control the verbosity of my program. Usually, the debug level is set globally at execution start. But it can also be adjusted locally on routine level.

Basically, I save the repeated if (debugLevel >= DEBUG_ALL) {...} brackets around my trace calls. However, the parameters of the call have to be prepared and passed at runtime regardless of the debug level.

My question:

How could I nudge the compile-time optimizer or the JVM to remove superfluous trace calls? I am thinking on the lines of C/C++ function inlining.

A related question regarding C# was discussed here. But I am not sure how to port the suggested answers to Java. Another related post back from 2010 discussed similar approaches to mine. Im wondering if third-party tools like ProGuard are actually required do solve such a common task.

Answer 1

This is how most logging frameworks do it. For lightweight arguments (this includes built-in formatters which is a good best practice) do not check the level, otherwise check the level before serialising complicated string arguments.

You could use Java 8 java.util.functions.Supplier<String> for lacy evaluation, but I think there might be no performance to gain over the explicite level test case.

The logger would look like:

void debug(String ptrn, Supplier<String> args...)

And you can use it like:

debug("Hello {0}", this::getName());

Answer 2

Most logging APIs that I know suggest to check if the log level is enabled before actually calling the log method in case the message has to be prepared first, e.g.:

if (logger.isTraceEnabled()) {
    String msg = String.format("Name changed from %s to %s", oldName, newName);
    logger.trace(msg);
}

Some logging APIs like SLF4J also provide more complex log methods that accept a format string and multiple arguments, so that the log message is only built in case the log level is enabled:

logger.trace("Name changed from {} to {}", oldName, newName);

This is sufficient in most of the cases, but sometimes your message is more complex to build, or the arguments have to be converted to strings first. In this case, checking the log level is still a good approach.

Since Java 8, you could also take advantage of lambda expressions to solve this issue. Your log method could be implemented like that:

public void log(Supplier<String> messageSupplier) {
    if (isLogEnabled()) {
        String msg = messageSupplier.get();
        // TODO: log msg
    }
}

As you can see, the message is retrieved form the messageSupplier only in case logging is enabled. Thanks to lambda expressions, implementing a Supplier<String> is very easy:

logger.log(() -> String.format("Name changed from %s to %s", oldName, newName));

Update (thanks to Joshua Taylor)

Since Java 8, the java.util.logging API already supports message suppliers, e.g. see Logger#info, so you could easily exchange your logging implementation by the 'on-board' solution from JRE.

Answer 3

It seems weird to not use established logging framework due to their complexity, but worry about minor optimizations like method inlining, while ignoring the greater problem of formatting a log string irrespective of log level. But if you insist on reinventing the wheel:

The JVM (at least the Oracle hotspot JVM) automatically inlines short methods, and performs dead code elimination of unreachable branches. To be detected as unreachable, the log level of the message and the level threshold would have to be constant (compile-time constant, or static final). Otherwise, the JVM will compare logging levels on each call, though it is still likely to perform speculative inlining (inline the branch usually taken, guarded by a conditional branch instruction) which ensures that a branch instruction is only executed in the unusual case.

A much greater concern however is the cost of building the log message, which should only be incurred if the message must actually be logged. The old log4j approach of requiring calling code to check whether logging is enabled before preparing the message is rather verbose and easily forgotten. Instead, SLF4J defers string concatenation to the logging system by having the log methods take a format string and a variable number of objects to be inserted into placeholders. The SLF4J FAQ writes:

The following two lines will yield the exact same output. However, the second form will outperform the first form by a factor of at least 30, in case of a disabled logging statement.

logger.debug("The new entry is "+entry+".");
logger.debug("The new entry is {}.", entry);

It is worth noting that the arguments (here: entry) are of type Object, so their conversion to String only happens if the message actually has to be logged.

To be clear, there is no reliable way to skip evaluation of method arguments by redefining a method, because such elimination may only occur if the just in time compiler can prove the evaluation to be side effect free, which the hotspot jvm only detects if it has inlined the entire evaluation, which it will only to for very simple evaluations. Therefore, the API solution of moving formatting into the logging system is probabaly the best you can hope for.