Archiv der Kategorie: Performance

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

Der Performance auf der Spur – Teil 2 (Projektbeschreibung)

Herzstück des Beispielprojekts ist eine Klasse namens „Calculator“. Diese führt Berechnungen auf Interfaces durch. Das Interface hat entweder eine Implementierung (für den monomorphen Fall), zwei (bimorph) oder 3 (trimorph oder megamorph).

Der Code von Calculator:

package net.modellierung;

public class Calculator {

    public long add(Monomorph m1, Monomorph m2) {
        return m1.getValue() + m2.getValue();
    }

    public long add(Bimorph b1, Bimorph b2) {
        return b1.getValue() + b2.getValue();
    }

    public long add(Trimorph t1, Trimorph t2) {
        return t1.getValue() + t2.getValue();
    }
}

Die Klassen des Projekts – Interfaces mit einer bestimmten Anzahl von Implementierungen:

Klassendiagramm Performanceprojekt

Die Implementierungen der Interfaces besitzen einen Konstruktor mit einem Long-Parameter. Dieser Wert wird beim Aufruf von getValue() zurückgegeben.

Erwartetes Verhalten des JIT-Compilers ist, dass er im ersten Fall Code generieren kann, der auf die eine Implementierung zugeschnitten ist, und damit den teuren virtuellen Methodenaufruf umgeht. Trotzdem müssen in diesem Fall Instruktionen zur Absicherung des Typs generiert werden, da zur Laufzeit eine weitere Implementierung nachgeladen werden kann. Der kompilierte Code muss das merken und dann eine Deoptimierung durchführen (also wieder den Bytecode ausführen und ggf. neuen Code (der beide Implementierungen berücksichtigt) generieren.
Im zweiten Fall weiß der JIT-Compiler, dass es zwei Implementierungen gibt. Der generierte Code kann aber mit einem Typcheck beide Implementierungen unterscheiden und somit auch den virtuellen Aufruf sparen. Auch hier muss der generierte Code Logik enthalten, um ggf. nachgeladene Implementierungen zu berücksichtigen.
Der dritte Fall soll hingegen nicht optimierbar sein, es müssen also virtuelle Aufrufe stattfinden.

Richard Warburton hat bereits mit einer etwas anderen Fragestellung einen interessanten Artikel geschrieben.

Der Performance auf der Spur – Teil 1

Bei Performanceproblemen von Anwendungen mit niedrigen Latenzzeiten merkt der Entwickler schnell, dass die Java Runtime Environment sehr viele versteckte Dinge macht. Sei es, dass BiasedLocking nach 4 Sekunden plötzlich eingeschaltet wird, oder dass der Just-in-time-Compiler (im folgenden „JITC“ genannt) ein Stück Code optimiert, auf jeden Fall kann es Sprünge in der Performance geben, die auf den ersten Blick nicht erklärbar sind.

An verschiedenen Stellen habe ich gelesen, dass der JITC Interfaces unterschiedlich behandelt. Gibt es nur eine Implementierung (der Classloader kann später ggf. weitere nachladen), dann muss kein Code für Polymorphismus generiert werden, sondern die Methode kann direkt aufgerufen werden.

Da es häufig vorkommt, dass zwei Implementierungen eines Interfaces (oder einer abstrakten Klasse) vorliegen, gibt es dafür auch noch eine Optimierung: Der generierte Code prüft mit „instanceof“, welche der Implementierung vorliegt, und muss dann ebenfalls keinen polymorphen Aufruf machen.

Darüber zu lesen ist eine Sache, es auszuprobieren eine andere. Da der JITC erst nach einigen tausend Aufrufen eine Methode optimiert, habe ich mich für das JMH-Framework entschieden, womit sich sehr einfach Microbenchmarks erstellen lassen.

Die ersten Ergebnisse überraschen:

# Run complete. Total time: 00:02:01

Benchmark                                 Mode  Cnt          Score          Error  Units
InliningBenchmark.testBimorphBothTypes   thrpt   20  318966702,179 ±  8259966,525  ops/s
InliningBenchmark.testBimorphSingleType  thrpt   20  320496503,653 ±  6204071,530  ops/s
InliningBenchmark.testMonomorph          thrpt   20  303301715,877 ± 13156878,442  ops/s

Die Performance mit nur einer Implementierung eines Interfaces ist etwas langsamer als der Test mit 2 Implementierungen.

Hat der JITC hier wirklich optimiert? Sind die JMH-Einstellungen (Warmup-Iterationen, Iterationen etc.) richtig gewählt? Ist der Benchmal fehlerhaft?

Diese Fragen möchte ich in den nächsten Blogposts klären, eine Projektbeschreibung mit Beispielcode wird es ebenfalls geben.