-XXの出力を理解する：+ PrintCompilation

Question

Javaリスト反復コードでいくつかのマイクロベンチマークを実行しています。私は、-XX：+ PrintCompilationと-verbose：gcフラグを使用して、タイミングが実行されているときにバックグラウンドで何も起こっていないことを確認しました。しかし、私は理解できないものを出力に見る。

は、ここで私は上でベンチマークを実行しています、コードです：

import java.util.ArrayList; 
import java.util.List; 

public class PerformantIteration { 

    private static int theSum = 0; 

    public static void main(String[] args) { 
     System.out.println("Starting microbenchmark on iterating over collections with a call to size() in each iteration"); 
     List<Integer> nums = new ArrayList<Integer>(); 
     for(int i=0; i<50000; i++) { 
      nums.add(i); 
     } 

     System.out.println("Warming up ..."); 
     //warmup... make sure all JIT comliling is done before the actual benchmarking starts 
     for(int i=0; i<10; i++) { 
      iterateWithConstantSize(nums); 
      iterateWithDynamicSize(nums); 
     } 

     //actual   
     System.out.println("Starting the actual test"); 
     long constantSizeBenchmark = iterateWithConstantSize(nums); 
     long dynamicSizeBenchmark = iterateWithDynamicSize(nums); 
     System.out.println("Test completed... printing results"); 

     System.out.println("constantSizeBenchmark : " + constantSizeBenchmark); 
     System.out.println("dynamicSizeBenchmark : " + dynamicSizeBenchmark); 
     System.out.println("dynamicSizeBenchmark/constantSizeBenchmark : " + ((double)dynamicSizeBenchmark/(double)constantSizeBenchmark)); 
    } 

    private static long iterateWithDynamicSize(List<Integer> nums) { 
     int sum=0; 
     long start = System.nanoTime();   
     for(int i=0; i<nums.size(); i++) { 
      // appear to do something useful 
      sum += nums.get(i); 
     }  
     long end = System.nanoTime(); 
     setSum(sum); 
     return end-start; 
    } 

    private static long iterateWithConstantSize(List<Integer> nums) { 
     int count = nums.size(); 
     int sum=0; 
     long start = System.nanoTime();   
     for(int i=0; i<count; i++) { 
      // appear to do something useful 
      sum += nums.get(i); 
     } 
     long end = System.nanoTime(); 
     setSum(sum); 
     return end-start; 
    } 

    // invocations to this method simply exist to fool the VM into thinking that we are doing something useful in the loop 
    private static void setSum(int sum) { 
     theSum = sum;  
    } 

} 

はここで出力です。

152 1  java.lang.String::charAt (33 bytes) 
    160 2  java.lang.String::indexOf (151 bytes) 
    165 3Starting microbenchmark on iterating over collections with a call to size() in each iteration  java.lang.String::hashCode (60 bytes) 
    171 4  sun.nio.cs.UTF_8$Encoder::encodeArrayLoop (490 bytes) 
    183 5 
     java.lang.String::lastIndexOf (156 bytes) 
    197 6  java.io.UnixFileSystem::normalize (75 bytes) 
    200 7  java.lang.Object::<init> (1 bytes) 
    205 8  java.lang.Number::<init> (5 bytes) 
    206 9  java.lang.Integer::<init> (10 bytes) 
    211 10  java.util.ArrayList::add (29 bytes) 
    211 11  java.util.ArrayList::ensureCapacity (58 bytes) 
    217 12  java.lang.Integer::valueOf (35 bytes) 
    221 1%  performance.api.PerformantIteration::main @ 21 (173 bytes) 
