Odd decrease of benchmark throughput

Dávid Karnok akarnokd at gmail.com
Tue Sep 6 10:05:23 UTC 2016


I've been benchmarking some code changes and I found an odd throughput
profile:

https://github.com/akarnokd/RxJava/blob/MacroFuseBack/src/perf/java/io/reactivex/ToFlowablePerf.java

The code benchmarked is single threaded and completely synchronous.

# JMH 1.13 (released 45 days ago)
# VM version: JDK 1.8.0_102, VM 25.102-b14
# VM invoker: C:\Program Files\Java\jdk1.8.0_102\jre\bin\java.exe
# VM options: -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -Xmx512m
-Dfile.encoding=windows-1250 -Duser.country=HU -Duser.language=hu
-Duser.variant
# Warmup: 5 iterations, 1 s each
# Measurement: 5 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: io.reactivex.ToFlowablePerf.flowable
# Parameters: (times = 1000000)

# Run progress: 16,67% complete, ETA 00:01:47
# Fork: 1 of 1
# Warmup Iteration   1: 622,250 ops/s
# Warmup Iteration   2: 646,154 ops/s
# Warmup Iteration   3: 637,035 ops/s
# Warmup Iteration   4: 639,014 ops/s
# Warmup Iteration   5: 645,212 ops/s
Iteration   1: 648,120 ops/s
Iteration   2: 647,042 ops/s
Iteration   3: 650,176 ops/s
Iteration   4: 335,979 ops/s
Iteration   5: 195,415 ops/s


Result "flowable":
  495,346 �(99.9%) 829,634 ops/s [Average]
  (min, avg, max) = (195,415, 495,346, 650,176), stdev = 215,453
  CI (99.9%): [? 0, 1324,981] (assumes normal distribution)

It starts out nice then drops to 1/3. I've run LogCompilation and
PrintAssembly:

https://gist.github.com/akarnokd/629f4b4f0e384dfefdfa11e3d972c4f6

and it seems the throughput drop happens the moment C2 compiles
the ToFlowablePerf.flowable() method at last. If I run up to 90 iteration,
the number stays around 195 ops/s.

Running FlightRecorder along doesn't indicate any GC activity and there
should be only minimal garbage.

The rest of the benchmark doesn't exhibit this wild jumps:

Benchmark                       (times)   Mode  Cnt         Score
 Error  Units
ToFlowablePerf.flowable               1  thrpt    5  18898985,162 �
406247,396  ops/s
ToFlowablePerf.flowable            1000  thrpt    5    537046,181 �
6422,190  ops/s
ToFlowablePerf.flowable         1000000  thrpt    5       495,346 �
 829,634  ops/s
ToFlowablePerf.flowableInner          1  thrpt    5   5929002,117 �
186151,492  ops/s
ToFlowablePerf.flowableInner       1000  thrpt    5      4726,420 �
 442,621  ops/s
ToFlowablePerf.flowableInner    1000000  thrpt    5         4,620 �
 0,444  ops/s
ToFlowablePerf.observable             1  thrpt    5  18840902,427 �
203311,147  ops/s
ToFlowablePerf.observable          1000  thrpt    5    400928,054 �
 19985,975  ops/s
ToFlowablePerf.observable       1000000  thrpt    5       446,110 �
 7,270  ops/s
ToFlowablePerf.observableInner        1  thrpt    5   4900112,825 �
139406,631  ops/s
ToFlowablePerf.observableInner     1000  thrpt    5      5151,550 �
 218,203  ops/s
ToFlowablePerf.observableInner  1000000  thrpt    5         4,845 �
 0,063  ops/s


(Running Windows 7 x64, Java 8u102, i7 4790)

Please advise.
-- 
Best regards,
David Karnok


More information about the jmh-dev mailing list