jmh表示M1比M2快，但M1委托给M2

Question

我编写了一个JMH基准测试，涉及两个方法: M1和M2。M1调用M2，但出于某种原因，JMH声称M1比M2更快。

下面是基准源代码：

import java.util.concurrent.TimeUnit;
import static org.bitbucket.cowwoc.requirements.Requirements.assertThat;
import static org.bitbucket.cowwoc.requirements.Requirements.requireThat;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public class MyBenchmark {

    @Benchmark
    public void assertMethod() {
        assertThat("value", "name").isNotNull().isNotEmpty();
    }

    @Benchmark
    public void requireMethod() {
        requireThat("value", "name").isNotNull().isNotEmpty();
    }

    public static void main(String[] args) throws RunnerException {
        Options opt = new OptionsBuilder()
                .include(MyBenchmark.class.getSimpleName())
                .forks(1)
                .build();

        new Runner(opt).run();
    }
}

在上面的例子中，M1是assertThat()，M2是requireThat()。意思是，assertThat()调用引擎盖下的requireThat()。

下面是基准输出：

# JMH 1.13 (released 8 days ago)
# VM version: JDK 1.8.0_102, VM 25.102-b14
# VM invoker: C:\Program Files\Java\jdk1.8.0_102\jre\bin\java.exe
# VM options: -ea
# Warmup: 20 iterations, 1 s each
# Measurement: 20 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: com.mycompany.jmh.MyBenchmark.assertMethod

# Run progress: 0.00% complete, ETA 00:01:20
# Fork: 1 of 1
# Warmup Iteration   1: 8.268 ns/op
# Warmup Iteration   2: 6.082 ns/op
# Warmup Iteration   3: 4.846 ns/op
# Warmup Iteration   4: 4.854 ns/op
# Warmup Iteration   5: 4.834 ns/op
# Warmup Iteration   6: 4.831 ns/op
# Warmup Iteration   7: 4.815 ns/op
# Warmup Iteration   8: 4.839 ns/op
# Warmup Iteration   9: 4.825 ns/op
# Warmup Iteration  10: 4.812 ns/op
# Warmup Iteration  11: 4.806 ns/op
# Warmup Iteration  12: 4.805 ns/op
# Warmup Iteration  13: 4.802 ns/op
# Warmup Iteration  14: 4.813 ns/op
# Warmup Iteration  15: 4.805 ns/op
# Warmup Iteration  16: 4.818 ns/op
# Warmup Iteration  17: 4.815 ns/op
# Warmup Iteration  18: 4.817 ns/op
# Warmup Iteration  19: 4.812 ns/op
# Warmup Iteration  20: 4.810 ns/op
Iteration   1: 4.805 ns/op
Iteration   2: 4.816 ns/op
Iteration   3: 4.813 ns/op
Iteration   4: 4.938 ns/op
Iteration   5: 5.061 ns/op
Iteration   6: 5.129 ns/op
Iteration   7: 4.828 ns/op
Iteration   8: 4.837 ns/op
Iteration   9: 4.819 ns/op
Iteration  10: 4.815 ns/op
Iteration  11: 4.872 ns/op
Iteration  12: 4.806 ns/op
Iteration  13: 4.811 ns/op
Iteration  14: 4.827 ns/op
Iteration  15: 4.837 ns/op
Iteration  16: 4.842 ns/op
Iteration  17: 4.812 ns/op
Iteration  18: 4.809 ns/op
Iteration  19: 4.806 ns/op
Iteration  20: 4.815 ns/op


Result "assertMethod":
  4.855 �(99.9%) 0.077 ns/op [Average]
  (min, avg, max) = (4.805, 4.855, 5.129), stdev = 0.088
  CI (99.9%): [4.778, 4.932] (assumes normal distribution)


# JMH 1.13 (released 8 days ago)
# VM version: JDK 1.8.0_102, VM 25.102-b14
# VM invoker: C:\Program Files\Java\jdk1.8.0_102\jre\bin\java.exe
# VM options: -ea
# Warmup: 20 iterations, 1 s each
# Measurement: 20 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: com.mycompany.jmh.MyBenchmark.requireMethod

