Benchmarking with JMH

A microbenchmark measures the cost of a small piece of code. On the JVM a timing loop written by hand measures the interpreter, the JIT compiler, and the optimizer as much as the code. This lesson shows each pitfall with a runnable program that prints checks, then shows how JMH (Java Microbenchmark Harness, the OpenJDK benchmarking tool) avoids it. After it, a reader can write a JMH benchmark, run it, and read its results.

JMH is not on this course's class path, and a JMH run needs its annotation processor plus several minutes per benchmark. JMH code is therefore marked java,ignore. The runnable examples print checks and counts, never times, because times differ on every machine.

Example 1: the first iterations measure the compiler

The JIT compiles a method only after it has run many times (tiered compilation). CompilationMXBean.getTotalCompilationTime reports the total milliseconds the JIT threads have spent compiling, so a change during a timing round shows that the round included compilation.

import java.lang.management.CompilationMXBean;
import java.lang.management.ManagementFactory;

public class WarmupCheck {
    static long work(int n) {
        long s = 0;
        for (int i = 0; i < n; i++) s += (i * 31L) ^ (s >>> 3);
        return s;
    }

    public static void main(String[] args) {
        CompilationMXBean jit = ManagementFactory.getCompilationMXBean();
        System.out.println("compilation time monitored: " + jit.isCompilationTimeMonitoringSupported());

        long sink = 0;
        long before = jit.getTotalCompilationTime();
        for (int i = 0; i < 2_000; i++) sink += work(1_000);   // "round 1" of a naive benchmark
        long after = jit.getTotalCompilationTime();

        System.out.println("JIT compiled during round 1: " + (after > before));
        System.out.println("sink used: " + (sink != 42));
    }
}

compilation time monitored: true
JIT compiled during round 1: true
sink used: true

Round 1 ran partly in the interpreter, partly in C1 code, and partly in C2 code, and it paid for the compilations. A time taken over that round describes none of those modes. JMH separates warmup iterations, whose results are discarded, from measurement iterations.

Example 2: dead code elimination

Dead code elimination removes computations whose result is never used (escape analysis and loop optimizations). In a naive benchmark the result of the measured call is often thrown away, so after compilation the loop may measure nothing. The program shows the fix that JMH automates: every result flows into a value the program uses.

public class DeadCodeSink {
    static double compute(double x) {
        return Math.sqrt(x) * Math.log(x + 1);
    }

    public static void main(String[] args) {
        // Broken pattern: the result is dropped. After C2 compiles this loop,
        // the call has no observable effect and can be removed.
        for (int i = 1; i <= 1_000_000; i++) {
            compute(i);
        }

        // Fixed pattern: every result feeds a sink that is printed at the end.
        double sink = 0;
        for (int i = 1; i <= 1_000_000; i++) {
            sink += compute(i);
        }
        System.out.println("sink is finite: " + Double.isFinite(sink));
        System.out.println("sink > 0: " + (sink > 0));
    }
}

sink is finite: true
sink > 0: true

The first loop runs correctly and prints nothing, which is the problem: no check can show that it did the work, and once compiled it may not. Summing into a sink has its own cost (an add per call) and lets the JIT combine work across iterations. JMH's Blackhole (Example 6) consumes a value in a way the JIT cannot see through and that costs about the same each time.

Example 3: constant folding

Constant folding computes an expression with constant inputs once, at compile time. javac folds constant expressions of primitives and strings, and the JIT folds more after inlining, for example a static final field read in a pure method. A benchmark whose inputs are constants can end up measuring a load of the precomputed answer.

public class ConstantFolding {
    static final int SIZE = 6 * 7;          // folded by javac to 42
    static final String KEY = "order" + "-" + SIZE;   // folded to "order-42"

    public static void main(String[] args) {
        String built = new StringBuilder("order").append('-').append(42).toString();
        System.out.println("SIZE = " + SIZE);
        System.out.println("KEY is a pooled literal: " + (KEY == "order-42"));
        System.out.println("runtime string is a new object: " + (built != "order-42"));
        System.out.println("equal content: " + KEY.equals(built));
    }
}

SIZE = 42
KEY is a pooled literal: true
runtime string is a new object: true
equal content: true

KEY == "order-42" is true because javac replaced the expression with one literal from the string pool. The same happens inside the JIT for Math.sqrt(16.0) once the argument is known to be constant. JMH avoids it by reading inputs from fields of a @State object, which the JIT treats as values that can change.

Example 4: on-stack replacement

On-stack replacement (OSR) switches a method from the interpreter to compiled code in the middle of a running loop. A main method with one long timing loop is compiled this way, and OSR code is often optimized less well than a normal compilation of the same method, because the compiler starts from the loop's middle. The program below is the shape that triggers OSR; -XX:+PrintCompilation marks such compilations with %.

public class OsrShape {
    public static void main(String[] args) {
        long sum = 0;
        for (int i = 0; i < 50_000_000; i++) {   // one hot loop, never called again
            sum += i % 7;
        }
        System.out.println("sum = " + sum);
    }
}

sum = 149999997

Representative -XX:+PrintCompilation lines for this program (taken from one run in source-file mode; ids and timestamps differ per run):

1097 1256 %     3       OsrShape::main @ 4 (32 bytes)
1098 1258 %     4       OsrShape::main @ 4 (32 bytes)

