Java Performance – Why Algorithm Becomes Faster After Multiple Executions

algorithmjavajitjvmperformance

I have a Sudoku solving algorithm for which my goal is to make as fast as possible. To test this algorithm, I run it multiple times and calculate the average. After noticing some weird numbers, I decided to print all times and got this result:

Execution Time : 4.257746 ms (#1)
Execution Time : 7.610686 ms (#2)
Execution Time : 6.277609 ms (#3)
Execution Time : 7.595707 ms (#4)
Execution Time : 7.610131 ms (#5)
Execution Time : 5.011104 ms (#6)
Execution Time : 3.970937 ms (#7)
Execution Time : 3.923783 ms (#8)
Execution Time : 4.070238 ms (#9)
Execution Time : 4.765347 ms (#10)
Execution Time : 0.818264 ms (#11)
Execution Time : 0.620216 ms (#12)
Execution Time : 0.679021 ms (#13)
Execution Time : 0.643516 ms (#14)
Execution Time : 0.718408 ms (#15)
Execution Time : 0.744481 ms (#16)
Execution Time : 0.760569 ms (#17)
Execution Time : 0.80384 ms (#18)
Execution Time : 0.75946 ms (#19)
Execution Time : 0.802176 ms (#20)
Execution Time : 66.032508 ms : average = 3.3016254000000003

After 10 to 15 executions (it varies randomly), the performance of the algorithm is drastically improves. If I run it several hundred times, it will eventually steady at around 0.3ms. Note that I run the algorithm once before this loop for JIT to do it's thing.

Furthermore, if I make the thread sleep for 2 seconds before running my loop, all my times are at 1ms (+/- 0.2).

Furthermore, if I solved a generic Sudoku (a grid with 1-9 diagonally) some 500 times before my loop, all my times are around 0.3ms (+/- 0.02).

Every solve is identical. All values are reset.

So my question is many-fold:

-Why does each solve time improve after consecutive solves?

-Why do I have a sudden drop in solve time after 10-15 solves?

Best Answer

This is because JIT is compiling that method after JVM makes certain number of frequent calls to that method. In practice methods are not compiled the first time they are called. For each method JVM maintains a call count ,which is incremented every time the method is called. The JVM interprets a method until its call count exceeds a JIT compilation threshold. As the call count reaches threshold , JIT compiles and optimizes the bytecodes so that it run faster when next time it is called by JVM. Therefore, in your case the performance of the algorithm is drastically improving after every 10 to 15(at random) executions.

Related Solutions

Java Performance Benchmarking – Why is the Second Loop Faster in Java Benchmarking?

This is a classic java benchmarking issue. Hotspot/JIT/etc will compile your code as you use it, so it gets faster during the run.

Run around the loop at least 3000 times (10000 on a server or on 64 bit) first - then do your measurements.

Java Performance – Loop Slows Down After Multiple Runs: JIT Issue?

Preamble: Writing microbenchmarks manually is almost always doomed to a failure.
There are frameworks that have already solved the common benchmarking problems.

JIT compilation unit is a method. Incorporating several benchmarks into a single method leads to unpredictable results.
JIT heavily relies on the execution profile, i.e. the run-time statistics. If a method runs the first scenario for a long time, JIT will optimize the generated code for it. When the method suddenly switches to another scenario, do not expect it to run at the same speed.
JIT may skip optimizing the code that is not executed. It will leave an uncommon trap for this code. If the trap is ever hit, JVM will deoptimize the compiled method, switch to interpreter and after that recompile the code with the new knowledge. E.g. when your method run is compiled for the first time inside the first hot loop, JIT does not know about System.out.println yet. As soon as the execution reaches println, the earlier compiled code is likely to get deoptimized.
The bigger is method - the harder is to optimize it for JIT compiler. E.g. it may appear that there is not enough spare registers to hold all local variables. That's what happen in your case.

To sum it up, your benchmark seem to pass through the following scenario:

The first hot loop (addStatic) triggers the compilation of run method. The execution profile does not know anything except addStatic method.
System.out.println triggers the deoptimization and after that the second hot loop (addDynamic) leads to recompilation of run method.
Now the execution profile contains information only about addDynamic, so JIT optimizes the second loop, and the first loop appears to have extra register spills:

Optimized loop:

0x0000000002d01054: add    %rbx,%r14
0x0000000002d01057: add    $0x1,%rbx          ;*ladd
                                              ; - TestPerformanceOfStaticVsDynamicCalls::addDynamic@2
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@105

0x0000000002d0105b: add    $0x1,%r14          ; OopMap{rbp=Oop off=127}
                                              ;*goto
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@116

0x0000000002d0105f: test   %eax,-0x1c91065(%rip)        # 0x0000000001070000
                                              ;*lload
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@92
                                              ;   {poll}
0x0000000002d01065: cmp    $0x3b9aca00,%rbx
0x0000000002d0106c: jl     0x0000000002d01054

Loop with an extra register spill:

0x0000000002d011d0: mov    0x28(%rsp),%r11  <---- the problem is here
0x0000000002d011d5: add    %r10,%r11
0x0000000002d011d8: add    $0x1,%r10
0x0000000002d011dc: add    $0x1,%r11
0x0000000002d011e0: mov    %r11,0x28(%rsp)    ;*ladd
                                              ; - TestPerformanceOfStaticVsDynamicCalls::addStatic@2
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@33

0x0000000002d011e5: mov    0x28(%rsp),%r11  <---- the problem is here
0x0000000002d011ea: add    $0x1,%r11          ; OopMap{[32]=Oop off=526}
                                              ;*goto
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@44

0x0000000002d011ee: test   %eax,-0x1c911f4(%rip)        # 0x0000000001070000
                                              ;*goto
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@44
                                              ;   {poll}
0x0000000002d011f4: cmp    $0x3b9aca00,%r10
0x0000000002d011fb: jl     0x0000000002d011d0  ;*ifge
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@25

P.S. The following JVM options are useful to analyze the JIT compilation:

-XX:+PrintCompilation -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining -XX:+PrintAssembly -XX:CompileOnly=TestPerformanceOfStaticVsDynamicCalls

Best Answer

Related Solutions

Java Performance Benchmarking – Why is the Second Loop Faster in Java Benchmarking?

Java Performance – Loop Slows Down After Multiple Runs: JIT Issue?

Related Question