Wie schnell läuft das?

Die Tücken bei der Performancemessung [Java-Trickkiste]

Arno Haase

© Software & Suport Media

„Ausprobieren“ ist ein verbreitetes Verfahren, um zu überprüfen, wie viel Zeit ein verdächtiges Stück Code tatsächlich benötigt. Dabei kann aber überraschend viel schiefgehen … Vor einiger Zeit arbeitete ich an einer Messaging-Middleware mit. Dort wurden viele UUIDs erzeugt, und das Profiling deutete darauf hin, dass Aufrufe von UUID.randomUUID() spürbaren negativen Einfluss auf die Gesamtperformance hatten.

Ein ad hoc durchgeführter Minimaltest (Listing 1) ließ uns den Schreck in die Glieder fahren: Das Erzeugen einer einzigen UUID dauert 10 Millisekunden – indiskutabel lange. Dazu ein Hinweis: Hier und im Folgenden erscheinen gemessene Zeiten. Diese sind erstens mit großer Vorsicht zu genießen – darum geht es ja gerade – und außerdem spezifisch für einen konkreten Computer, auf dem sie erfasst wurden. Sie können also höchstens grobe Anhaltspunkte sein. Im Sinne der Lesbarkeit verzichte ich aber darauf, das bei jedem einzelnen Messwert zu wiederholen.

final long start = System.nanoTime();
UUID.randomUUID();
System.out.println(System.nanoTime() - start);


Steigen wir also in die Welt der Mikrobenchmarks ein. Es gibt fertige Frameworks, die einem hier viel Arbeit abnehmen können, aber betrachten wir einmal die Schwierigkeiten bei der Performancemessung im Kleinen.

Wenn wir vor der Messung ein paar andere UUIDs erzeugen (Listing 2), erhalten wir erheblich kürzere Zeiten. Schon für n=1 sind es nur noch etwa 25 µs. Offenbar passieren beim ersten Aufruf teure Initialisierungen, die nur dort zu Buche schlagen. Außerdem wird schon beim ersten Aufruf der Hotspot-Compiler aktiv, wie man mit dem JVM-Schalter -XX:+PrintCompile sehen kann: Er kompiliert vier interne Methoden, die ab der zweiten UUID entsprechend schneller laufen. Das zeigt, wie eine naive Einmalmessung im Wesentlichen keinen Aussagewert hat. Ein Vergrößern des Wertes von n führt zu schrittweise kürzeren Messzeiten, weil Hotspot nach und nach immer mehr interne Methoden kompiliert.

for(int i=0; i<n; i++)
  UUID.randomUUID();
final long start = System.nanoTime();
UUID.randomUUID();
System.out.println(System.nanoTime() - start);


Hotspot

Für die Praxis ist oft interessant, wie lange ein Aufruf dauert, nachdem der Hotspot-Compiler ihn komplett kompiliert hat (Tipp: Ein Video über HotSpot-Schalter von Arno Haase findet sich auch hier auf JAXenter). Auf meiner Maschine tut er das per Default nach 10 000 Aufrufen. Und tatsächlich, die Ausgaben von -XX:+PrintCompile zeigen für n=10 000, dass UUID.randomUUID() selbst kompiliert wird. Zunächst verlangsamt das allerdings die Ausführung etwas, weil das Kompilieren Zeit benötigt. Bei n=1 000 000 ist allerdings schon lange ein stabiler Wert erreicht, und das Erzeugen einer UUID dauert jetzt 6,7 µs. Ist dieser Wert also „die Wahrheit“?

Zunächst einmal ist es eine gute Idee, den Messwert über viele Aufrufe zu mitteln (Listing 3), alleine schon, weil die Messung dadurch weniger anfällig für Umwelteinflüsse wird.

for(int i=0; i<1_000_000; i++)
  UUID.randomUUID();
final long start = System.nanoTime();
for(int i=0; i<100_000; i++) 
  UUID.randomUUID();
final long end = System.nanoTime();
System.out.println((end – start) / 100_000);



Aber hoppla – jetzt dauert das Erzeugen einer UUID im Mittel nur noch 2,2 µs – nur noch etwa ein Drittel von vorher.

Die Ausgaben von -XX:+PrintCompile zeigen den Grund: Jetzt wird auch der Aufruf von UUID.randomUUID() von Hotspot kompiliert. Listing 2 rief die Methode ja während der Messung nur ein einziges Mal auf, sodass die JVM diesen Aufruf ausgeführt hat, ohne ihn irgendwie zu optimieren. Und das Ausführen von interpretiertem Code braucht eben seine Zeit. Auf Ebene der JVM haben wir damit erst einmal das Ende der Einflussfaktoren erreicht.

