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

[Valentin Kovalenko]

Alexey, thanks for the reply.
I am surprised to learn that JMH calculates throughput the way you
described. And of course, it's easy to achieve surprising results this way.

There are probably reasons why it was chosen not to use the biggest (among
all workers) measured local iteration duration when calculating local
throughputs. Could you please share those reasons? Actually, if the biggest
local iteration duration were used to calculate local throughputs, it would
be equivalent to summing up all the local ops and dividing them by this
biggest iteration duration. With such an approach JMH could have
underestimated the throughput, but it would never overestimated it. To me,
overestimation of throughput seems incorrect, while underestimation is just
a "benchmark infrastructure overhead". What do you think about it?

Also, thanks for explaining why exactly the benchmark may "hang" for much
longer than the iteration duration limit. I did not know that when sync
iterations option is enabled, all workers continue to execute operations
until the last of them discovers that the iteration should stop (e.g. by
finally finishing executing an operation that it started executing at the
very beginning of the iteration, but have not had a chance to finish for a
long time since then). Interestingly, this behaviour is explained in the
SyncIterations example
https://hg.openjdk.java.net/code-tools/jmh/file/99d7b73cf1e3/jmh-samples/src/main/java/org/openjdk/jmh/samples/JMHSample_17_SyncIterations.java,
so no excuses for me.

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

> ...
> $ java -jar jmh-samples/target/benchmarks.jar TmpTest.writeLock -t 2 -f 1
> -w 1s -r 10s -si false
> # JMH version: 1.22-SNAPSHOT
> # VM version: JDK 1.8.0_212, OpenJDK 64-Bit Server VM, 25.212-b03
> # VM invoker:
> /home/shade/.sdkman/candidates/java/8.0.212.hs-adpt/jre/bin/java
> # VM options: <none>
> # Warmup: 5 iterations, 1 s each
> # Measurement: 5 iterations, 10 s each
> # Timeout: 10 min per iteration
> # Threads: 2 threads, ***WARNING: Synchronize iterations are disabled!***
> # Benchmark mode: Throughput, ops/time
> # Benchmark: org.openjdk.jmh.samples.TmpTest.writeLockSleep
>
> # Run progress: 0.00% complete, ETA 00:00:55
> # Fork: 1 of 1
> # Warmup Iteration   1:
> Thread[org.openjdk.jmh.samples.TmpTest.writeLockSleep-jmh-worker-1,5,main]
> Raw Results: allOps=1,
> measuredOps=1, time=2000
> Thread[org.openjdk.jmh.samples.TmpTest.writeLockSleep-jmh-worker-2,5,main]
> Raw Results: allOps=1,
> measuredOps=1, time=1000
> 1.500 ops/s
>
> See what happened here? Second thread did do 1 measured invocation and
> spent 1000ms there, got
> termination signal and exited the measurement. Once it did, first thread
> was able to acquire the
> lock, do its own operation (sleep), and that took 2000ms (both for waiting
> the lock acquisition and
> its own op). The overall throughput is (1 / 2000ms) = 0.5 ops/sec from 1
> thread, and (1 / 1000ms) =
> 1 ops/sec from the second thread, yielding the proper total.
>
> The pitfall in this experiment is relativity in termination protocol: you
> might think the throughput
> should be 1 ops/sec, because iteration "stops" momentarily in all threads,
> but that premise is
> incorrect. All threads react to termination at different times.
> ...
>
> -Aleksey
>
>