"-XX:+PrintCompilation" - Watching JIT Compilation Logs

JVM Tutorials - Herong's Tutorial Examples

∟"-XX:+PrintCompilation" - Watching JIT Compilation Logs

This section provides a tutorial example on how to use the HotSpot JVM command option, -XX:+PrintCompilation, to watch JIT compilation logs. The JIT compilation of the test method to native machine code does reduce the execution by 25%.

In order to find out the impact on the execution time by the JIT compilation, I did another test with the "-XX:+PrintCompilation" HotSpot JVM option:

herong> java -XX:+PrintCompilation BenchmarkRunner \
   BenchmarkLoopTest emptyLoop 1000000 3 3

  1       java.lang.String::hashCode (60 bytes)
  2       java.lang.String::charAt (33 bytes)
  3       java.lang.String::indexOf (166 bytes)
Are you ready?
y

Waking up the JIT compiler...
  4       java.lang.String::indexOf (151 bytes)
Run: 1, Time: 6146, Test returns: 3
Run: 2, Time: 3353, Test returns: 3
Run: 3, Time: 3353, Test returns: 3
...
Run: 15, Time: 3632, Test returns: 3
  5       sun.reflect.ClassFileAssembler::emitByte (11 bytes)
  6       sun.reflect.ByteVectorImpl::add (38 bytes)
Run: 16, Time: 3632, Test returns: 3
...
Run: 37, Time: 3353, Test returns: 3
  7  !    sun.nio.cs.SingleByteEncoder::encodeArrayLoop (475 bytes)
Run: 38, Time: 3352, Test returns: 3
...
Run: 96, Time: 3352, Test returns: 3
  8       sun.nio.cs.Surrogate::is (18 bytes)
Run: 97, Time: 3353, Test returns: 3
Run: 98, Time: 4749, Test returns: 3
  9       java.lang.Object::<iRun: nit> (1 bytes)
99, Time: 3352, Test returns: 3
---   n   java.lang.System::arraycopy (static)
Run: 100, Time: 3352, Test returns: 3
...
Run: 221, Time: 3073, Test returns: 3
 10       java.lang.String::getChars (66 bytes)
Run: 222, Time: 3073, Test returns: 3
...
... Some other methods compiled
...
Run: 388, Time: 3353, Test returns: 3
Run: 389, Time: 3073, Test returns: 3
 19       BenchmarkLoopTest::emptyLoop (38 bytes)
Run: 390, Time: 3353, Test returns: 3
Run: 391, Time: 4470, Test returns: 3
Run: 392, Time: 3073, Test returns: 3
Run: 393, Time: 3353, Test returns: 3
Run: 394, Time: 3352, Test returns: 3
 20       java.lang.AbstractStringBuilder::stringSizeOfLong (38 bytes)
Run: 395, Time: 3073, Test returns: 3
Run: 396, Time: 3632, Test returns: 3
Run: 397, Time: 3632, Test returns: 3
Run: 398, Time: 2235, Test returns: 3
Run: 399, Time: 2514, Test returns: 3
...
... Some other methods compiled
...
Run: 1614, Time: 2514, Test returns: 3
 79       sun.reflect.DelegatingMethodAccessorImpl::invoke (10 bytes)
Run: 1615, Time: 2514, Test returns: 3
Run: 1616, Time: 3631, Test returns: 3
Run: 1617, Time: 2235, Test returns: 3
Run: 1618, Time: 2514, Test returns: 3
Run: 1619, Time: 2234, Test returns: 3
 80       BenchmarkRunner::returnTime (10 bytes)
Run: 1620, Time: 2515, Test returns: 3
Run: 1621, Time: 3631, Test returns: 3
Run: 1622, Time: 2235, Test returns: 3
Run: 1623, Time: 3073, Test returns: 3
 81       java.lang.StringBuilder::append (8 bytes)
Run: 1624, Time: 2234, Test returns: 3
Run: 1625, Time: 2514, Test returns: 3
Run: 1626, Time: 2515, Test returns: 3
Run: 1627, Time: 3632, Test returns: 3
Run: 1628, Time: 13410, Test returns: 3
Run: 1629, Time: 1956, Test returns: 3
 82       java.lang.AbstractStringBuilder::append (80 bytes)
Run: 1630, Time: 1956, Test returns: 3
Run: 1631, Time: 2514, Test returns: 3
Run: 1632, Time: 1956, Test returns: 3
Run: 1633, Time: 1956, Test returns: 3
...
... Some other methods compiled
...
Run: 1696, Time: 1955, Test returns: 3
 88  !    sun.reflect.GeneratedMethodAccessor1::invoke (138 bytes)
Run: 1697, Time: 3073, Test returns: 3
Run: 1698, Time: 2515, Test returns: 3
Run: 1699, Time: 1956, Test returns: 3
...

The test result is very interesting:

java.lang.String::indexOf() got compiled 2 times.
The test method, BenchmarkLoopTest::emptyLoop() got compiled once, which contributed to the execution time drop from 3352 to 2514 nanoseconds.
Other two execution time drops from 6146 to 3353 and from 2512 to 1956 nanoseconds were resulted from JIT compilations of other methods.
88 methods were compiled, or recompiled in total. The last method was compiled at run 1697. After that, the JIT compiler stayed quiet.

Takeaways:

The compilation of the test method, emptyLoop(), into native machine code reduced the execution time by 25%, from 3352 to 2514 nanoseconds.
After about 1700 repeating runs, or calls, of the test methods, the JIT compiler finishes identifying and compiling "hot spot" methods.