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

• 为什么这两种方法都被编译了两次？
• 我该如何阅读这个输出......不同的数字代表什么意思？

- Parag

---

感谢@Thomas Jungblut，不确定我是如何在标题中漏掉了-XX：+PrintCompilation的。 - Parag

np，这里有一个关于编译的好资源：https://gist.github.com/1165804#file_notes.md - Thomas Jungblut

Answer 1

我将尝试回答自己的问题，并借助链接，该链接由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' 是时间戳。

第二列

第二列是编译ID和方法属性。当触发HotSpot编译时，每个编译单元都会得到一个编译ID。第二列中的数字是编译ID。JIT编译和OSR编译有两个不同的编译ID序列。因此，1%和1是不同的编译单元。在前两行中的％表示这是一个OSR编译。由于代码正在循环遍历大型循环并且VM确定该代码很热，因此触发了OSR编译。这将使VM能够进行On Stack Replacement并转移到优化后的代码，一旦它准备好。

第三列

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

第四列

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

Java方法中的“位置”由其字节码索引（BCI）定义， 触发OSR编译的位置称为“osr_bci”。 只能从其osr_bci进入OSR-编译nmethod； 同时可以有多个相同方法的OSR编译版本，前提是它们的osr_bci不同。

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

第一个是OSR编译，据推测是在循环运行时通过热身代码（在示例中）触发的，第二个编译是JIT编译，据推测是为了进一步优化编译代码？

- Parag

---

如果在热身期间出现OSR代码，“你做错了”。同时列出JVM的参数，可能只有C1（客户端/愚笨编译器）和C2（更聪明、更慢的编译器）。重新编译也可能是去优化的结果。最简单的方法是列出生成的代码，如果看到C1存根，就知道它是C1代码。 - bestsss

@bestsss 为什么会这样呢？我认为 OSR 编译是因为示例的预热代码调用了一个大循环。 - Parag

我的观点是，如果你想要加速任何东西，你应该避免使用OSR，而是将其拆分成更小的方法。 - bestsss

如果你禁用分层编译（-XX：-TieredCompilation）并只保留C2，那么你可以确定它是OSR+C2。 - bestsss

@bestsss 谢谢，我试过了。结果与没有使用-XX：-TieredCompilation时得到的完全相同。所以我猜测这是OSR+C2。按编译单元列出代码是一个好主意。它可能会给出一些关于为什么尝试重新编译的想法。 - Parag

Answer 2

我认为第一次发生OSR时，它会改变调用计数器以触发编译器方法。

- wgz