Betriebssystem

Moderne CPUs haben variable Taktfrequenzen, und die Betriebssysteme ändern diese je nach Last. Das gilt besonders für Laptops und Desktoprechner, also die typischen Umgebungen, in denen Entwickler ihre Ad-hoc-Tests ausführen. Das Verhalten hängt natürlich von der verwendeten Hardware und dem Betriebssystem sowie seiner Konfiguration ab. Eine gute Faustregel ist, im Mess-Thread vor Beginn der Messung Last zu erzeugen, damit das Betriebssystem zumindest die eine verwendete CPU hochtaktet – wie es ja auch in einem System unter Last der Fall ist.

Außerdem hat es (auf meiner Maschine und allgemein auf vielen modernen Multicore-CPUs) Auswirkungen auf die Performance, ob weitere Threads laufen oder nicht. Und zwar auch dann, wenn die Zahl der Threads kleiner ist als die Zahl der Prozessorkerne.

Erzeugen wir also einmal ein halbwegs typisches Lastszenario. Dazu starten wir vor Beginn der Messung bei x Prozessorkernen x-2 Hintergrundthreads, die einfach CPU-Last erzeugen (Listing 4).

final int numProcessors = Runtime.getRuntime().availableProcessors();
for(int i=0; i < numProcessors-2; i++) {
  new Thread() {
    @Override public void run() {
      while(true) {
        new Random().nextGaussian();
      }
    }
  }.start();
}



Jeder dieser Threads lastet einen Core voll aus. Ein weiterer Core wird von der Messung belegt, und ein Core steht für Hintergrundaktivitäten von JVM und Betriebssystem zur Verfügung. Wir wollen zwar Last erzeugen, dabei aber die Messung nicht unterbrechen. Bei dieser Hintergrundlast dauert das Erzeugen einer UUID 3,4 µs, etwa 50 Prozent mehr als ohne die Hintergrundlast. Das liegt einfach daran, dass meine CPU intern einen Kern um 50 Prozent übertaktet („Turbo-Boost“), wenn nur ein Kern Arbeit hat. Und das sollte sie für realistische Vergleichszahlen mit einem laufenden Serversystem nicht tun.

Multi-Threading

Eine echte Überraschung gibt es, wenn man Listing 4 so ändert, dass die Hintergrundthreads auch UUIDs erzeugen, statt andere prozessorlastige Dinge zu tun. Dann dauert nämlich in der Messung das Erzeugen einer UUID zwischen 25 µs und 30 µs, etwa einen Faktor sieben länger als ohne die Hintergrundthreads. Oder anders gesagt: Das Erzeugen der UUIDs wird offenbar praktisch nicht parallelisiert – meine CPU hat acht Cores, es laufen also sechs Hintergrundthreads, und wenn diese insgesamt sieben Threads die Methode aufrufen, dauert jeder Aufruf im Mittel sieben Mal so lange. Und tatsächlich, die Methode SecureRandom.nextBytes(), die fast die ganze Arbeit erledigt, ist synchronized.

Fazit

Was ist also die Wahrheit, wie lange dauert das Erzeugen einer UUID? Das hängt vom konkreten System ab. Wie häufig kollidieren Aufrufe aus verschiedenen Threads? Wie viel Last hat der Server typischerweise? Mikrobenchmarks sind jedenfalls überraschend komplex, die Tücke liegt im Detail, und sie sind im Allgemeinen kein Ersatz für Lasttests mit Messungen in einer realistischen Umgebung.

Bei der eingangs erwähnten Messaging-Middleware haben wir jedenfalls in Lasttests verifiziert, dass die Antwortzeiten mit einer selbst implementierten eindeutigen ID messbar besser wurden, und uns dann für diese entschieden.

Im letzten Teil der Kolumne ging es übrigens um Checked und Unchecked Exceptions – zu finden hier auf JAXenter.

Geschrieben von
Arno Haase
Arno Haase
Arno Haase ist freiberuflicher Softwareentwickler. Er programmiert Java aus Leidenschaft, arbeitet aber auch als Architekt, Coach und Berater. Seine Schwerpunkte sind modellgetriebene Softwareentwicklung, Persistenzlösungen mit oder ohne relationaler Datenbank und nebenläufige und verteilte Systeme. Arno spricht regelmäßig auf Konferenzen und ist Autor von Fachartikeln und Büchern. Er lebt mit seiner Frau und seinen drei Kindern in Braunschweig.
Kommentare

Hinterlasse einen Kommentar

Hinterlasse den ersten Kommentar!

avatar
400
  Subscribe  
Benachrichtige mich zu: