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