Wird ein JMH-Projekt von der Kommandozeile ohne weitere Parameter gestartet, so werden die Defaultwerte übernommen. Je nachdem, wie lange ein Benchmark dauert, ergibt sich eine unterschiedliche Anzahl an Durchläufen (eine Iteration läuft eine Sekunde lang). Das bedeutet wiederum, dass unklar ist, wann Hotspot-Optimierungen durchgeführt werden. Deshalb ist es sinnvoll, diese Werte zu überprüfen. Dieser Artikel beschreibt einige JMH-Optionen und deren Optimierung in der Praxis.
Anzahl der Warmup-Iterationen
JMH bietet dafür Profiler an. Um sicherzustellen, dass während des Benchmarks keine JIT-Kompilierung durchgeführt wird, können die Statistiken mit Hilfe des Profilers „hs_comp“ untersucht werden.
Hier ein Beispiel für die Ausgabe des Profilers:
Iteration 20: 309496556,530 ops/s ·compiler.nmethodCodeSize: 604,750 Kb ·compiler.nmethodSize: 1013,000 Kb ·compiler.osrBytes: 0,507 Kb ·compiler.osrCompiles: 3,000 methods ·compiler.osrTime: 15,031 ms ·compiler.standardBytes: 48,589 Kb ·compiler.standardCompiles: 579,000 methods ·compiler.standardTime: 393,727 ms ·compiler.totalBailouts: ≈ 0 methods ·compiler.totalCompiles: 582,000 methods ·compiler.totalInvalidates: ≈ 0 methods ·compiler.totalTime: 408,759 ms
Steigen die Werte an, so werden Optimierungen in den Iterationen durchgeführt. Das verfälscht die Testergebnisse. Die Optimierungen sollen in der Warmup-Phase durchgeführt werden. Als Entwickler kann man dafür an den Stellschrauben „-w“ (für die Warmup-Zeit) und „-wi“ (Anzahl der Warmup-Iterationen) drehen.
Problem bei Profilern ist, dass der Profiler erst nach der Warmup-Phase läuft. Deshalb kann der Profiler selbst wieder JIT-Optimierungen verursachen (meine Vermutung, siehe den nächsten Absatz), da jetzt neuer Code ausgeführt wird. Als Alternative zum „hs_comp“-Profiler kann daher das JVM-Flag „-XX:+PrintCompilation“ genutzt werden. Auch damit gelingt es oft nicht vollständig, alle JIT-Kompilierungen in die Warmup-Phase zu verlagern. Mit der Zeit entwickelt sich aber ein Gefühl, wann der Code „aufgewärmt“ ist.
java -jar benchmarks.jar -jvmArgs -XX:+PrintCompilation -f 1 -wi 100
Vermutung: Profiler verursachen JIT-Compilation
Der Benchmark wird gestartet mit:
java -jar target/benchmarks.jar -jvmArgs -XX:+PrintCompilation -f 1 -wi 100 -prof hs_comp
Die Ausgabe (die Ausgabe des Profilers habe ich entfernt) sagt, dass in der ersten Iteration der ObjectOutputStream vom JIT-Compiler betroffen ist:
... # Warmup Iteration 98: 310172820,693 ops/s # Warmup Iteration 99: 99571 756 4 java.util.concurrent.ConcurrentHashMap::get (162 bytes) 311345201,664 ops/s # Warmup Iteration 100: 99574 187 3 java.util.concurrent.ConcurrentHashMap::get (162 bytes) made not entrant 300041258,685 ops/s Iteration 1: 101573 758 3 sun.reflect.ClassFileAssembler::emitInt (46 bytes) 101574 748 ! 4 java.io.ObjectOutputStream::writeObject0 (619 bytes) made not entrant 101574 757 3 sun.reflect.ClassFileAssembler::opc_invokespecial (26 bytes) 101574 469 3 net.modellierung.generated.InliningBenchmark_testBimorphBothTypes_jmhTest::testBimorphBothTypes_thrpt_jmhStub (58 bytes) made zombie 288048392,852 ops/s Iteration 2: 102576 759 ! 3 java.io.ObjectOutputStream::writeObject0 (619 bytes) 288340959,529 ops/s ...
Zum Überprüfen der Vermutung wird derselbe Test nochmal mit 200 Warmup-Iterationen ausgeführt, auch hier taucht der ObjectOutputStream wieder auf:
... # Warmup Iteration 194: 321640659,056 ops/s # Warmup Iteration 195: 303901282,485 ops/s # Warmup Iteration 196: 287955025,384 ops/s # Warmup Iteration 197: 288741152,039 ops/s # Warmup Iteration 198: 288386461,504 ops/s 198626 858 1 java.lang.String::toString (2 bytes) 198626 639 3 java.lang.String::toString (2 bytes) made not entrant # Warmup Iteration 199: 290359354,168 ops/s # Warmup Iteration 200: 315150741,755 ops/s Iteration 1: 201630 755 ! 4 java.io.ObjectStreamClass::lookup (335 bytes) made not entrant 201630 860 3 sun.reflect.ClassFileAssembler::emitInt (46 bytes) 201631 745 ! 4 java.io.ObjectOutputStream::writeObject0 (619 bytes) made not entrant 201631 861 4 java.io.ObjectStreamClass::hasWriteObjectMethod (17 bytes) 321301694,150 ops/s ...
Das ist kein harter Beweis, aber der Verdacht besteht, dass durch „Scharfschalten“ des Profilers nach dem Warmup weitere JIT-Kompilationen verursacht werden. Wenn der Benchmark mit mehreren Threads, die nicht synchonisiert werden, ausgeführt werden, so kann das Ergebnis etwas verfälscht werden. Bei einem Thread bin ich mir nicht sicher, je nachdem, ob die Kompilierung während der Ausführung des „echten Codes“ oder des zusätzlichen Benchmarkcodes abläuft, oder wie der generierte Benchmarkcode die Zeiten summiert, kann es ebenfalls Beeinflussungen geben. Diese sind aber normalerweise nicht signifikant.
Eliminierung von externen Einflüssen
Der Benchmark sollte unter möglichst gleichen Bedingungen wie der Code in Produktion ablaufen. Falls das nicht erreicht werden kann, dann sollte für konstante Bedingungen gesorgt werden.
Bei Ausführung auf dem Entwicklerrechner sollte deshalb die IDE geschlossen werden (Hintergrundindizierung und Codeanalyse!) und, falls der Rechner ein Notebook ist, eine feste CPU-Frequenz vorgegeben werden.
Eliminieren der GC-Effekte
Ein Microbenchmark hilft bei der Performancebeurteilung. Da die GarbageCollection der JVM an jedem Safepoint stattfinden kann, kann dies auch während einer Iteration geschehen, und somit einen Extremwert bei den Durchlaufzeiten verursachen.
Nun gehört zur Bestimmung der Laufzeit des Codes auch das Aufräumen der allokierten Objekte. Es kann aber vorkommen, dass bei dem Vergleich von zwei Benchmarks bei dem einen Benchmark die GC z.B. in der Setup-Phase einer Iteration stattfindet, bei dem anderen Benchmark aber während der Ausführung der Messung. Das schränkt dann die Vergleichbarkeit ein.
Zum einen kann man versuchen, das Problem statistisch zu lösen, mit vielen Iteration und vielen Forks (der -f Parameter von JMH). Weiterhin kann der Speicher der JVM so angepasst (verringert) werden, dass die GarbageCollection häufiger, aber schneller stattfindet. JMH bietet ebenfalls den Parameter „-gc true“ an (im Hilfetext steht „use with care“).