Dead-code elimination: Java Logging

In my previous article, we have seen how the Java compiler (javac), inlines final declared variables as a compile-time optimisation.

Today, we are going to focus in dead-code elimination. Dead-code elimination is the process, where the compiler removes part of code that will never be executed.

Java logging: a simple use case

Let's say that we need to build a simple logging facility for our Java program and the requirements indicate to have the classic interface of methods; info and debug.

The tricky part with the logging, is that usually it is some kind of string, serialized. The anti-pattern that happens all the time, is that the string message is usually evaluated, even if the logging level ignores it in the end.

So, this is the Logging class:

public class Logger {
    private final static Logger defaultInstance;
    private final static boolean debugMode = true;

    static {
        defaultInstance = new Logger();
    }

    private Logger() {
        // empty
    }

    public void info(String fmt, Object ... args) {
        System.out.printf(fmt, args);
    }

    public void debug(String fmt, Object ... args) {
        if (debugMode) {
            System.out.printf(fmt, args);
        }
    }
 
    public static Logger getInstance() {
        return defaultInstance;
    }
}

Note that there is a boolean attribute of the Logger class, which dictates if our program is in debug mode or not.

Of course, we also need a Main class to test this logging facility.

public class Main {

    public static void main(String[] args) {
        Logger logger = Logger.getInstance();

        logger.info("this is an infomartional log");
        logger.debug("this is a debug log");
    }
}

As you can see, Logger is a singleton class, we retrieve the instance of it through getInstance method, then we print an info-level log message and a debug-level.

The trick with a twist

Our goal is to enable the compiler to enable dead-code elimination feature. Keep in mind that the Java compiler, avoids to do excessive optimization on the code generation level, because if so, JIT (just-in time) compiler ends up having minimized benefit. Even so, dead-code elimination exists :).

private final static boolean debugMode = true;

If we compile the Logger class, with the debugMode set to true, and then decompile the class, we get the following result:

% javap -c Logger 
Compiled from "Logger.java"
public class Logger {
  public void info(java.lang.String, java.lang.Object...);
    Code:
       0: getstatic     #9                  // Field java/lang/System.out:Ljava/io/PrintStream;
       3: aload_1
       4: aload_2
       5: invokevirtual #15                 // Method java/io/PrintStream.printf:(Ljava/lang/String;[Ljava/lang/Object;)Ljava/io/PrintStream;
       8: pop
       9: return

  public void debug(java.lang.String, java.lang.Object...);
    Code:
       0: getstatic     #9                  // Field java/lang/System.out:Ljava/io/PrintStream;
       3: aload_1
       4: aload_2
       5: invokevirtual #15                 // Method java/io/PrintStream.printf:(Ljava/lang/String;[Ljava/lang/Object;)Ljava/io/PrintStream;
       8: pop
       9: return

  public static Logger getInstance();
    Code:
       0: getstatic     #21                 // Field defaultInstance:LLogger;
       3: areturn

  static {};
    Code:
       0: new           #1                  // class Logger
       3: dup
       4: invokespecial #25                 // Method "<init>":()V
       7: putstatic     #21                 // Field defaultInstance:LLogger;
      10: return
}

It is apparent, that everything is in order. We can see the constructor and the implementation of the logging methods.

If you examine closely, you will see a minor simplification. The following code,

if (debugMode) {
     System.out.printf(fmt, args);
}

is automatically reduced to,

System.out.printf(fmt, args);

because the compiler understood at compile-time that the debugMode is always true.

So, what happens if you se debugMode to false?

% javap -c Logger
Compiled from "Logger.java"
public class Logger {
  public void info(java.lang.String, java.lang.Object...);
    Code:
       0: getstatic     #9                  // Field java/lang/System.out:Ljava/io/PrintStream;
       3: aload_1
       4: aload_2
       5: invokevirtual #15                 // Method java/io/PrintStream.printf:(Ljava/lang/String;[Ljava/lang/Object;)Ljava/io/PrintStream;
       8: pop
       9: return

  public void debug(java.lang.String, java.lang.Object...);
    Code:
       0: return

  public static Logger getInstance();
    Code:
       0: getstatic     #21                 // Field defaultInstance:LLogger;
       3: areturn

  static {};
    Code:
       0: new           #1                  // class Logger
       3: dup
       4: invokespecial #25                 // Method "<init>":()V
       7: putstatic     #21                 // Field defaultInstance:LLogger;
      10: return
}

You can see that the code from the debug method is completely eliminated. The question now is, “is it also removed from the main class”?

Let's decompile it.

% javap -c Main 
Compiled from "Main.java"
public class Main {
  public Main();
    Code:
       0: aload_0
       1: invokespecial #1                  // Method java/lang/Object."<init>":()V
       4: return

  public static void main(java.lang.String[]);
    Code:
       0: invokestatic  #7                  // Method Logger.getInstance:()LLogger;
       3: astore_1
       4: aload_1
       5: ldc           #13                 // String this is an infomartional log
       7: iconst_0
       8: anewarray     #2                  // class java/lang/Object
      11: invokevirtual #15                 // Method Logger.info:(Ljava/lang/String;[Ljava/lang/Object;)V
      14: aload_1
      15: ldc           #19                 // String this is a debug log
      17: iconst_0
      18: anewarray     #2                  // class java/lang/Object
      21: invokevirtual #21                 // Method Logger.debug:(Ljava/lang/String;[Ljava/lang/Object;)V

So, the debug method call is not removed from the runtime and it is expected to be honest, since it will change the program in an intrusive way.

The twist

With this strategy on the implementation, we are introducing the (String fmt, Object … args) at the method level, allowing the log message serialization to calculated lazily. So, when you have debugMode set to false, the overhead is zero.

Epilogue

Logging is just a use case that this compiler hacking can be used in order to improve the executable code and maybe use it to act as a preprocessor. But I can see many use cases, where this approach could differentiate the generated bytecode, tailoring it to a custom runtime environment with specific requirements.