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.