2009-04-29 33 views
2

下面是一个示例代码:为什么连续调用两次相同的方法会产生不同的执行时间?

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

}

这给出了以下的输出:通过 'FONE' 所需的时间... 390273 通过 'fTwo' 所需的时间.. 118451 'fOne'所用的时间... 53359 'fTwo'所用的时间... 115936 按任意键继续。 。 。

为什么第一次执行同样的方法比连续调用需要更多时间(显着更多)?

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

回答

7

有几个原因。 JIT(Just In Time)编译器可能没有运行。 JVM可以在调用之间进行优化。你正在测量已用时间,所以也许你的机器上运行的不是Java以外的东西。在随后的调用中,处理器和RAM缓存可能“温暖”。

您确实需要为每个方法的执行时间准确地进行多次调用(以千计)。

2

最有可能的罪魁祸首是JIT(即时)热点引擎。基本上,第一次执行代码时,机器代码被JVM“记住”,然后在未来的执行中重用。

1

我认为这是因为第一次运行后第二次生成的代码已经优化。

5
  1. 测试的代码非常微不足道。所采取的最昂贵的操作是

    System.out.println(k); 
    

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

  2. JIT /热点逐步优化经常使用的代码路径。

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

  4. 您的样本量太小。此类微基准通常会进行热身阶段,您可以看到应该如何进行广泛的操作,如Java is really fast at doing nothing

3

除了JITting,其他因素可能是:

  • 进程的输出流阻塞,当你打电话的System.out。的println
  • 你的过程中越来越被另一个进程调出
  • 垃圾收集器做在后台线程

如果你想获得良好的基准,你应该

  • 运行代码的一些工作你至少需要数千次基准测试,并计算平均时间。
  • 忽略前几个呼叫的时间(由于JITting等)
  • 如果可以,禁用GC;如果你的代码产生了很多对象,这可能不是一个选项。
  • 将日志记录(println调用)从正在进行基准测试的代码中取出。

在几个平台上有基准图书馆,将帮助你做这些东西;他们也可以计算标准差和其他统计数据。

1

如前所述,JIT可能是罪魁祸首,但是如果机器上的其他进程正在使用资源,那么I/O等待时间以及资源等待时间也是如此。

这个故事的寓意是,micrbenchmarking是一个难题,尤其是Java。我不知道你为什么要这样做,但如果你试图在两种方法中选择一种方法来解决问题,不要用这种方法来衡量它们。使用策略设计模式,用两种不同的方法运行整个程序并测量整个系统。从长远来看,这样做在处理时间上几乎没有什么问题,并且让您更加真实地了解您的整个应用程序的性能在这一点上是多么的棘手(提示:它可能比您想象的要小)。

7

Andreas提到的问题JIT的不可预测性是真实的,但还是多了一个问题是类加载器

fOne的第一个电话彻底从后面的一些不同,因为那是什么使第一个电话到System.out.println,这意味着当类加载器将从磁盘或文件系统缓存(通常是缓存)所需的所有类打印文本。将参数-verbose:class提供给JVM以查看在此小程序期间实际加载了多少个类。

我注意到运行单元测试时有类似的行为 - 第一个调用大框架的测试需要更长的时间(在C2C6600上250 ms左右的Guice情况下),即使测试代码是相同的,第一次调用是当类加载器加载数百个类时。

由于您的示例程序太短,开销可能来自JIT优化和类加载活动。垃圾收集器可能在程序结束之前甚至不会启动。


更新:

现在我找到了一个可靠的方式来了解一下什么是真正服用的时间。没有人知道它,尽管它与课程加载密切相关 - 它是本地方法的动态链接

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

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

,显示究竟发生什么事了运行程序,用正确的JVM parameters命令:

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方法被调用之前发生。

1

那么最可能的答案是初始化。 JIT肯定不是正确的答案,因为在开始优化之前需要更多的周期。但在第一次可以有:

  • 寻找补课(被缓存,所以没有第二查找需要)
  • 加载类(在内存中加载一次住宿)
  • 从本地库获得额外的代码(本地代码被缓存)
  • 最后它加载要在CPU的L1缓存中执行的代码。在你的意义上,这是最适合加速的情况,同时也是基准测试(微基准测试)没有多少说明的原因。如果代码足够小,则第二次循环调用可以从CPU内部完全运行,速度很快。在现实世界中,这不会发生,因为程序更大,L1缓存的重用远不是那么大。
相关问题