The % column marks OSR, @ 4 is the bytecode index of the loop, and 3 and 4 are the C1 and C2 tiers. JMH calls the benchmark method from its own loop, so the method is compiled normally and inlined into that loop.

Example 5: a first JMH benchmark

JMH generates the harness code from annotations at compile time, so a project needs jmh-core and the jmh-generator-annprocess annotation processor. This code is java,ignore because neither is on the class path here.

import java.util.concurrent.TimeUnit;
import org.openjdk.jmh.annotations.*;

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 5, time = 1)
@Measurement(iterations = 5, time = 1)
@Fork(2)
@State(Scope.Thread)
public class SqrtBenchmark {
    double x = 12345.678;          // a field, not a constant: no folding

    @Benchmark
    public double sqrt() {
        return Math.sqrt(x);       // returned values are consumed by JMH
    }
}

Forks matter because JIT decisions depend on the profile. If two benchmarks run in one JVM, the second sees call sites already shaped by the first (profile pollution) and can be slower for reasons unrelated to its code.

Example 6: State, Setup, Param, and Blackhole

@Setup prepares inputs outside the measured time, @Param runs the benchmark for each listed value, and Blackhole.consume sinks values when a method produces more than one.

import java.util.*;
import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.infra.Blackhole;

@State(Scope.Benchmark)
@Fork(2)
public class LookupBenchmark {
    @Param({"16", "1024", "65536"})
    int size;

    Map<Integer, Integer> hashMap;
    Map<Integer, Integer> treeMap;
    int[] keys;

    @Setup(Level.Trial)              // once per fork, before warmup
    public void setUp() {
        hashMap = new HashMap<>();
        treeMap = new TreeMap<>();
        Random random = new Random(42);
        keys = new int[1024];
        for (int i = 0; i < size; i++) { hashMap.put(i, i); treeMap.put(i, i); }
        for (int i = 0; i < keys.length; i++) keys[i] = random.nextInt(size);
    }

    @Benchmark
    public void hashLookup(Blackhole bh) {
        for (int k : keys) bh.consume(hashMap.get(k));
    }

    @Benchmark
    public void treeLookup(Blackhole bh) {
        for (int k : keys) bh.consume(treeMap.get(k));
    }
}

Level.Trial runs once per fork, Level.Iteration before each iteration, and Level.Invocation before every call. Level.Invocation adds timer overhead to each call and is meant only for operations that take at least about a millisecond. The keys array spreads lookups across the map, so the benchmark does not measure one cached key.

Example 7: running, profiling, and reading results

A Maven or Gradle JMH build produces benchmarks.jar. Options on the command line override the annotations; -prof gc adds allocation counters.

java -jar target/benchmarks.jar LookupBenchmark -f 2 -wi 5 -i 5 -prof gc
java -jar target/benchmarks.jar -lprof          # list available profilers

Representative result table (not captured here; the numbers illustrate the format):

Benchmark                                    (size)  Mode  Cnt      Score     Error   Units
LookupBenchmark.hashLookup                       16  avgt   10   3120.442 ±  41.207   ns/op
LookupBenchmark.hashLookup                    65536  avgt   10   9871.115 ± 310.884   ns/op
LookupBenchmark.treeLookup                       16  avgt   10   4402.903 ±  52.611   ns/op
LookupBenchmark.treeLookup                    65536  avgt   10  41250.770 ± 902.315   ns/op
LookupBenchmark.hashLookup:gc.alloc.rate.norm    16  avgt   10      0.012 ±   0.001    B/op

How to read it:

• Cnt is forks times measurement iterations. Error is the 99.9% confidence interval. Two scores whose intervals overlap are not shown to differ.
• ns/op is per benchmark call; here one call is 1024 lookups.
• gc.alloc.rate.norm is bytes allocated per operation. A value near 0 means the measured path does not allocate. Here get(k) boxes k; the Integer cache covers -128 to 127, so for larger keys any allocation that escape analysis does not remove shows up in this column.
• Other profilers: -prof stack (sampled hot frames), -prof perfasm (hot assembly, needs Linux perf and hsdis), -prof async (async-profiler, see JFR and async-profiler).

A result describes one JVM, one machine, and one input shape. Benchmarks are compared on the same machine, with the same JDK and flags, and the explanation is confirmed with a profiler before the number is trusted.

Interview points

• Naive timing fails because the measured code runs in several modes (interpreted, C1, C2, OSR) and the JIT may remove or precompute it.
• Dead code elimination removes unused results; JMH returns them or sinks them in a Blackhole.
• Constant folding precomputes constant inputs; JMH reads inputs from @State fields.
• @Fork runs each benchmark in a fresh JVM so profile pollution from other benchmarks does not leak in.
• @Setup(Level.Invocation) adds timer overhead to each call and is meant only for long operations.
• -prof gc reports gc.alloc.rate.norm, the bytes allocated per operation, which is often more stable than the time.
• The Error column is a confidence interval; overlapping intervals mean no shown difference.

Summary

• Warmup iterations let the JIT finish compiling; their results are discarded.
• OSR compiles a loop while it runs and can produce weaker code than a normal compilation.
• @Benchmark methods return their results or use Blackhole.consume.
• @State holds inputs, @Setup prepares them, @Param varies them.
• @BenchmarkMode selects throughput, average time, a sampled distribution, or single-shot cold time.
• JMH code needs jmh-core and the jmh-generator-annprocess annotation processor.