Wednesday, January 30, 2013

HotSpot -XX:+PrintComilation output, what does it mean?

HotSpot -XX:+PrintAssembly How to:

Reference:

https://wikis.oracle.com/display//HotSpotInternals/PrintAssembly
http://stackoverflow.com/questions/9341083/how-to-use-xxunlockdiagnosticvmoptions-xxcompilecommand-print-option-with-j

Build the plugin:

For PrintAssembly to work, you need hotspot disassembler plugin. You can download a prebuilt one, or build it your self.  The source is located <jdk>/src/share/tools/hsdis.  There is a README.  Here are the steps I did:
(0. copy the source code from hotspot bundles: hotspot/src/share/tools/hsdis)
1. cd  <jdk>/src/share/tools/hsdis
2. Download binutils from http://directory.fsf.org/project/binutils, put it under build/binutils.  The makefile will look for binutils under build by default.  Or you can build binutils separately and export the environment variable  BINUTILS=<path> "export BINUTILS=<.../tools/hsdis/build/binutils-2.22>
3. make
4. You might see error
hsdis.c:32:20: error: sysdep.h: No such file or directory
 
Need to change hsdis.c
-bash-4.1$ diff hsdis.c hsdis.c.orig                                                                                 
32c32
< #include <errno.h>
---
> #include <sysdep.h>

Try make again.
5. copy hsdis-amd64.so (or other names depending on the platform) to <jdk>/jre/lib/amd64

Generate the assembly code:

 -XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly
You can separate the assembly output to another file -XX:+LogVMOutput -XX:LogFile=foo*.log .

Things to look for:

lock addl
callq


HotSpot -XX:+LogCompilation How to:

"The -XX:+LogCompilation flag produces a low-level XML file about compiler and runtime decisions, which may be interesting to some. The -XX:+UnlockDiagnosticVMOptions must come first. The dump is to hotspot.log in the current directory; use -XX:LogFile=foo.log to change this."

LogCompilation gives similar information as -XX:+PrintCompilation -XX:+PrintInling, with more information why a decision is made.

Generate the log:

 -XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation -XX:LogFile=foo.log

Build the log parser:

The log is low level xml, which is hard to read.  You can build a parser logc.jar to parse the log. Steps:
(0. copy the source code from hotspot bundles: hotspot/src/share/tools/LogCompilation)
1. cd  <jdk>/src/share/tools/LogCompilation
2. make
It creates build dir, and generates logc.jar

How to use the log parser: (From README under share/tools/LogCompilation)

 -bash-4.1$ cat README                                                                                                
This is a very rough tool for parsing -XX:+LogCompilation output.
It's main purpose is to recreate output similar to
-XX:+PrintCompilation -XX:+PrintInlining output from a debug JVM.  It
requires a 1.5 JDK to build and simply typing make should build it.

It produces a jar file, logc.jar, that can be run on the
hotspot.log from LogCompilation output like this:

  java -jar logc.jar hotspot.log

This will produce something like the normal PrintCompilation output.
Adding the -i option with also report inlining like PrintInlining.

More information about the LogCompilation output can be found at

http://wikis.sun.com/display/HotSpotInternals/LogCompilation+overview
http://wikis.sun.com/display/HotSpotInternals/PrintCompilation
http://wikis.sun.com/display/HotSpotInternals/LogCompilation+tool

What does it mean in the log output?

The output produced by logc.jar has better format than those produced by -XX:+PrintComilation -XX:+PrintInlining (some lines tangle together).  Also gives more details on compilation, like 'uncommon trap', 'not entrant' , 'zombie'.
'uncommon trap': something changed.  May need recompile
'not entrant': new calls are not allowed to enter this
'zombie': on its way to death.

70 make_not_entrant
2 uncommon trap class_check maybe_recompile
  @14 HighContentionSimulator run ()V
2 uncommon trap class_check maybe_recompile
  @14 HighContentionSimulator run ()V
2 uncommon trap class_check maybe_recompile
  @14 HighContentionSimulator run ()V
2 make_not_entrant
65 make_not_entrant
3%   HighContentionSimulator::run @ 2 (24 bytes)
    @ 14 java.lang.Runnable::run (0 bytes)
     type profile java/lang/Runnable -> HighContentionSimulator$Mode$1 (59%)

Lines start with @ is line:

@ 14 java.lang.Runnable::run (0 bytes)

If no other reasons are printed, it is inlined.

 @ 23 java.util.concurrent.locks.AbstractQueuedSynchronizer::selfInterrupt never execute

If there is a reason, then it is not inlined.

With hotspot   -XX:+PrintComilation, you can get something like this:
 8922    3 %     4       HighContentionSimulator::run @ 2 (24 bytes)
<timestamp> <compilation-id> flags <comilation-level if TieredCompilation is on> <Method> @ 2 (code size)
flags: %: is_osr_method (on stack replacement)
         s: is_synchronized
         !: has_exception_handler
         b: is_blocking
         n: is_native
@: 2: it is osr_method and osr_bci is 2