Understanding the output generated by PrintCompilation flag

The last example from our previous post produced the following output

> java -XX:+PrintCompilation Main2 | Select-String -Pattern calculate
     76   68       3       Main::calculate (9 bytes)
     79   72       4       Main::calculate (9 bytes)
     81   68       3       Main::calculate (9 bytes)   made not entrant

>

Lets try to understand what this output means

Frist column is the no. of milliseconds elapsed since the start of the program. This indicates the time at which our method calculate() is JIT compiled

The second column here is the compilation id. Each compilation unit gets a unique id. 68 on 1st and 3rd lines in the above output indicates they refer to the same compilation unit. 

The third column is blank in our output. Its a five character string, representing the characteristics of the code compiled

% - OSR compilation.
s - synchronized method.
! - Method has an exception handler.
b - Blocking mode.
n - Wrapper to a native method.

Fourth column is a number from 0 to 4 indicating the tier at which the compilation is done. If tiered compilation is turned off, this column will be blank.

Fifth column is the fully qualified method name

Sixth column is the size in bytes - size of the byte code that is getting compiled 

Last column contains the message of the deoptimization done - made not entrant in our sample output

 

Watching JIT in Action

How can we find what JIT is doing to our code at runtime? And how can we figure out which of our methods are getting compiled at runtime and when?

We have a java command line flag -XX:+PrintCompilation which when included, logs all the JIT compile events to standard output.

Lets see this in action. We will start with the below code

public class Main {
    
    static final int LOOP_COUNT = 10 * 10; //100

    public static void main(String[] args) {

        for (int i = 0; i < LOOP_COUNT; i++) {
            calculate();
        }
    }
    
    static void calculate() {
        double value = Math.random() * Math.random();
    }
}

We have the calculate() method, which creates two random numbers and multiplies them. This method is called in a loop from the main() method. We start with a loop count of 100. 

Execute this program with PrintCompilation flag, and watch for JIT compilation of compute method in the output, using the below command

> java -XX:+PrintCompilation Main | Select-String -Pattern calculate

>

Note: Above command is run on Windows OS, using Select-String -> an equivalent of grep for powershell. 

Without grep, we can see a lot of lines in the output - the logs from JIT compilation of java library methods.

Here we grep for "calculate" in the generated output. We do not see any compile event log for our method, indicating that our method calculate() is not JIT compiled this time.  

We will now increase the loop count to 10K and watch out for JIT compilation event for our calculate() method. The code now is as shown below

public class Main1 {
    
    static final int LOOP_COUNT = 100 * 100; //10K

    public static void main(String[] args) {

        for (int i = 0; i < LOOP_COUNT; i++) {
            calculate();
        }
    }
    
    static void calculate() {
        double value = Math.random() * Math.random();
    }
}

Executing this code with the PrintCompilation flag, and watching for JIT compilation event for calculate() method, we see the compilation event log in the output as shown below 

> java -XX:+PrintCompilation Main1 | Select-String -Pattern calculate

     71   67       3       Main1::calculate (9 bytes)
     
>

This indicates that our method calculate() is JIT compiled this time. 

What happens if we increase the loop count still further? We will try to increase the loop count to 1M this time. Code now is as shown below

public class Main2 {
    
    static final int LOOP_COUNT = 1000 * 1000; //1M

    public static void main(String[] args) {

        for (int i = 0; i < LOOP_COUNT; i++) {
            calculate();
        }
    }

    static void calculate() {
        double value = Math.random() * Math.random();
    }
}
 

Executing this code again with PrintCompilation flag, we new see multiple JIT compilation event logs  for our calculate() method  

> java -XX:+PrintCompilation Main2 | Select-String -Pattern calculate
     76   68       3       Main::calculate (9 bytes)
     79   72       4       Main::calculate (9 bytes)
     81   68       3       Main::calculate (9 bytes)   made not entrant

>

Why is the JIT compilation kicking in only when loop count is high and why we we seeing multiple JIT compilation events occurring when loop count is very high? We will explore that in a subsequent post. 

Before that we will see how to read the output generated by PrintCompilation flag in our next post.

JIT Compiler

Lets start by talking a bit about JIT compiler...

This is an age old topic that has been widely discussed. There are a lot of materials out there explaining JIT compilation in much greater detail.

But I am bent on telling it one more time... the way I have understood it... put in as simply as I can!!!

So lets start with this universal Hello World! code

public class Main {

    public static void main(String[] args) {
        System.out.println("Hello World!");
    }
}

To execute this program, we execute two commands

1. javac command to compile this source code into a class file
2. java command to execute the class file

javac Main.java

java Main

The first command converts the source code into set of JVM instructions, commonly referred to as Java byte codes. These byte codes are stored in a .class file.

The second command starts a JVM instance, reads the byte codes from the class file and executes them on the JVM to produce the desired output.  

Now the JVM itself is a virtual layer on top of the hardware on which we execute the java command. What JVM actually does is interpret the byte codes and convert it (compile it) into assembly language instruction set that can be executed on the specific hardware.  

So the JVM, at a high level performs the following steps for each byte code instruction

1. Read that byte code instruction
2. Interpret that byte code and compile it to generate the equivalent assembly language instructions for the specific hardware on which its getting executed 
3. And finally get these generated assembly language instructions executed on that hardware

This might just be fine for a simple program like hello world, but the real world programs are much more complex. 

Consider for instance, the below example where we print the String "Hello World" from within the method hello(). This method is called 10,000 times over from the main method

public class Main1 {

    public static void main(String[] args) {

        for (int i = 0; i < 10000; i++) {
            hello();
        }
    }
    
    static void hello() {
        System.out.println("Hello World!");
    }
}

The JVM performing the cycle of read -> interpret -> execute 10,000 times would sure be not an efficient approach. 

The compiled instruction set that gets generated is going to be the same for each of the 10,000 cycles. Java byte code need not be interpreted each time the JVM loops through. 

The component that does this compilation is the Just In-time Compiler or the JIT compiler and it is executed as part of the JVM process. 

So, 

• javac is the static compiler that converts java source files into byte code instruction set
• JIT compiler is part of the JVM process that is started by the java command and it performs dynamic compilation of byte code instruction set to native assembly language instructions