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.