为什么对同一方法的两次连续调用会产生不同的执行时间？

这是一个示例代码:

public class TestIO{
public static void main(String[] str){
    TestIO t = new TestIO();
    t.fOne();
    t.fTwo();
    t.fOne();
    t.fTwo();
}


public void fOne(){
    long t1, t2;
    t1 = System.nanoTime();
    int i = 10;
    int j = 10;
    int k = j*i;
    System.out.println(k);
    t2 = System.nanoTime();
    System.out.println("Time taken by 'fOne' ... " + (t2-t1));
}

public void fTwo(){
    long t1, t2;
    t1 = System.nanoTime();
    int i = 10;
    int j = 10;
    int k = j*i;
    System.out.println(k);
    t2 = System.nanoTime();
    System.out.println("Time taken by 'fTwo' ... " + (t2-t1));
}

}

这给出了以下输出:100'fOne'所花费的时间... 390273 100'fTwo'所花费的时间... 118451 100'fOne'所花费的时间... 53359 100'fTwo'所花费的时间... 115936按任意键继续 ...

为什么第一次执行相同的方法比连续调用花费更多的时间(显着更多)？

我试着给-XX:CompileThreshold=1000000命令行,但没有区别.

有几个原因.JIT(即时)编译器可能没有运行.JVM可以执行不同调用之间的优化.您正在测量经过的时间,因此您的计算机上可能正在运行Java之外的其他内容.处理器和RAM缓存在后续调用中可能"温暖".

您确实需要进行多次调用(成千上万次)才能获得准确的每个方法执行时间.

Andreas提到的问题和JIT的不可预测性都是正确的,但还有一个问题是类加载器:

第一个调用fOne与后者的调用完全不同,因为这是第一次调用的System.out.println意思,这意味着类加载器将从磁盘或文件系统缓存(通常是缓存)中打印出来的所有类.文本.将参数提供-verbose:class给JVM以查看在此小程序中实际加载了多少个类.

我在运行单元测试时注意到了类似的行为 - 调用大框架的第一个测试需要更长时间(如果Guice在C2Q6600上大约250ms),即使测试代码是相同的,因为第一次调用是类加载器加载了数百个类.

由于您的示例程序太短,因此开销可能来自非常早期的JIT优化和类加载活动.垃圾收集器甚至可能在程序结束之前就没有启动.

更新:

现在我找到了一种可靠的方法来找出真正花费时间的东西.没有人发现它,虽然它与类加载密切相关 - 它是本机方法的动态链接!

我按如下方式修改了代码,以便日志在测试开始和结束时显示(通过查看何时加载这些空标记类).

    TestIO t = new TestIO();
    new TestMarker1();
    t.fOne();
    t.fTwo();
    t.fOne();
    t.fTwo();
    new TestMarker2();

运行程序的命令,使用正确的JVM参数显示实际发生的情况:

java -verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation TestIO

并输出:

* snip 493 lines *
[Loaded java.security.Principal from shared objects file]
[Loaded java.security.cert.Certificate from shared objects file]
[Dynamic-linking native method java.lang.ClassLoader.defineClass1 ... JNI]
[Loaded TestIO from file:/D:/DEVEL/Test/classes/]
  3       java.lang.String::indexOf (166 bytes)
[Loaded TestMarker1 from file:/D:/DEVEL/Test/classes/]
[Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]
100
Time taken by 'fOne' ... 155354
100
Time taken by 'fTwo' ... 23684
100
Time taken by 'fOne' ... 22672
100
Time taken by 'fTwo' ... 23954
[Loaded TestMarker2 from file:/D:/DEVEL/Test/classes/]
[Loaded java.util.AbstractList$Itr from shared objects file]
[Loaded java.util.IdentityHashMap$KeySet from shared objects file]
* snip 7 lines *

而时差的原因是: [Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]

我们还可以看到,JIT编译器不会影响这个基准.只编译了三种方法(例如java.lang.String::indexOf在上面的代码片段中)并且它们都在fOne调用方法之前发生.

测试的代码非常简单.采取的最昂贵的行动是

 System.out.println(k);

所以你要测量的是调试输出的写入速度.这种情况差异很大,甚至可能取决于屏幕上调试窗口的位置,是否需要滚动其大小等.

JIT/Hotspot逐步优化常用的代码路径.

处理器优化预期的代码路径.使用的路径更经常执行得更快.

您的样本量太小.这样的微基准测试通常会做一个预热阶段,你可以看到这应该做得多么广泛,就像Java真的很快就无所事事.