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

[Сергей Цыпанов]

Hello Valentin,

pay attention to

1) as mentioned in JavaDoc method Thread::sleep "Causes the currently executing thread to sleep (temporarily cease execution) for the specified number of milliseconds, subject to the precision and accuracy of system timers and schedulers".

2) wLock.lock() is not aquired right at the moment benchmark method is called, as first you call s.rwLock.writeLock()

I assume these are the reasons for slight inaccuracy in numbers: inaccuracy brought in by system timers and schedulers and inaccuracy from the source code.

 

21.05.2019, 05:06, "Valentin Kovalenko" <valentin.male.kovalenko at gmail.com>:
> 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>