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

[Valentin Kovalenko]

Hi Сергей,

1) While it's true that the Thread.sleep wall-clock duration is subject to
the precision, accuracy and scheduling, it does not matter in a situation
when both Thread.sleep duration and JMH measurements are done using the
same clock. Unless, of course, this clock regularly jumps backwards during
the benchmark at an inconvenient moment, which can't be the case.
2) This is not an inaccuracy in the code:
  a) the actions inside lock/unlock block can't be executed concurrently;
  b) the actions inside lock/unlock block (mostly Thread.sleep) take at
least 1 second.
So provably, the throughput of the critical section inside the method is
less than or equal to 1 ops/s, and any other actions before or after the
critical section can only decrease it further.

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


On Tue, 21 May 2019 at 02:21, Сергей Цыпанов <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>
>