# Run progress: 50.00% complete, ETA 00:00:40
# Fork: 1 of 1
# Warmup Iteration   1: 7.193 ns/op
# Warmup Iteration   2: 4.835 ns/op
# Warmup Iteration   3: 5.039 ns/op
# Warmup Iteration   4: 5.053 ns/op
# Warmup Iteration   5: 5.077 ns/op
# Warmup Iteration   6: 5.102 ns/op
# Warmup Iteration   7: 5.088 ns/op
# Warmup Iteration   8: 5.109 ns/op
# Warmup Iteration   9: 5.096 ns/op
# Warmup Iteration  10: 5.096 ns/op
# Warmup Iteration  11: 5.091 ns/op
# Warmup Iteration  12: 5.089 ns/op
# Warmup Iteration  13: 5.099 ns/op
# Warmup Iteration  14: 5.097 ns/op
# Warmup Iteration  15: 5.090 ns/op
# Warmup Iteration  16: 5.096 ns/op
# Warmup Iteration  17: 5.088 ns/op
# Warmup Iteration  18: 5.086 ns/op
# Warmup Iteration  19: 5.087 ns/op
# Warmup Iteration  20: 5.097 ns/op
Iteration   1: 5.097 ns/op
Iteration   2: 5.088 ns/op
Iteration   3: 5.092 ns/op
Iteration   4: 5.097 ns/op
Iteration   5: 5.082 ns/op
Iteration   6: 5.089 ns/op
Iteration   7: 5.086 ns/op
Iteration   8: 5.084 ns/op
Iteration   9: 5.090 ns/op
Iteration  10: 5.086 ns/op
Iteration  11: 5.084 ns/op
Iteration  12: 5.088 ns/op
Iteration  13: 5.091 ns/op
Iteration  14: 5.092 ns/op
Iteration  15: 5.085 ns/op
Iteration  16: 5.096 ns/op
Iteration  17: 5.078 ns/op
Iteration  18: 5.125 ns/op
Iteration  19: 5.089 ns/op
Iteration  20: 5.091 ns/op


Result "requireMethod":
  5.091 �(99.9%) 0.008 ns/op [Average]
  (min, avg, max) = (5.078, 5.091, 5.125), stdev = 0.010
  CI (99.9%): [5.082, 5.099] (assumes normal distribution)


# Run complete. Total time: 00:01:21

Benchmark                       Mode  Cnt  Score   Error  Units
MyBenchmark.assertMethod        avgt   20  4.855 � 0.077  ns/op
MyBenchmark.requireMethod       avgt   20  5.091 � 0.008  ns/op

在当地复制：

1. 创建包含上述基准测试的Maven项目。
2. 添加以下依赖项： org.bitbucket.cowwoc需求2.0.0
3. 或者，从https://github.com/cowwoc/requirements.java/下载库

我有以下问题：

1. 你能在你的头上复制这个结果吗？
2. 如果说有什么问题的话，那么基准有什么问题呢？

更新：我终于得到了一致、有意义的结果。

Benchmark                  Mode  Cnt   Score   Error  Units
MyBenchmark.assertMethod   avgt   60  22.552 ± 0.020  ns/op
MyBenchmark.requireMethod  avgt   60  22.411 ± 0.114  ns/op

对于consistent，我的意思是在运行期间得到几乎相同的值。

meaningful的意思是assertMethod()比requireMethod()慢。

我做了以下修改：

• 锁定CPU时钟( Windows电源选项中将最小/最大CPU设置为99% )
• 添加了JVM选项-XX:-TieredCompilation -XX:-ProfileInterpreter

没有人能够在不增加运行时间的情况下实现这些结果吗？

UPDATE2：禁用内联会产生相同的结果，而不会出现明显的性能下降。我发布了一个更详细的答案，这里。

Answer 1

在这种情况下，由于注册分配问题，assertMethod requireMethod 确实比requireMethod编译得更好。

基准看起来是正确的，而且我可以始终如一地复制您的结果。

为了分析我做了简化基准的问题

package bench;

import com.google.common.collect.ImmutableMap;
import org.openjdk.jmh.annotations.*;

@State(Scope.Benchmark)
public class Requirements {
    private static boolean enabled = true;

    private String name = "name";
    private String value = "value";

    @Benchmark
    public Object assertMethod() {
        if (enabled)
            return requireThat(value, name);
        return null;
    }

    @Benchmark
    public Object requireMethod() {
        return requireThat(value, name);
    }

    public static Object requireThat(String parameter, String name) {
        if (name.trim().isEmpty())
            throw new IllegalArgumentException();
        return new StringRequirementsImpl(parameter, name, new Configuration());
    }

    static class Configuration {
        private Object context = ImmutableMap.of();
    }

    static class StringRequirementsImpl {
        private String parameter;
        private String name;
        private Configuration config;
        private ObjectRequirementsImpl asObject;

        StringRequirementsImpl(String parameter, String name, Configuration config) {
            this.parameter = parameter;
            this.name = name;
            this.config = config;
            this.asObject = new ObjectRequirementsImpl(parameter, name, config);
        }
    }

    static class ObjectRequirementsImpl {
        private Object parameter;
        private String name;
        private Configuration config;

        ObjectRequirementsImpl(Object parameter, String name, Configuration config) {
            this.parameter = parameter;
            this.name = name;
            this.config = config;
        }
    }
}

首先，我通过-XX:+PrintInlining验证了整个基准测试都包含在一个大方法中。显然，这个编译单元有大量的节点，并且没有足够的CPU寄存器来保存所有的中间变量。也就是说，编译器需要溢油其中的一些。

