In OS X, why does using println() cause my program to run faster than without println()

Question

I've run into a really strange bug, and I'm hoping someone here can shed some light as it's way out of my area of expertise.

First, relevant background information: I am running OS X 10.9.4 on a Late 2013 Macbook Pro Retina with a 2.4GHz Haswell CPU. I'm using JDK SE 8u5 for OS X from Oracle, and I'm running my code on the latest version of IntelliJ IDEA. This bug also seems to be specific only to OS X, as I posted on Reddit about this bug already and other users with OS X were able to recreate it while users on Windows and Linux, including myself, had the program run as expected with the println() version running half a second slower than the version without println().

Now for the bug: In my code, I have a println() statement that when included, the program runs at ~2.5 seconds. If I remove the println() statement either by deleting it or commenting it out, the program counterintuitively takes longer to run at ~9 seconds. It's extremely strange as I/O should theoretically slow the program down, not make it faster.

For my actual code, it's my implementation of Project Euler Problem 14. Please keep in mind I'm still a student so it's not the best implementation:

public class ProjectEuler14
{
    public static void main(String[] args)
    {
        final double TIME_START = System.currentTimeMillis();

        Collatz c = new Collatz();
        int highestNumOfTerms = 0;
        int currentNumOfTerms = 0;
        int highestValue = 0; //Value which produces most number of Collatz terms


        for (double i = 1.; i <= 1000000.; i++)
        {
            currentNumOfTerms = c.startCollatz(i);


            if (currentNumOfTerms > highestNumOfTerms)
            {
                highestNumOfTerms = currentNumOfTerms;
                highestValue = (int)(i);
                System.out.println("New term: " + highestValue); //THIS IS THE OFFENDING LINE OF CODE
            }
        }

        final double TIME_STOP = System.currentTimeMillis();

        System.out.println("Highest term: " + highestValue + " with " + highestNumOfTerms + " number of terms");
        System.out.println("Completed in " + ((TIME_STOP - TIME_START)/1000) + " s");
    }
}


public class Collatz
{
    private static int numOfTerms = 0;
    private boolean isFirstRun = false;

    public int startCollatz(double n)
    {
        isFirstRun = true;
        runCollatz(n);
        return numOfTerms;
    }

    private void runCollatz(double n)
    {
        if (isFirstRun)
        {
            numOfTerms = 0;
            isFirstRun = false;
        }

        if (n == 1)
        {
            //Reached last term, does nothing and causes program to return to startCollatz()
        }

        else if (n % 2 == 0)
        {
            //Divides n by 2 following Collatz rule, running recursion
            numOfTerms = numOfTerms + 1;
            runCollatz(n / 2);
        }

        else if (n % 2 == 1)
        {
            //Multiples n by 3 and adds one, following Collatz rule, running recursion
            numOfTerms = numOfTerms + 1;
            runCollatz((3 * n) + 1);
        }
    }
}

The line of code in question has been commented in with all caps, as it doesn't look like SO does line numbers. If you can't find it, it's within the nested if() statement in my for() loop in my main method.

I've run my code multiple times with and without that line, and I consistently get the above stated ~2.5sec times with println() and ~9sec without println(). I've also rebooted my laptop multiple times to make sure it wasn't my current OS run and the times stay consistent.

Since other OS X 10.9.4 users were able to replicate the code, I suspect it's due to a low-level bug with the compliler, JVM, or OS itself. In any case, this is way outside my knowledge. It's not a critical bug, but I definitely am interested in why this is happening and would appreciate any insight.

Answer 1

I did some research and some more with @ekabanov and here are the findings.

• The effect you are seeing only happens with Java 8 and not with Java 7.
• The extra line triggers a different JIT compilation/optimisation
• The assembly code of the faster version is ~3 times larger and quick glance shows it did loop unrolling
• The JIT compilation log shows that the slower version successfully inlined the runCollatz while the faster didn't stating that the callee is too large (probably because of the unrolling).

There is a great tool that helps you analyse such situations, it is called jitwatch. If it is assembly level then you also need the HotSpot Disassembler.

I'll post also my log files. You can feed the hotspot log files to the jitwatch and the assembly extraction is something that you diff to spot the differences.

• Fast version's hotspot log file
• Fast version's assembly log file
• Slow version's hotspot log file
• Slow version's assembly log file