Archiv für den Monat: März 2017

Benutzung und Tuning von JMH

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“).