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

5ce0156bc2f1864459fd77229eff3fe3?s=47 forax
April 20, 2018

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

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

5ce0156bc2f1864459fd77229eff3fe3?s=128

forax

April 20, 2018
Tweet

Transcript

  1. 1 java.lang.invoke whisper to the JIT for speed gain Rémi

    Forax
  2. 2

  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
  9. 9

  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
  13. 13

  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
  24. 24

  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
  30. 30

  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
  34. 34

  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
  43. 43

  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