Logging API

[John Rose]

On May 22, 2012, at 1:38 PM, Adam Hawthorne wrote:

> I think Hotspot is currently able to inline that method.  It also seems
> like allocating a lambda should be side-effect free.  If so, might we
> expect the VM to be smart enough in JDK 8 to know that it can push the
> allocation inside that 'if' (assuming it's not used for anything else)?

This question made me curious.  In the Hotspot JVM we have various bits of escape analysis, etc., but there is always a question of what happens in some specific use case.  I tried a few use case combinations and noted the results in this file:
  https://blogs.oracle.com/jrose/resource/code/EALogTest.zip

I got the usual answer.  The JVM can optimize some use cases but not all, and will require more work to optimize a wider variety of cases.

One bright spot:  Closures (or simple "message objects") will optimize better than random formatted strings.

One dim spot:  You currently have to use "static final" configuration variables, or the compiler will assume you might decide to log something at any moment.

(I'm going back to lurk mode now.)

— John

P.S.  Here's the whole file.

/*
  Demonstration of optimization of a log-like API.
  Requires constant (static final) log level setting, or else "as if final" stable value optimization.
  Requires simple (not StringBuffer) object message argument to log function.

  Test cases:
  $ java -DLOG_LEVEL=0 EALogTest   # hello() optimizes to null routine
  $ java -DLOG_LEVEL=1 EALogTest   # hello() builds a simple Greeting, and queues it
  $ java -DLOG_EXCITEMENT=1 EALogTest  # hello() does StringBuffer stuff, and throws it away
  $ java -DLOG_{LEVEL,EXCITEMENT}=1 EALogTest  # hello() does StringBuffer stuff, and queues it

  To observe the object code, put hsdis-amd64.{dll,so,dylib} on your LLP and:
  $ java -XX:CompileCommand=print,EALogTest.hello -Xbatch -XX:+UnlockDiagnosticVMOptions -XX:+Print{Compilation,Inlining} -XX:+LogCompilation EALogTest
  Ref: https://wikis.oracle.com/display/HotSpotInternals/PrintAssembly

  Conclusion:  Hotspot JVM has sufficient if limited EA capability
  to remove unused log message construction, if log switch is "static final",
  and if the log messages are simple objects (lambdas should work).

  Desirable future work:
  - optimistically constant-fold stable values (as if they were declared final) until they change
  - allow side-effect-free object creation code to move down past an 'if', if it is dead on one branch
  - eliminate string formatting code if it goes unused
 */

class EALogTest {
    public static void main(String... av) {
        System.out.println("Preparing greetings...  (L/E="+LOG_LEVEL+"/"+LOG_EXCITEMENT+")");
        helloStorm("City", 100000);
        helloStorm("State", 100000);
        maybeChangeLogLevel();
        helloStorm("World", 100000);
    }
    static void maybeChangeLogLevel() {
        if (LOG_LEVEL == 1)  return;
        //LOG_LEVEL = 1;
        try {
            java.lang.reflect.Field LOG_LEVEL = EALogTest.class.getDeclaredField("LOG_LEVEL");
            if ((java.lang.reflect.Modifier.FINAL & LOG_LEVEL.getModifiers()) == 0) {
                LOG_LEVEL.setInt(null, 1);
                System.out.println("set LOG_LEVEL to 1");
            } else {
                System.out.println("cannot set LOG_LEVEL (it is final)");
            }
        } catch (Exception ex) {
            throw new RuntimeException("cannot touch LOG_LEVEL!", ex);
        }
    }

    static void helloStorm(String who, int count) {
        for (int i = 0; i < count; i++)
            hello(who);
    }
    static void hello(String who) {
        if (LOG_EXCITEMENT > 0)
            // Much harder to EA!
            logMsg("HELLO, "+who);
        else
            logMsg(new Greeting(who));
    }
    static class Greeting {
        final String who;
        Greeting(String who) { this.who = who; }
        public String toString() { who.toString(); return "Hello, "+who; }
    }

    static void logMsg(Object msg) {
        if (LOG_LEVEL > 0) {
            int ptr = LOG_SINK_PTR + 1;
            if (ptr == 0)  System.out.println(msg);
            if (ptr == LOG_SINK.length)  ptr = 0;
            LOG_SINK[LOG_SINK_PTR = ptr] = msg;
        }
    }
    static
        final // this modifier is important, pending JVM optimizations for stable values
        int LOG_LEVEL = Integer.parseInt(System.getProperty("LOG_LEVEL", "0"));
    static final int LOG_EXCITEMENT = Integer.parseInt(System.getProperty("LOG_EXCITEMENT", "0"));
    static Object[] LOG_SINK = new Object[100];
    static int LOG_SINK_PTR = -1;
}