java.lang.invoke whisper to the JIT for speed gain

Use java.lang.invoke to implement a 'no cost if not enabled 'Logger API

Transcript

1. 1 java.lang.invoke whisper to the JIT for speed gain Rémi Forax
3. 3 Me, myself and I Java Champion OpenJDK amber & valhalla ex: jigsaw, lambda, invokedynamic
4. 4 public class HelloLog { private static final Logger LOGGER = LogManager.getLogger(HelloLog.class); public static void main(String[] args) { LOGGER.debug("should not be printed !"); } } Log4J2: Performance of a disabled logger ??
5. 5 With JMH log4j2_disabled_text 1.081 ns/op +/- 0.004 no_op 0.272 ns/op +/- 0.005
6. 6 public class HelloLog { private static final Logger LOGGER = LogManager.getLogger(HelloLog.class); public static void main(String[] args) { LOGGER.debug(() -> "should not be printed !"); } } Performance of a disabled logger ?? (v2)
7. 7 public class HelloLog { private static final Logger LOGGER = LogManager.getLogger(HelloLog.class); public static void main(String[] args) { if (LOGGER.isDebugEnabled()) { LOGGER.debug("should not be printed !"); } } } Performance of a disabled logger ?? (v3)
8. 8 With JMH log4j2_disabled_text 1.081 ns/op +/- 0.004 log4j2_disabled_lambda 1.080 ns/op +/- 0.003 log4j2_disabled_block 1.081 ns/op +/- 0.004 no_op 0.272 ns/op +/- 0.005
10. 10 A mooar simple Logger public class SimpleLogger { public enum Level { WARNING, DEBUG } final Level level; public SimpleLogger(Level level) { this.level = level; } public boolean isDebugEnabled() { return level.compareTo(Level.DEBUG) <= 0; } public void debug(String message) { if (isDebugEnabled()) { System.err.println(message); } } }
11. 11 A mooar simple Logger (v2) public class SimpleLogger { public enum Level { WARNING, DEBUG } final Level level; public SimpleLogger(Level level) { this.level = level; } public boolean isDebugEnabled() { return level.ordinal() - Level.DEBUG.ordinal() <= 0; } public void debug(String message) { if (isDebugEnabled()) { System.err.println(message); } } } class Enum { final int ordinal; public int ordinal() { return ordinal; } }
12. 12 With JMH log4j2_disabled 1.081 ns/op +/- 0.004 simple_logger 0.679 ns/op +/- 0.007 no_op 0.272 ns/op +/- 0.005
14. 14 The VM doesn’t trust final fields !!
15. 15 java.lang.invoke
16. 16 java.lang.invoke Better invocation modes than reflection Do the security check once ! Do not box by default ! Richer API bindTo(), guardWithTest(), asType(), loop(), … Introduced in 7, used by Java for Lambda creation in 8+ String concatenation in 9+
17. 17 Hello java.lang.invoke Lookup lookup = MethodHandles.lookup(); MethodHandle mh = lookup.findVirtual( PrintStream.class, "println", methodType(void.class, String.class)); mh.invokeExact(System.err, "hello java.lang.invoke");
18. 18 Partial application var lookup = MethodHandles.lookup(); var mh = lookup.findVirtual(PrintStream.class, "println", methodType(void.class, String.class)); mh = mh.bindTo(System.err); mh.invokeExact("hello java.lang.invoke");
19. 19 Drop Arguments var mh = lookup.findVirtual(PrintStream.class, "println", methodType(void.class, String.class)); mh = mh.bindTo(System.err); mh = MethodHandles.dropArguments(mh, 0, Level.class); mh.invokeExact(Level.WARNING, "hello java.lang.invoke");
20. 20 guardWithTest() + empty() private static boolean isDebug(Level l) { return l == Level.DEBUG || l == Level.TRACE; } var mh = lookup.findVirtual(PrintStream.class, "println", methodType(void.class, String.class)); mh = mh.bindTo(System.err); mh = MethodHandles.dropArguments(mh, 0, Level.class); var test = lookup.findStatic(Logger.class, "isDebug", methodType(boolean.class, Level.class)); var empty = MethodHandles.empty( methodType(void.class, Level.class, String.class)); var guard = MethodHandles.guardWithTest(test, mh, empty); guard.invokeExact(Level.WARNING, "warning !"); guard.invokeExact(Level.DEBUG, "debug !");
21. 21 Method Handle Tree Configuration test target fallback empty level isDebug prinln bindTo System.err dropArguments guard
22. 22 Implementation of a logger public interface Logger { default void debug(String message) { log(Level.DEBUG, message); } void log(Level level, String messsage); public static Logger getLogger(Class<?> configClass) { MethodHandle mh = getLoggingMethodHandle(configClass); return new Logger() { @Override public void log(Level level, String message) { try { mh.invokeExact(level, message); } catch (Throwable e) { throw rethrow(e); } } }; }
23. 23 With JMH log4j2_disabled 1.081 ns/op +/- 0.004 simple_logger 0.679 ns/op +/- 0.007 inner_class_logger 2.966 ns/op +/- 0.008 no_op 0.272 ns/op +/- 0.005
25. 25 The VM still doesn’t trust final fields !!
26. 26 Constant fields for the VM from http://hg.openjdk.java.net/jdk/jdk/file/49489/src/hotspot/share/ci/ciField.cpp#l204 static bool trust_final_non_static_fields(ciInstanceKlass* holder) { // Never trust strangely unstable finals: System.out, etc. if (holder->name() == ciSymbol::java_lang_System()) return false; // Even if general trusting is disabled, trust system-built closures if (holder->is_in_package("java/lang/invoke") || holder->is_in_package("sun/invoke")) return true; // Trust VM anonymous classes, can't be serialized so no field hacking if (holder->is_anonymous()) return true; // Trust final fields in all boxed classes if (holder->is_box_klass()) return true; // Trust final fields in String if (holder->name() == ciSymbol::java_lang_String()) return true; return TrustFinalNonStaticFields; }
27. 27 Implementation of a logger public interface Logger { default void debug(String message) { log(Level.DEBUG, message); } void log(Level level, String messsage); public static Logger getLogger(Class<?> configClass) { MethodHandle mh = getLoggingMethodHandle(configClass); return new Logger() { @Override public void log(Level level, String message) { try { mh.invokeExact(level, message); } catch (Throwable e) { throw rethrow(e); } } }; }
28. 28 Implementation of a logger – with a lambda public interface Logger { default void debug(String message) { log(Level.DEBUG, message); } void log(Level level, String messsage); public static Logger getLogger(Class<?> configClass) { MethodHandle mh = getLoggingMethodHandle(configClass); return (level, message) -> { try { mh.invokeExact(level, message); } catch (Throwable e) { throw rethrow(e); } }; }
29. 29 With JMH log4j2_disabled 1.081 ns/op +/- 0.004 simple_logger 0.679 ns/op +/- 0.007 inner_class_logger 2.966 ns/op +/- 0.008 lambda_logger 0.271 ns/op +/- 0.001 no_op 0.272 ns/op +/- 0.005
31. 31 So everything is fine ??
32. 32 Which one is faster ?? (for 220 elements) @Benchmark public int log4j2_sum() { int sum = 0; for(int i = 0; i < array.length; i++) { sum += array[i]; LOG4J2_LOGGER.debug("should not be printed !"); } return sum; } @Benchmark public int log4j2_foreach_sum() { int sum = 0; for(int value: array) { sum += value; LOG4J2_LOGGER.debug("should not be printed !"); } return sum; }
33. 33 With JMH log4j2_sum 1.621 ms/op +/- 0.011 log4j2_foreach_sum 1.053 ms/op +/- 0.008 nologger_sum 0.314 ms/op +/- 0.002 nologger_foreach_sum 0.315 ms/op +/- 0.003
35. 35 class CoreLogger implements Logger { static class PrivateConf { final int intLevel; final Object filter; final Conf conf; PrivateConf(int intLevel) { …; conf = new ConfImpl(null); } boolean filter(Level level, Marker marker, String msg) { Object filter = conf.getFilter(); if (filter != null) { … } return level != null && intLevel >= level.intLevel(); } } volatile PrivateConf config; CoreLogger(Level level) { this.config = new PrivateConf(level.intLevel()); } @Override public boolean isDebugEnabled() { return config.filter(Level.DEBUG, null, null); } } interface Conf { public Object getFilter(); }
36. 36 How to react to a configuration change using java.lang.invoke ??
37. 37 java.lang.invoke.SwitchPoint A boolean value that can be switch off Can create guards from it Switch off with SP.invalidateAll(new SP[] { sp }) Implemented by recording invalidation dependencies between a SP and all JITed codes that depend on it => look Ma, no volatile !
38. 38 Method Handle Tree Configuration guard test target fallback empty level isDebug prinln bindTo System.err dropArguments CS guard target fallback reset SwitchPoint get new setTarget
39. 39 Beautiful Logger Real zero overhead if disabled Programmatically configure/re-configure – 3 levels of configuration module/package/class • A SwitchPoint at each level Output to SLF4J, LOG4J, JUL, System.Logger API https://github.com/forax/beautiful_logger
40. 40 With JMH – final result log4j2_disabled 1.081 ns/op +/- 0.004 beautiful_logger_disabled 0.270 ns/op +/- 0.001 no_op 0.272 ns/op +/- 0.005
41. 41 With JMH – final result (2) log4j2_disabled 1.081 ns/op +/- 0.004 logback_disabled 1.082 ns/op +/- 0.003 jul_disable 0.699 ns/op +/- 0.007 beautiful_logger_disabled 0.270 ns/op +/- 0.001 no_op 0.272 ns/op +/- 0.005
42. 42 With JMH – final result (3) log4j2_sum 1.621 ms/op +/- 0.011 log4j2_foreach_sum 1.053 ms/op +/- 0.008 logback_sum 1.582 ms/op +/- 0.003 logback_foreach_sum 1.020 ms/op +/- 0.005 jul_sum 1.136 ms/op +/- 0.004 jul_foreach_sum 0.596 ms/op +/- 0.004 beautiful_logger_sum 0.314 ms/op +/- 0.005 nologger_foreach_sum 0.314 ms/op +/- 0.002
44. 44 Exotic classes A bestiary of classes with exotic semantics https://github.com/forax/exotic MostlyConstant A constant value that can be changed StableField A field that acts as a constant when initialized ConstantMemoizer A function that returns a constant if the argument is a constant StructuralCall To do structural call