JMH measurement problem for a specific case (impossible throughput results; no respect to the iteration duration limit)

[Valentin Kovalenko]

I know I discredited myself with the message
https://mail.openjdk.java.net/pipermail/jmh-dev/2019-February/002813.html,
but the situation I am facing right now seems to be extremely
straightforward, and yet JMH measurements and behaviour does not seem to be
correct.

//see the complete benchmark here
https://github.com/stIncMale/sandbox/blob/c781f7c9fa8a0cc434cbff0d9460d4c569610f0d/benchmarks/src/test/java/stincmale/sandbox/benchmarks/TmpTest.java#L152
(no
3rd party dependencies this time :)
@Benchmark
public final void writeLockSleep(final BenchmarkState s) throws
InterruptedException {//BenchmarkState is Scope.Benchmark
  final ReentrantReadWriteLock.WriteLock wLock = s.rwLock.writeLock();
  wLock.lock();
  try {
    Thread.sleep(1000);
  } finally {
    wLock.unlock();
  }
}

Since the write lock is shared between all benchmark threads
(BenchmarkState is annotated with @Scope.Benchmark) the throughput of this
benchmark can't be greater than 1 ops/s. However, not according to JMH:

# JMH version: 1.21
# VM version: JDK 12, OpenJDK 64-Bit Server VM, 12+33
# VM invoker:
/Library/Java/JavaVirtualMachines/jdk-12.jdk/Contents/Home/bin/java
# VM options: -Xfuture --illegal-access=deny -Xms1024m -Xmx1024m
# Warmup: <none>
# Measurement: 2 iterations, 1000 ms each
# Timeout: 1000000000 ms per iteration
# Threads: 2 threads, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: stincmale.sandbox.benchmarks.TmpTest.writeLockSleep
# Run progress: 66.67% complete, ETA 00:00:07
# Fork: 1 of 1
Iteration   1: 1.327 ops/s
Iteration   2: 1.331 ops/s

These results can't be correct, so I hooked up to JMH lifecycle via
@Setup(Level.Iteration)/@TearDown(Level.Iteration) methods. This way I can
count the number of operations and measure the iteration duration (I
understand that measuring duration between the end of a
@Setup(Level.Iteration) method and the beginning of the
@TearDown(Level.Iteration) method overestimates the duration measured by
JMH). Here are the results:

# JMH version: 1.21
# VM version: JDK 12, OpenJDK 64-Bit Server VM, 12+33
# VM invoker:
/Library/Java/JavaVirtualMachines/jdk-12.jdk/Contents/Home/bin/java
# VM options: -Xfuture --illegal-access=deny -Xms1024m -Xmx1024m
# Warmup: <none>
# Measurement: 2 iterations, 1000 ms each
# Timeout: 1000000000 ms per iteration
# Threads: 2 threads, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: stincmale.sandbox.benchmarks.TmpTest.writeLockSleep
# Run progress: 66.67% complete, ETA 00:00:06
# Fork: 1 of 1
Iteration   1:
# non-JMH: throughput 0.995 ops/s (4 ops / 4.020 s)
1.326 ops/s
Iteration   2:
# non-JMH: throughput 0.998 ops/s (13 ops / 13.031 s)
1.081 ops/s

We can see that the estimated throughput (# non-JMH) is fine, while the
values measured by JMH are again higher than 1 ops/s. Besides, JMH did not
respect the 1000 ms iteration duration limit and made 13 operations
spending more than 13 s for the second iteration.

Here are some other behaviours most likely caused by the same (unknown to
me) root cause that causes the aforementioned behaviour:
- If we comment out @Setup(Level.Iteration)/@TearDown(Level.Iteration)
methods and stop counting operations manually, the writeLockSleep benchmark
may sometimes take minutes before it stops. This is the behaviour that
initially made me think that something is wrong here. Interestingly, the
benchmark that uses a Java monitor via synchronized block instead of a
write lock always (in my experiments) finishes in a sane amount of time but
still produces impossible throughput results.
- If we run the benchmark with 1 thread, the measurements are correct.
- Changing the duration of the Thread.sleep in the benchmark to 100ms
instead of 1000ms does not qualitatively change JMH results. So it does not
matter whether the actual benchmark latency is greater than the iteration
duration limit, or several times smaller than that.

It seems that either JMH does not account for some operations in an
iteration, or incorrectly measures the iteration duration.

Valentin
[image: LinkedIn] <https://www.linkedin.com/in/stIncMale>   [image: GitHub]
<https://github.com/stIncMale>   [image: YouTube]
<https://www.youtube.com/user/stIncMale>