了解-XX输出:+ PrintCompilation(Understanding the outpu

2019-08-01 23:41发布

我运行于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


我不明白,从输出这四条线。

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:

我要试图回答我的问题与此的帮助链接张贴由托马斯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”是时间戳。

第二列

第二列是compilation_id和method_attributes。 当热点编译被触发时,每个编译单元中得到一个编译ID。 在第二列的数字是编译的ID。 JIT编译,并且OSR编译对编译ID两种不同的序列。 因此,1%和1是不同的编译单元。 在第一个两行的%,指的是事实,这是一个OSR汇编。 一个OSR编译被触发,因为代码是遍历一个大的循环,以及VM确定该代码是热的。 因此,一个OSR编译被触发,这将使虚拟机做了一个堆栈更换和移动到优化的代码,一旦它已准备就绪。

第三列

第三列performance.api.PerformantIteration::iterateWithConstantSize是方法名。

第四列

第四列是再不同的,当OSR编译发生,当它没有。 让我们来看看常见的部分第一。 第四列(59个字节)的端部,指的是编译单元的字节码大小(未编译的代码的大小)。 在@ 19部分OSR编译指osr_bci。 我会从上述链接引用 -

A“到位” Java方法是由它的字节码索引(BCI),并且触发的OSR编译被称为“osr_bci”的地方所定义。 一个OSR编译nmethod只能从它的osr_bci进入; 还有可以在同一时间同一方法的多个OSR编译版本,只要他们osr_bci不同。

最后,为什么该方法编了两次?

第一个是一个OSR汇编,而循环是由于(在该示例中)延伸到预热代码这大概发生,并且所述第二编译是一个JIT编译,大概是为了进一步优化编译代码?



Answer 2:

我觉得第一次OSR发生了,那么它改变调用计数器跳跳虎方法compilar(PS:对不起,我的英语是池)



文章来源: Understanding the output of -XX:+PrintCompilation