2009-04-29 59 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緩存的重用遠不是那麼大。
相關問題