I observed some strange behaviour in one of my Java programs. I have tried to strip the code down as much as possible while still being able to replicate the behaviour. Code in full below.
public class StrangeBehaviour {
static boolean recursionFlag = true;
public static void main(String[] args) {
long startTime = System.nanoTime();
for (int i = 0; i < 10000; i ++) {
functionA(6, 0);
}
long endTime = System.nanoTime();
System.out.format("%.2f seconds elapsed.\n", (endTime - startTime) / 1000.0 / 1000 / 1000);
}
static boolean functionA(int recursionDepth, int recursionSwitch) {
if (recursionDepth == 0) { return true; }
return functionB(recursionDepth, recursionSwitch);
}
static boolean functionB(int recursionDepth, int recursionSwitch) {
for (int i = 0; i < 16; i++) {
if (StrangeBehaviour.recursionFlag) {
if (recursionSwitch == 0) {
if (functionA(recursionDepth - 1, 1 - recursionSwitch)) return true;
} else {
if (!functionA(recursionDepth - 1, 1 - recursionSwitch)) return false;
}
} else {
// This block is never entered into.
// Yet commenting out one of the lines below makes the program run slower!
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
System.out.println("...");
}
}
return false;
}
}
I have two functions, functionA() and functionB() that call each other recursively. Both functions take a recursionDepth parameter that controls the termination of the recursion. functionA() calls functionB() a maximum of once with recursionDepth unchanged. functionB() calls functionA() 16 times with recursionDepth - 1. The recursion terminates when functionA() is called with a recursionDepth of 0.
functionB() has a code block with a number of System.out.println() calls. This block is never entered into, as entry is controlled by a boolean recursionFlag variable that is set to true and never changed during program execution. However, commenting out even one of the println() calls causes the program to run slower. On my machine, execution time is <0.2s with all the println() calls present, and >2s when one of the calls is commented out.
What could be causing this behaviour? My only guess is that there is some naive compiler optimisation that is being triggered by a parameter related to the length of the code block (or the number of function calls etc.). Any further insight into this will be much appreciated!
Edit: I'm using JDK 1.8.
