Slide 1

Slide 1 text

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

Slide 2

Slide 2 text

2

Slide 3

Slide 3 text

3 Me, myself and I Java Champion OpenJDK amber & valhalla ex: jigsaw, lambda, invokedynamic

Slide 4

Slide 4 text

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 ??

Slide 5

Slide 5 text

5 With JMH log4j2_disabled_text 1.081 ns/op +/- 0.004 no_op 0.272 ns/op +/- 0.005

Slide 6

Slide 6 text

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)

Slide 7

Slide 7 text

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)

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

9

Slide 10

Slide 10 text

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); } } }

Slide 11

Slide 11 text

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; } }

Slide 12

Slide 12 text

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

Slide 13

Slide 13 text

13

Slide 14

Slide 14 text

14 The VM doesn’t trust final fields !!

Slide 15

Slide 15 text

15 java.lang.invoke

Slide 16

Slide 16 text

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+

Slide 17

Slide 17 text

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");

Slide 18

Slide 18 text

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");

Slide 19

Slide 19 text

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");

Slide 20

Slide 20 text

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 !");

Slide 21

Slide 21 text

21 Method Handle Tree Configuration test target fallback empty level isDebug prinln bindTo System.err dropArguments guard

Slide 22

Slide 22 text

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); } } }; }

Slide 23

Slide 23 text

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

Slide 24

Slide 24 text

24

Slide 25

Slide 25 text

25 The VM still doesn’t trust final fields !!

Slide 26

Slide 26 text

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; }

Slide 27

Slide 27 text

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); } } }; }

Slide 28

Slide 28 text

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); } }; }

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

30

Slide 31

Slide 31 text

31 So everything is fine ??

Slide 32

Slide 32 text

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; }

Slide 33

Slide 33 text

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

Slide 34

Slide 34 text

34

Slide 35

Slide 35 text

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(); }

Slide 36

Slide 36 text

36 How to react to a configuration change using java.lang.invoke ??

Slide 37

Slide 37 text

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 !

Slide 38

Slide 38 text

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

Slide 39

Slide 39 text

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

Slide 40

Slide 40 text

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

Slide 41

Slide 41 text

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

Slide 42

Slide 42 text

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

Slide 43

Slide 43 text

43

Slide 44

Slide 44 text

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