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

StackOverflow https://stackoverflow.com/questions/804620

質問

サンプルコードを次に示します。

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（Just In Time）コンパイラーが実行されていない可能性があります。 JVMは、呼び出しごとに異なる最適化を実行できます。経過時間を測定しているため、Java以外の何かがマシンで実行されている可能性があります。プロセッサとRAMのキャッシュはおそらく「ウォーム」です。後続の呼び出しで。

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

他のヒント

Andreas とJITの予測不可能性は真実ですが、さらにもう1つの問題はクラスローダー：

です。

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

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

サンプルプログラムは非常に短いため、オーバーヘッドはおそらく初期の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 *

その時間差の理由は次のとおりです。 [動的リンクネイティブメソッドjava.io.FileOutputStream.writeBytes ... JNI]

JITコンパイラがこのベンチマークに影響を与えていないこともわかります。コンパイルされるメソッドは3つだけで（上記のスニペットの java.lang.String :: indexOf など）、これらはすべて fOne メソッドが呼び出される前に発生します。

  1. テストしたコードは非常に簡単です。最も高価なアクションは

    です 
     System.out.println(k);

    測定しているのは、デバッグ出力の書き込み速度です。これは大きく異なり、デバッグウィンドウのサイズなどをスクロールする必要がある場合、画面上のデバッグウィンドウの位置にも依存します。

  2. JIT / Hotspotは、よく使用されるコードパスを段階的に最適化します。

  3. プロセッサは、予想されるコードパスに対して最適化します。より頻繁に使用されるパスはより速く実行されます。

  4. サンプルサイズが小さすぎます。そのようなマイクロベンチマークは通常、 Javaのように、これがどれほど広範囲に行われるべきかを確認できるウォームアップ段階を実行します。何もしないで速い。

JITtingに加えて、他の要因は次のとおりです。

  • System.out.printlnを呼び出したときのプロセスの出力ストリームのブロック
  • あなたのプロセスは別のプロセスによってスケジュールされています
  • バックグラウンドスレッドで作業を行うガベージコレクター

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

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

このようなことを行うのに役立ついくつかのプラットフォームにベンチマークライブラリがあります。また、標準偏差やその他の統計を計算できます。

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

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

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

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

さて、おそらくおそらく答えは初期化です。 JITは最適化を開始するまでにさらに多くのサイクルを要するため、正しい答えではありません。しかし、最初は次のことが可能です：

  • クラスの検索（キャッシュされているため、2回目の検索は不要です）
  • クラスのロード（一度ロードされるとメモリに残ります）
  • ネイティブライブラリから追加コードを取得する（ネイティブコードはキャッシュされます）
  • 最終的に、実行されるコードをCPUのL1キャッシュにロードします。それはあなたの感覚でスピードアップのための最も適切なケースであり、同時にベンチマーク（マイクロベンチマークである）があまり言っていない理由です。コードが十分に小さい場合、ループの2回目の呼び出しは、高速なCPU内から完全に実行できます。現実の世界では、プログラムはより大きく、L1キャッシュの再利用はそれほど大きくないため、これは起こりません。
ライセンス： CC-BY-SA と 帰属
所属していません StackOverflow
scroll top