了解 -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

我看不懂输出中的这四行。

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

我将尝试在Thomas Jungblut 发布的link 的帮助下回答我自己的问题。

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”是时间戳。

第二栏

第二列是compile_id和method_attributes。当触发 HotSpot 编译时，每个编译单元都会获得一个编译 ID。第二列中的数字是编译 id。 JIT 编译和 OSR 编译有两种不同的编译 id 序列。所以 1% 和 1 是不同的编译单位。前两行中的 % 表示这是一个 OSR 编译。触发了 OSR 编译，因为代码在一个大循环上循环，并且 VM 确定此代码很热。因此触发了 OSR 编译，这将使 VM 能够执行堆栈替换并在准备好后移至优化代码。

第三栏

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

第四栏

当 OSR 编译发生和不发生时，第四列再次不同。我们先来看看常见的部分。第四列的末尾（59 个字节），指的是编译单元在字节码中的大小（不是编译后代码的大小）。 OSR 编译中的@19 部分指的是osr_bci。我将引用上面提到的链接 -

Java 方法中的“位置”由其字节码索引 (BCI) 定义，并且 触发 OSR 编译的地方称为“osr_bci”。 一个 OSR 编译的 nmethod 只能从它的 osr_bci 输入；那里 可以同时是同一方法的多个 OSR 编译版本 时间，只要它们的 osr_bci 不同。

最后，为什么方法编译了两次？

第一个是 OSR 编译，大概是在循环运行时由于预热代码（在示例中）而发生的，第二个编译是 JIT 编译，大概是为了进一步优化编译后的代码？

Answer 2

我认为第一次 OSR 发生了，然后它改变了 Invocation Counter tigger 方法编译器 （PS：对不起，我的英文是pool）