Gili Gili - 4 months ago 16
Java Question

jmh indicates that M1 is faster than M2 but M1 delegates to M2

I wrote a JMH benchmark involving 2 methods: M1 and M2. M1 invokes M2 but for some reason, JMH claims that M1 is faster than M2.

Here is the benchmark source-code:

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();
}
}


In the above example, M1 is
assertThat()
, M2 is
requireThat()
. Meaning,
assertThat()
invokes
requireThat()
under the hood.

Here is the benchmark output:

# 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


To reproduce this locally:


  1. Create a Maven project containing the above benchmark.

  2. Add the following dependency:

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

  3. Alternatively, download the library from https://bitbucket.org/cowwoc/requirements/



I have the following questions:


  1. Can you reproduce this result on your end?

  2. What, if anything, is wrong with the benchmark?



UPDATE: I posted an updated benchmark source-code, benchmark output, jmh-test output and xperfasm output to https://bitbucket.org/cowwoc/requirements/downloads per Aleksey Shipilev's suggestion. I cannot post these to Stackoverflow due to the 30k character limit on questions.

UPDATE2: I am finally getting consistent, meaningful results.

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


By
consistent
, I mean that I get almost the same values across runs.

By
meaningful
, I mean that
assertMethod()
is slower than
requireMethod()
.

I made the following changes:


  • Locked the CPU clock (min/max CPU set to 99% in Windows Power Options)

  • Added JVM options
    -XX:-TieredCompilation -XX:-ProfileInterpreter



Is anyone able to achieve these results without the doubling of run times?

UPDATE3: Disabling inlining yields the same results without a noticeable performance slowdown. I posted a more detailed answer here.

Answer

Answering my own question:

It seems that inlining is skewing results. All I needed to do to get consistent, meaningful results was the following:

  • Lock the CPU clock (min/max CPU set to 99% in Windows Power Options)
  • Disable inlining by annotating both methods with @CompilerControl(CompilerControl.Mode.DONT_INLINE).

I now get the following results:

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

I tried analyzing the output of -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining but couldn't find anything wrong. Both methods seem to get inlined the same way. <shrug>


The benchmark source-code is:

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: http://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();
    }
}