"-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:

C:\herong\jvm>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:

Conclusions:

Last update: 2010.

Table of Contents

 About This Book

 Downloading and Installing JDK 1.8.0 on Windows

 Downloading and Installing JDK 1.7.0 on Windows

 java.lang.Runtime Class - The JVM Instance

 java.lang.System Class - The Operating System

 ClassLoader Class - Class Loaders

 Class Class - Class Reflections

 Sun's JVM - Java HotSpot VM

 JRockit JVM 28.2.7 by Oracle Corporation

 JVM Runtime Data Areas

 Memory Management and Garbage Collectors

 Garbage Collection Tests

 JVM Stack, Frame and Stack Overflow

 Thread Testing Program and Result

 CPU Impact of Multi-Thread Applications

 I/O Impact of Multi-Thread Applications

 CDS (Class Data Sharing)

Micro Benchmark Runner and JVM Options

 What Is Micro Benchmark?

 BenchmarkRunner.java - Benchmark Runner Program

 emptyLoop() - The Empty Loop Test Method

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

 "-XX:+PrintGC" - Watching GC (Garbage Collection) Logs

 "-Xms" and "-Xmx" - Avoiding GC with Large Memory Size

 Benchmark Affected by Other Running Applications

 "-Xint" - Running in Interpreted-Only Mode

 Micro Benchmark Tests on "int" Operations

 Micro Benchmark Tests on "long" Operations

 Micro Benchmark Tests in JIT Compilation Mode

 Micro Benchmark Tests on "float" and "double" Operations

 Outdated Tutorials

 References

 PDF Printing Version