How JMH measures execution time below granularity value?

Question

So I'm trying to play a bit with microbenchmarks, have chosen JMH, have read some articles. How JMH measures execution of methods below system's timer granularity?

A more detailed explanation:

These are the benchmarks I'm running (method names speak for themselves):

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

import java.util.concurrent.TimeUnit;

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@State(Scope.Thread)
@Warmup(iterations = 10, time = 200, timeUnit = TimeUnit.NANOSECONDS)
@Measurement(iterations = 20, time = 200, timeUnit = TimeUnit.NANOSECONDS)
public class RandomBenchmark {

    public long lastValue;

    @Benchmark
    @Fork(1)
    public void blankMethod() {
    }

    @Benchmark
    @Fork(1)
    public void simpleMethod(Blackhole blackhole) {
        int i = 0;
        blackhole.consume(i++);
    }

    @Benchmark
    @Fork(1)
    public void granularityMethod(Blackhole blackhole) {
        long initialTime = System.nanoTime();
        long measuredTime;
        do {
            measuredTime = System.nanoTime();
        } while (measuredTime == initialTime);
        blackhole.consume(measuredTime);
    }
}

Here are results:

# Run complete. Total time: 00:00:02

Benchmark                          Mode  Cnt    Score    Error  Units
RandomBenchmark.blankMethod        avgt   20    0,887 ?  0,274  ns/op
RandomBenchmark.granularityMethod  avgt   20  407,002 ? 26,297  ns/op
RandomBenchmark.simpleMethod       avgt   20    6,979 ?  0,743  ns/op

Currently ran on Windows 7 and as it's described in various articles it has big granularity (407 ns). Checking with basic code below it's indeed new timer value comes every ~400ns:

    final int sampleSize = 100;
    long[] timeMarks = new long[sampleSize];
    for (int i=0; i < sampleSize; i++) {
        timeMarks[i] = System.nanoTime();
    }
    for (long timeMark : timeMarks) {
        System.out.println(timeMark);
    }

It's hard to fully understand how generated methods exactly work but looking through decompiled JMH generated code it seems like it's using the same System.nanoTime() before and after execution and measures the difference. How is it able to measure method execution of couple nanoseconds while granularity is 400 ns?

Wyler

If it doesn't iterate over the measured method sufficently many times, then you got me. – Halmahera

Probably by averaging over a number of samples? – Emersen

yeah, that's obvious idea, but maybe there's some other trick, considering nanoTime() is intrinsic. – Wyler

Answer 1

You are totally right. You cannot measure something that is faster than your system's timer granularity.

JMH doesn't measure each invocation of the bechmark method. It calls System.nanotime() before the start of an iteration, executes the benchmark method X times and call System.nanotime() again after the iteration. The results is then time difference / # of operations (potentially you specify on the method more than 1 operation per invocation with @OperationsPerInvocation).

Aleksey Shipilev discussed measurement problems with Nanotime in his article Nanotrusting the Nanotime. Section 'Latency' contains a code example that shows how JMH measures one benchmark iteration.

Compony

Shipilev's blog could also be useful for you: shipilev.net. Watch some presentations to learn more about JMH and about problems you will face while creating a good benchmark. – Compony