java - 同じメソッドを 2 回連続して呼び出すと、実行時間が異なるのはなぜですか?

Question

サンプルコードは次のとおりです。

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

}

これにより、次の出力が得られます。何かキーを押すと続行します。. .

同じメソッドを初めて実行するのに、連続して呼び出すよりも時間がかかるのはなぜですか?

コマンドラインにあげ-XX:CompileThreshold=1000000てみましたが、違いはありませんでした。

score 7 · Accepted Answer

Andreasが言及した問題とJITの予測不可能性は真実ですが、それでももう1つの問題はクラスローダーです。

への最初の呼び出しfOneは、後者の呼び出しとは根本的に異なりますSystem.out.println。これは、への最初の呼び出しを行うためです。つまり、クラスローダーがディスクまたはファイルシステムのキャッシュ（通常はキャッシュされている）から、印刷に必要なすべてのクラスを取得します。文章。-verbose:classこの小さなプログラム中に実際にロードされるクラスの数を確認するには、JVMにパラメーターを指定します。

単体テストを実行するときに同様の動作に気づきました-大きなフレームワークを呼び出す最初のテストは、テストコードが同じであっても、はるかに長い時間がかかります（C2Q6600で約250msのGuiceの場合）。何百ものクラスがクラスローダーによってロードされます。

サンプルプログラムは非常に短いため、オーバーヘッドはおそらく非常に初期の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コンパイラがこのベンチマークに影響を与えていないこともわかります。コンパイルされるメソッドは3つだけで（java.lang.String::indexOf上記のスニペットなど）、fOneメソッドが呼び出される前にすべて実行されます。

score 7 · Accepted Answer

いくつかの理由があります。JIT (ジャストインタイム) コンパイラが実行されていない可能性があります。JVM は、呼び出しごとに異なる最適化を行うことができます。経過時間を測定しているため、マシンで Java 以外の何かが実行されている可能性があります。プロセッサと RAM キャッシュは、その後の呼び出しではおそらく「ウォーム」です。

メソッドごとの正確な実行時間を取得するには、複数回 (数千回) 呼び出しを行う必要があります。

score 5 · Accepted Answer

テストされたコードは非常に簡単です。最もコストのかかるアクションは、
```
 System.out.println(k);
```
したがって、測定しているのは、デバッグ出力が書き込まれる速さです。これは大きく異なり、サイズをスクロールする必要がある場合など、画面上のデバッグウィンドウの位置によっても異なります。
JIT/Hotspot は、頻繁に使用されるコードパスを段階的に最適化します。
プロセッサは、予想されるコードパスを最適化します。より頻繁に使用されるパスは、より高速に実行されます。
サンプルサイズが小さすぎます。このようなマイクロベンチマークは通常、ウォームアップフェーズを実行します。Java が何もしないのが非常に高速であるように、これをどれだけ広範囲に実行する必要があるかを確認できます。

score 3 · Accepted Answer

JITting に加えて、次の要因が考えられます。

System.out.println を呼び出すとプロセスの出力ストリームがブロックされる
プロセスが別のプロセスによってスケジュールされている
バックグラウンドスレッドで何らかの作業を行っているガベージコレクター

良いベンチマークを取得したい場合は、

ベンチマークしているコードを何度も、少なくとも数千回実行し、平均時間を計算します。
最初の数回の呼び出しの時間を無視します (JITting などによる)。
可能であれば GC を無効にします。コードが多くのオブジェクトを生成する場合、これはオプションではない可能性があります。
ベンチマーク対象のコードからロギング (println 呼び出し) を取り除きます。

いくつかのプラットフォームには、この作業を支援するベンチマークライブラリがあります。また、標準偏差やその他の統計を計算することもできます。

score 2 · Accepted Answer

最も可能性の高い原因は、JIT (ジャストインタイム) ホットスポットエンジンです。基本的に、最初にコードが実行されると、マシンコードは JVM によって「記憶」され、その後の実行で再利用されます。

score 1 · Accepted Answer

示唆されているように、JIT が原因である可能性がありますが、その時点でマシン上の他のプロセスがリソースを使用していた場合は、I/O 待機時間とリソース待機時間も原因である可能性があります。

この話の教訓は、特に Java の場合、マイクロベンチマークは困難な問題であるということです。なぜこれを行っているのかわかりませんが、問題に対して 2 つのアプローチのどちらかを選択しようとしている場合は、この方法で測定しないでください。戦略設計パターンを使用して、2 つの異なるアプローチでプログラム全体を実行し、システム全体を測定します。これにより、長い目で見れば処理時間のわずかな増加が均等になり、その時点でアプリ全体のパフォーマンスがどの程度ボトルネックになっているかをより現実的に把握できます (ヒント: おそらく、あなたが思っているよりも少ないでしょう)。

score 1 · Accepted Answer

最も可能性の高い答えは初期化です。JIT は、最適化を開始するまでにより多くのサイクルがかかるため、正しい答えではありません。しかし、最初は次のことが考えられます。

クラスのルックアップ (キャッシュされるため、2 回目のルックアップは必要ありません)
クラスの読み込み (一度読み込まれるとメモリに残ります)
ネイティブライブラリから追加コードを取得する (ネイティブコードはキャッシュされます)
最後に、実行するコードを CPU の L1 キャッシュにロードします。これは、あなたの感覚では高速化の最も可能性の高いケースであると同時に、ベンチマーク (マイクロベンチマークであるため) が多くを語らない理由でもあります。コードが十分に小さい場合、ループの 2 番目の呼び出しは、高速な CPU 内部から完全に実行できます。現実の世界では、プログラムが大きく、L1 キャッシュの再利用がそれほど大きくないため、これは起こりません。

score 1 · Accepted Answer

最初の実行後、生成されたコードが既に最適化されているためだと思います。

java - 同じメソッドを 2 回連続して呼び出すと、実行時間が異なるのはなぜですか?

8 に答える 8

Related

Reference