2

下面的短代码隔离了问题。基本上我正在计时方法addToStorage。我从执行一百万次开始，我能够将它的时间缩短到大约 723 纳秒。然后我做了一个短暂的暂停（使用忙碌的旋转方法不释放 cpu 核心）并在不同的代码位置再次对该方法计时 N 次。令我惊讶的是，我发现N 越小，延迟越大addToStorage。

例如：

If N = 1 then I get 3.6 micros
If N = 2 then I get 3.1 and 2.5 micros
if N = 5 then I get 3.7, 1.8, 1.7, 1.5 and 1.5 micros

有谁知道为什么会发生这种情况以及如何解决？我希望我的方法能够在尽可能快的时间内始终如一地执行，无论我在哪里调用它。

注意：我不认为它与线程相关，因为我没有使用Thread.sleep. 我还测试了使用taskset将我的线程固定到具有相同结果的 cpu 内核。

import java.util.ArrayList;
import java.util.List;

public class JvmOdd {

    private final StringBuilder sBuilder = new StringBuilder(1024);
    private final List<String> storage = new ArrayList<String>(1024 * 1024);

    public void addToStorage() {

        sBuilder.setLength(0);

        sBuilder.append("Blah1: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah2: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah3: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah4: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah5: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah6: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah7: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah8: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah9: ").append(System.nanoTime()).append('\n');
        sBuilder.append("Blah10: ").append(System.nanoTime()).append('\n');

        storage.add(sBuilder.toString());
    }

    public static long mySleep(long t) {
        long x = 0;
        for(int i = 0; i < t * 10000; i++) {
            x += System.currentTimeMillis() / System.nanoTime();
        }
        return x;
    }

    public static void main(String[] args) throws Exception {

        int warmup = Integer.parseInt(args[0]);
        int mod = Integer.parseInt(args[1]);
        int passes = Integer.parseInt(args[2]);
        int sleep = Integer.parseInt(args[3]);

        JvmOdd jo = new JvmOdd();

        // first warm up

        for(int i = 0; i < warmup; i++) {
            long time = System.nanoTime();
            jo.addToStorage();
            time = System.nanoTime() - time;
            if (i % mod == 0) System.out.println(time);
        }

        // now see how fast the method is:

        while(true) {

            System.out.println();

            // Thread.sleep(sleep);
            mySleep(sleep);

            long minTime = Long.MAX_VALUE;

            for(int i = 0; i < passes; i++) {
                long time = System.nanoTime();
                jo.addToStorage();
                time = System.nanoTime() - time;
                if (i > 0) System.out.print(',');
                System.out.print(time);
                minTime = Math.min(time, minTime);
            }
            System.out.println("\nMinTime: " + minTime);
        }
    }
}

执行：

$ java -server -cp . JvmOdd 1000000 100000 1 5000
59103
820
727
772
734
767
730
726
840
736

3404
MinTime: 3404
4

3 回答 3

5

这里发生了很多事情，我不知道从哪里开始。但是让我们从这里开始......

           long time = System.nanoTime();
            jo.addToStorage();
            time = System.nanoTime() - time;

使用此技术无法测量 addToStoarge() 的延迟。它只是运行得太快，这意味着您可能低于时钟的分辨率。如果不运行此程序，我的猜测是您的措施主要由时钟边沿计数决定。您需要增大工作单元的体积才能获得噪声水平较低的测量值。

至于发生了什么？有许多调用站点优化，最重要的是内联。内联将完全消除调用站点，但它是特定于路径的优化。如果您从不同的地方调用该方法，那将遵循执行虚拟方法查找然后跳转到该代码的缓慢路径。因此，要看到从不同路径进行内联的好处，该路径也必须“热身”。

我强烈建议您同时查看 JMH（随 JDK 提供）。那里有诸如黑洞之类的设施，这将有助于降低 CPU 时钟的影响。您可能还想借助 JITWatch（采用 OpenJDK 项目）等工具来评估工作台的质量，这些工具将获取 JIT 生成的日志并帮助您中断它们。

于 2017-04-08T07:10:43.683 回答
3

这个主题有很多内容，但最重要的是，您不能编写像这样简单的基准测试并期望它告诉您任何有用的信息。您将需要使用 JMH。

我建议观看：https ://www.infoq.com/presentations/jmh关于微基准测试和 JMH

我的书中还有一章关于微基准测试和 JMH：http: //shop.oreilly.com/product/0636920042983.do

于 2017-04-08T08:29:34.583 回答
0

Java 内部使用 JIT（Just in Compiler）。根据相同方法执行的次数，它可以优化指令并更好地执行。对于较小的值，方法的使用将是正常的，这可能不属于显示执行时间更多的优化。当同一个方法调用更多时间时，它使用 JIT 并在更短的时间内执行，因为针对相同方法执行的优化指令。

于 2017-04-08T06:24:38.580 回答