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

【问题标题】：jmh indicates that M1 is faster than M2 but M1 delegates to M2jmh 表示 M1 比 M2 快，但 M1 委托给 M2
【发布时间】：2016-12-05 19:58:14
【问题描述】：

我编写了一个 JMH 基准测试，涉及 2 种方法：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

要在本地重现：

创建一个包含上述基准的 Maven 项目。

添加以下依赖：

 <dependency>
     <groupId>org.bitbucket.cowwoc</groupId>
     <artifactId>requirements</artifactId>
     <version>2.0.0</version>
 </dependency>

或者，从https://github.com/cowwoc/requirements.java/下载库

我有以下问题：

你能重现这个结果吗？
基准测试有什么问题（如果有的话）？

更新：根据Aleksey Shipilev 的建议，我向https://bitbucket.org/cowwoc/requirements/downloads 发布了更新的基准源代码、基准输出、jmh-test 输出和xperfasm 输出。由于问题的字符数限制为 30k，我无法将这些发布到 Stackoverflow。

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

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

是否有人能够在不加倍运行时间的情况下实现这些结果？

UPDATE3：禁用内联会产生相同的结果，而不会明显降低性能。我发布了更详细的答案here。

【问题讨论】：

这可能不是问题，但您应该从@State 字段获取输入，并将输出接收到@Benchmark 返回值或显式Blackhole。见：gist.github.com/shipilev/712b5e4e4800c3ed982dcbae97e4d6df
我无法在类似配置上重现差异，这让人怀疑环境设置的有效性。尝试运行 JMH 核心基准测试？可运行的 JAR：central.maven.org/maven2/org/openjdk/jmh/jmh-core-benchmarks/…
@AlekseyShipilev 很好地了解了非最终输入和下沉输出。我现在得到了更实际的数字（参见 UPDATE2），但 assertMethod() 仍然比 requireMethod() 快。正如你提到的，我还运行了 JMH 核心基准测试，它们似乎恢复正常。由于 30k 字符限制，我无法在 Stackoverflow 上发布结果，但如果您给我发电子邮件（查看我的个人资料以获取我的电子邮件地址），我会将文件发送给您。
@AlekseyShipilev 有趣的是，如果我一次只运行一个基准测试方法（我注释掉另一个），我仍然会得到相同的结果。这意味着，一个基准不可能干扰另一个基准的测试结果。
@Gili：我怪你的操作系统（Windows）不适合基准测试。下面是我在 Linux 上得到的。

标签： java performance-testing jmh

【解决方案1】：

在这种特殊情况下，由于寄存器分配问题，assertMethod 确实比 requireMethod 编译得更好。

基准看起来是正确的，我可以始终如一地重现您的结果。
分析我做的问题the simplified benchmark：

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 寄存器来保存所有的中间变量。也就是编译器需要spill其中一些。

在assertMethod 4 registers 在调用trim() 之前溢出到堆栈。
在requireMethod 7 registers 稍后会在调用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 纳秒的差异对于真正的应用程序性能来说不算什么。

【讨论】：

最后，一个有意义的答案！ :) 我特别喜欢您能够使用简化的基准测试来重现问题的事实。好工作！请尝试将尽可能多的要点转移到此答案中，以防止将来出现断开的链接。

【解决方案2】：

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

这里最有可能发生的情况称为配置文件污染，其中运行第一个基准测试会影响第二个基准测试的结果。过于简单化：如果你的虚拟机通过运行它的基准测试来训练 (a) 做得很好，它需要一些额外的时间来适应之后做 (b)。因此，(b) 似乎需要更多时间。

为了避免这种情况，请使用多个 fork 运行基准测试，其中不同的基准测试在新的 VM 进程上运行，以避免此类配置文件污染。您可以在are provided by JMH 的示例中阅读有关分叉的更多信息。

您还应该检查the sample on state；您不应将输入称为常量，而应让 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

为了补全，我也用perfasm跑了benchmark，两种方法基本编译成同一个东西。

【讨论】：

这个答案听起来很有希望，但分叉和状态隔离都对我不起作用。请尝试在本地重现问题。如果您能够解决它，请发布工作代码，以便我确认您的发现。
我在问题中添加了更新的基准。看一看。我也很感激你在这个答案中发布你自己的实现。
我已经可以发现错误。不要使字符串最终；这会呈现一个由 javac 内联的编译时间常数。相反，注释基准本身并将（非最终）字段添加到它。不需要额外的课程。
我尝试了您的建议（注释方法并使用非最终字段），但没有帮助。查看更新的答案。
指责 Windows 是一种简单的逃避方式。我不认为我们还在那里。首先，为什么您的误差幅度如此之大？我的总是小于 0.1 ns。有了如此大的误差范围，您不能肯定地说您的结果与我的结果有任何不同（assertMethod() 仍然可能比requireMethod() 快）。如果你得到更小的误差范围，你能重新运行并告诉我吗？

【解决方案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();
    }
}

更新：apangin 似乎有figured out 为什么assertMethod() 比requireMethod() 快。

【讨论】：

【解决方案4】：

这在微基准测试中非常常见。当我下载你的代码时，我得到了相同的结果，但使用其他数字，显然我的电脑比你的慢。但是，如果我将您的源代码修改为使用 5 个分叉、100 次预热迭代和 20 次测量迭代，那么 requireMethod 会像预期的那样比 assertMethod 快一点。

JMH 很棒，但是很容易编写看起来不错的测试，但是由于迭代太少，您不能相信结果。

【讨论】：

你让我兴奋，但我无法重现你的结果（使用你提到的相同参数）。然后我尝试了高达 10 次分叉、100 次预热迭代和 100 次测量迭代，但 assertMethod() 的运行速度仍然比 requireMethod() 快。