在OS X中,为什么使用println()会导致程序比没有println()运行得更快

Question

我遇到了一个非常奇怪的错误,我希望这里的某个人可以解决一些问题,因为它已经超出了我的专业领域.

首先,相关背景信息:我在2013年晚些时候使用2.4GHz Haswell CPU在Macbook Pro Retina上运行OS X 10.9.4.我正在从Oracle使用JDK SE 8u5 for OS X,并且我在最新版本的IntelliJ IDEA上运行我的代码.这个bug似乎也只针对OS X,因为我已经在Reddit上发布了关于这个bug的信息,而OS X的其他用户能够重新创建它,而Windows和Linux上的用户,包括我自己,让程序按预期运行println()版本运行比没有println()的版本慢半秒.

现在的bug:在我的代码中,我有一个println()语句,当包含时,程序运行在~2.5秒.如果我通过删除它或将其注释掉来删除println()语句,程序违反直觉需要更长时间才能运行~9秒.这是非常奇怪的,因为I/O理论上应该减慢程序速度,而不是让它更快.

对于我的实际代码,这是我对Project Euler Problem 14的实现.请记住我还是学生,所以这不是最好的实施:

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);
        }
    }
}

有问题的代码行已经使用全部大写字母进行了评论,因为它看起来不像是行号.如果你找不到它,它在我的main方法的for()循环中的嵌套if()语句中.

我在使用和不使用该行的情况下多次运行我的代码,并且我一直使用println()和没有println()的〜9秒来获得上述约2.5秒的时间.我还重启了我的笔记本电脑多次,以确保它不是我当前的操作系统运行和时间保持一致.

由于其他OS X 10.9.4用户能够复制代码,我怀疑这是由于编译器,JVM或操作系统本身的低级错误.无论如何,这超出了我的知识范围.这不是一个关键的错误,但我肯定对为什么会发生这种情况感兴趣并且会欣赏任何见解.

Answer 1

我做了一些研究,还有一些关于@ekabanov的研究,以下是研究结果.

• 您所看到的效果只发生在Java 8而不是Java 7中.
• 额外的行触发不同的JIT编译/优化
• 更快版本的汇编代码大约3倍,快速浏览显示它循环展开
• JIT编译日志显示较慢的版本成功内联runCollat​​z,而较快的版本没有说明被调用者太大(可能是因为展开).

有一个很棒的工具可以帮助你分析这种情况,它被称为jitwatch.如果它是汇编级别,那么您还需要HotSpot反汇编程序.

我也会发布我的日志文件.您可以将热点日志文件提供给jitwatch,并且您可以区分组件提取以发现差异.

• 快速版本的热点日志文件
• 快速版本的程序集日志文件
• 慢版本的热点日志文件
• 慢版本的程序集日志文件