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

[Kodewerk]

Hi Valentin,

Thread::sleep will temporaily suspend a thread. The thread will not restart until the time has expired. However it may not run until it is sheduled to do so.

Kind regards,
Kirk


> On May 21, 2019, at 5:21 PM, Сергей Цыпанов <sergei.tsypanov at yandex.ru> wrote:
> 
> 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>