• 在assertMethod中，4个寄存器在调用trim()之前溢出到堆栈中。
• 在requireMethod中，7个登记册稍后会在调用new Configuration()之后溢出。

-XX:+PrintAssembly输出：

  assertMethod             |  requireMethod
  -------------------------|------------------------
  mov    %r11d,0x5c(%rsp)  |  mov    %rcx,0x20(%rsp)
  mov    %r10d,0x58(%rsp)  |  mov    %r11,0x48(%rsp)
  mov    %rbp,0x50(%rsp)   |  mov    %r10,0x30(%rsp)
  mov    %rbx,0x48(%rsp)   |  mov    %rbp,0x50(%rsp)
                           |  mov    %r9d,0x58(%rsp)
                           |  mov    %edi,0x5c(%rsp)
                           |  mov    %r8,0x60(%rsp) 

除了if (enabled)检查之外，这几乎是两个编译方法之间的唯一区别。因此，性能差异由更多的变量溢出到内存中来解释。

那么，为什么较小的方法被编译得不那么优化呢？注册分配问题是NP-完全的。由于在理想情况下无法在合理的时间内解决这个问题，编译器通常依赖于某些启发式方法。在一种大的方法中，像额外的if这样的小东西可能会显着地改变寄存器分配算法的结果。

但是你不需要担心这个。我们看到的效果并不意味着requireMethod总是被编译得更糟。在其他用例中，由于内联，编译图将完全不同。无论如何，1毫微秒的差异对实际应用性能没有任何影响。

Answer 2

通过指定forks(1)，在单个VM进程中运行测试。在运行时，虚拟机会查看您的代码并试图找出它是如何实际执行的。然后，它创建所谓的配置文件，以便根据所观察到的行为优化应用程序。

这里最有可能发生的情况叫做profile污染，运行第一个基准对第二个基准的结果有影响。过于简单:如果您的VM被训练为(a)通过运行它的基准很好，那么它需要一些额外的时间来适应(b)之后的工作。因此，(b)似乎需要更多的时间。

为了避免这种情况，使用多个分支运行您的基准测试，在新的VM进程上运行不同的基准测试，以避免这种概要文件污染。您可以在由JMH提供的示例中阅读更多有关分叉的内容。

您还应该检查状态样本；您不应该将输入引用为常量，而是让JMH处理值的转义，以便应用实际的计算。

我想--如果应用得当--这两个基准都会产生类似的运行时。

更新-以下是我获得的固定基准测试的结果：

Benchmark                  Mode  Cnt   Score   Error  Units
MyBenchmark.assertMethod   avgt   40  17,592 ± 1,493  ns/op
MyBenchmark.requireMethod  avgt   40  17,999 ± 0,920  ns/op

为了完成，我还运行了性能测试，这两种方法基本上都编译成了相同的东西。

Answer 3

回答我自己的问题：

内衬似乎是扭曲的结果。为了取得一致、有意义的结果，我所需要做的就是：

• 锁定CPU时钟( Windows电源选项中将最小/最大CPU设置为99% )
• 通过用@CompilerControl(CompilerControl.Mode.DONT_INLINE)注释这两个方法来禁用内联。

我现在得到以下结果：

Benchmark                  Mode  Cnt   Score   Error  Units
MyBenchmark.assertMethod   avgt  200  11.462 ± 0.048  ns/op
MyBenchmark.requireMethod  avgt  200  11.138 ± 0.062  ns/op

我试着分析了-XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining的输出，但是没有发现任何问题。这两种方法似乎都是以同样的方式内联的。

基准源代码是：

import java.util.concurrent.TimeUnit;
import static org.bitbucket.cowwoc.requirements.Requirements.assertThat;
import static org.bitbucket.cowwoc.requirements.Requirements.requireThat;
import org.bitbucket.cowwoc.requirements.StringRequirements;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.CompilerControl;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;

@State(Scope.Benchmark)
public class MyBenchmark {

    private String name = "name";
    private String value = "value";

    @Benchmark
    public void emptyMethod() {
    }

    // Inlining leads to unexpected results: https://stackoverflow.com/a/38860869/14731
    @Benchmark
    @CompilerControl(CompilerControl.Mode.DONT_INLINE)
    public StringRequirements assertMethod() {
        return assertThat(value, name).isNotNull().isNotEmpty();
    }

    @Benchmark
    @CompilerControl(CompilerControl.Mode.DONT_INLINE)
    public StringRequirements requireMethod() {
        return requireThat(value, name).isNotNull().isNotEmpty();
    }

    public static void main(String[] args) throws RunnerException {
        Options opt = new OptionsBuilder()
                .include(MyBenchmark.class.getSimpleName())
                .jvmArgsAppend("-ea")
                .forks(3)
                .timeUnit(TimeUnit.NANOSECONDS)
                .mode(Mode.AverageTime)
                .build();

        new Runner(opt).run();
    }
}

UPDATE：阿潘金似乎有解出为什么assertMethod()比requireMethod()快。