Warming up ... 
    252 13  java.util.ArrayList::get (11 bytes) 
    252 14  java.util.ArrayList::rangeCheck (22 bytes) 
    253 15  java.util.ArrayList::elementData (7 bytes) 
    260 2%  performance.api.PerformantIteration::iterateWithConstantSize @ 19 (59 bytes) 
    268 3%  performance.api.PerformantIteration::iterateWithDynamicSize @ 12 (57 bytes) 
    272 16  performance.api.PerformantIteration::iterateWithConstantSize (59 bytes) 
    278 17  performance.api.PerformantIteration::iterateWithDynamicSize (57 bytes) 
Starting the actual test 
Test completed... printing results 
constantSizeBenchmark : 301688 
dynamicSizeBenchmark : 782602 
dynamicSizeBenchmark/constantSizeBenchmark : 2.5940773249184588 

私は出力からこれらの4行を理解していません。

260 2%  performance.api.PerformantIteration::iterateWithConstantSize @ 19 (59 bytes) 
268 3%  performance.api.PerformantIteration::iterateWithDynamicSize @ 12 (57 bytes) 
272 16  performance.api.PerformantIteration::iterateWithConstantSize (59 bytes) 
278 17  performance.api.PerformantIteration::iterateWithDynamicSize (57 bytes) 

• なぜ両方のこれらの方法は二回コンパイルされていますか？
• この出力を読むにはどうすればよいですか...さまざまな数字は何を意味していますか？

Answer 1

私はこのlinkの投稿で自分自身の質問に答えようとしています。Thomas Jungblutによって投稿されました。

260 2%  performance.api.PerformantIteration::iterateWithConstantSize @ 19 (59 bytes) 
268 3%  performance.api.PerformantIteration::iterateWithDynamicSize @ 12 (57 bytes) 
272 16  performance.api.PerformantIteration::iterateWithConstantSize (59 bytes) 
278 17  performance.api.PerformantIteration::iterateWithDynamicSize (57 bytes) 

最初の列は

最初の列 '260' のタイムスタンプです。

第二カラム2番目の列は、compilation_idとmethod_attributesあります。 HotSpotのコンパイルがトリガーされると、コンパイル単位ごとにコンパイルIDが取得されます。 2番目の列の番号はコンパイルIDです。 JITコンパイル、およびOSRコンパイルでは、コンパイルIDに2つの異なるシーケンスがあります。したがって、1％と1は異なるコンパイル単位です。最初の2行の％は、これがOSRコンパイルであるという事実を参照してください。コードが大きなループでループしていたためにOSRコンパイルがトリガされ、VMはこのコードが熱いと判断しました。そのため、OSRコンパイルがトリガされ、VMがOn Stack Replacementを実行し、最適化されたコードに移動する準備が整いました。

第カラム

3列performance.api.PerformantIteration::iterateWithConstantSizeは、メソッドの名前です。 OSRのコンパイルが発生し、それがないときでないとき

4列目

4列目は再び異なっています。最初に一般的な部分を見てみましょう。 4番目の列の終わり（59バイト）は、コンパイルされたコードのサイズではなく、バイトコードのコンパイル単位のサイズを参照します。 OSRコンパイルの@ 19部分は、osr_bciを参照しています。「osr_bci」と呼ばれているOSRコンパイルをトリガし、そのバイトコードインデックス（BCI）、および 場所で定義されたJavaメソッドで

A「場所」 - 私は、上記のリンクから引用するつもりです。 OSRコンパイルされたnmethodは、そのosr_bciからのみ入力できます。 は、同一のメソッドの複数のOSRコンパイル済みバージョンを、同じ の時間で、それらのosr_bciが異なる限り、複数のものにすることができます。

最後に、なぜメソッドが2回コンパイルされましたか？

最初のものはウォームアップコード（この例では）のためにループが実行されている間に起こったと思われるOSRコンパイルで、2番目のコンパイルはおそらくコンパイルされたコードをさらに最適化するJITコンパイルです。

Answer 2

は、私はそれが呼び出しカウンターティガー方法を変更する、初めてのOSRが起こったのだと思いcompilar から+ PrintCompilation：：私は-XXを逃したか（PS申し訳ありませんが、私の英語はプール）