May 29, 2021

all posts ->

Manchmal funktioniert deine App, aber du mochtest die Leistung verbessern, indem du den Durchsatz erhohst oder die Latenz reduzierst. In anderen Fallen mochtest du einfach wissen, wie sich Code zur Laufzeit verhalt, herausfinden, wo die Hotspots sind, oder verstehen, wie ein Framework unter der Haube funktioniert.

Das ist ein perfekter Anwendungsfall fur Profiler. Sie bieten eine Vogelperspektive auf beliebig grosse Ausfuhrungsabschnitte, was hilft, Probleme im grossen Massstab zu erkennen.

Viele Menschen glauben, dass sie nicht lernen mussen, wie man profilt, solange sie keine Hochlast-Anwendungen schreiben. Im Beispiel werden wir sehen, wie wir vom Profiling profitieren konnen, selbst wenn wir mit sehr einfachen Apps arbeiten.

Beispielanwendung

Nehmen wir an, wir haben das folgende Programm:

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.*;
import java.util.concurrent.TimeUnit;

public class CountEvents {

    public static int update(Deque<Long> events, long nanos, long interval) {
        events.add(nanos);
        events.removeIf(aTime -> aTime < nanos - interval);
        return events.size();
    }

    public static void main(String[] args) throws IOException {
        long start = System.nanoTime();
        int total = 100_000;
        long interval = TimeUnit.MILLISECONDS.toNanos(100);
        int[] count = new int[total];

        Deque<Long> collection = new ArrayDeque<>();
        for (int counter = 0; counter < count.length; counter++) {
            count[counter] = update(collection, System.nanoTime(), interval);
            Path p = Paths.get("./a/b");
            Files.createDirectories(p);
        }
        long spent = System.nanoTime() - start;

        //noinspection OptionalGetWithoutIsPresent
        System.out.println("Average count: " + (int) (Arrays.stream(count).average().getAsDouble()) + " op");
        System.out.println("Spent time: " + TimeUnit.NANOSECONDS.toMillis(spent) + " ms");
    }
}

Das Programm versucht wiederholt, einen Pfad im Dateisystem mit createDirectories() aus NIO2 zu erstellen. Dann messen wir den Durchsatz mit einem improvisierten Benchmark.

Jedes Mal, wenn eine Aufgabe ausgefuhrt wird, speichert die Benchmark-Logik den aktuellen Zeitstempel in einer Sammlung und entfernt alle Zeitstempel, die auf eine Zeit fruher als die aktuelle Zeit minus einem bestimmten Intervall zeigen. Dies ermoglicht es herauszufinden, wie viele Ereignisse wahrend dieses Zeitintervalls aufgetreten sind, indem man einfach die Sammlung abfragt. Dieser Benchmark soll uns helfen, die Leistung der createDirectories() -Methode zu bewerten.

Wenn wir das Programm ausfuhren, stellen wir fest, dass die Zahlen verdachtig niedrig sind:

Average count: 6623 op
Spent time: 1462 ms

Lass es uns profilen und sehen, was falsch ist.

Snapshot erstellen

Zuerst mussen wir Profiling-Daten sammeln, die auch als Snapshot bezeichnet werden. In dieser Phase lauft der Profiler neben dem Programm und sammelt Informationen uber seine Aktivitat. Profiler verwenden verschiedene Techniken, um dies zu erreichen, wie das Instrumentieren von Methodenein- und -ausgangen. IntelliJ Profiler macht das, indem er periodisch die Stack-Informationen von allen in der App laufenden Threads sammelt.

Um den Profiler von IntelliJ IDEA anzuhangen, wahle eine Run-Konfiguration, die du normalerweise zum Ausfuhren der Anwendung verwenden wurdest, und wahle Profile aus dem Menu.

Wenn die App fertig ist, erscheint ein Popup, das uns auffordert, den Snapshot zu offnen. Wenn wir das Popup versehentlich schliessen, ist der Snapshot immer noch verfugbar im Profiler Tool-Fenster.

Lass uns den Bericht offnen und sehen, was drin ist.

Snapshot analysieren

Das erste, was wir nach dem Offnen des Berichts sehen, ist das Flame-Graph. Dies ist im Wesentlichen eine Zusammenfassung aller gesammelten Stacks. Je mehr Samples mit demselben Stack der Profiler gesammelt hat, desto breiter wachst dieser Stack im Flame-Graph. Die Breite des Frames entspricht also ungefahr dem Anteil der Zeit, die in diesem Zustand verbracht wurde.

Zu unserer Uberraschung hat die createDirectories() -Methode nicht die meiste Ausfuhrungszeit beansprucht. Unser selbstgebauter Benchmark hat ungefahr die gleiche Zeit zur Ausfuhrung gebraucht!

Wenn wir uns den Frame daruber ansehen, sehen wir ausserdem, dass dies hauptsachlich an der removeIf() -Methode liegt, die fast die gesamte Zeit ihres Aufrufers, update() , ausmacht.

Das muss eindeutig naher untersucht werden.

Benchmark optimieren

Es scheint, als wurde der Code, der fur das Entfernen von Ereignissen aus der Queue verantwortlich ist, zusatzliche Arbeit leisten.

Da wir eine geordnete Sammlung verwenden und Ereignisse in chronologischer Reihenfolge hinzugefugt werden, konnen wir sicher sein, dass alle zu entfernenden Elemente immer am Anfang der Queue sind. Wenn wir removeIf() durch eine Schleife ersetzen, die abbricht, sobald sie uber Ereignisse iteriert, die sie nicht entfernen wird, konnen wir potenziell die Leistung verbessern:

// events.removeIf(aTime -> aTime < nanos - interval);
while (events.peekFirst() < nanos - interval) {
    events.removeFirst();
}

Lass uns den Code andern, dann unsere App erneut profilen und das Ergebnis ansehen:

Der Overhead durch die Benchmark-Logik ist jetzt minimal, wie es sein sollte, und der createDirectories() -Frame nimmt jetzt ungefahr 95% der gesamten Ausfuhrungszeit ein.

Die Verbesserung ist auch in der Konsolenausgabe sichtbar:

Average count: 14788 op
Spent time: 639 ms

Native Profiling

Nachdem wir das Problem im Benchmark gelost haben, konnten wir hier aufhoren und uns selbst auf die Schulter klopfen. Aber was ist mit unserer createDirectories() -Methode los? Ist sie zu langsam?

Es scheint wenig Raum fur Optimierung hier zu geben, da dies eine Bibliotheksmethode ist und wir keine Kontrolle uber ihre Implementierung haben. Trotzdem kann uns der Profiler einen Hinweis geben.

Durch das Aufklappen der eingeklappten Bibliotheks-Frames konnen wir inspizieren, was drinnen passiert.

Dieser Teil des Flame-Graphs zeigt, dass der Hauptbeitrag zur Ausfuhrungszeit von

createDirectories()

sun.nio.fs.UnixNativeDispatcher.mkdir0 ist. Ein grosser Teil dieses Frames hat nichts daruber. Dies wird als Eigenzeit der Methode bezeichnet und zeigt an, dass es uber diesen Punkt hinaus keinen Java-Code gibt. Es konnte jedoch nativen Code geben.

Da wir versuchen, ein Verzeichnis zu erstellen, was den Aufruf der Betriebssystem-API erfordert, konnen wir erwarten, dass die Eigenzeit von mkdir von nativen Aufrufen dominiert wird. UnixNativeDispatcher im Klassennamen scheint das zu bestatigen.

Lass uns natives Profiling in Settings | Build, Execution, Deployment | Java Profiler | Collect native calls aktivieren:

Das erneute Ausfuhren der Anwendung mit aktiviertem nativen Profiling zeigt uns das vollstandige Bild:

Hier ist der Haken. Die Dokumentation fur die createDirectories() -Methode sagt:

Die Beschreibung ist aus Java-Perspektive gultig, da sie keine Java-Exceptions auslost. Jedoch werden beim Versuch, ein Verzeichnis zu erstellen, das bereits existiert, Exceptions auf Betriebssystemebene geworfen. Dies fuhrt in unserem Szenario zu einer erheblichen Ressourcenverschwendung.

Lass uns versuchen, dies zu vermeiden und den Aufruf von createDirectories() in eine Files.exists() -Prufung einzuwickeln:

Path p = Paths.get("./a/b");
if (!Files.exists(p)) {
    Files.createDirectories(p);
}

Das Programm wird blitzschnell!

Average count: 50000 op
Spent time: 87 ms

Es ist jetzt etwa 16-mal schneller als ursprunglich. Diese Exception-Behandlung war wirklich teuer! Die Ergebnisse konnen je nach Hardware und Umgebung variieren, aber sie sollten auf jeden Fall beeindruckend sein.

Snapshot-Diff

Wenn du IntelliJ Profiler verwendest, gibt es ein praktisches Werkzeug, mit dem du zwei Snapshots visuell vergleichen kannst. Fur eine detaillierte Erklarung und Schritte empfehle ich, die Dokumentation zu lesen. Hier ist eine kurze Zusammenfassung der Ergebnisse, die der Diff zeigt:

Frames, die im neueren Snapshot fehlen, sind grun hervorgehoben, wahrend die neuen rot gefarbt sind. Wenn ein Frame mehrere Farben hat, bedeutet das, dass der Frame in beiden Snapshots vorhanden ist, aber seine Gesamtlaufzeit sich geandert hat.

Wie im Screenshot oben sichtbar, war die grosse Mehrheit der Operationen, die ursprunglich von unserem Programm ausgefuhrt wurden, unnotig, und wir konnten sie eliminieren. CountEvents.update() ist komplett grun, was bedeutet, dass unsere erste Anderung zu einer nahezu vollstandigen Verbesserung der Laufzeit der Methode gefuhrt hat. Das Hinzufugen von Files.exists() war keine 100%ige Verbesserung, aber es hat createDirectories() effektiv aus dem Snapshot entfernt und nur 60 ms zur Programmlaufzeit hinzugefugt.

Fazit

In diesem Szenario haben wir einen Profiler verwendet, um ein Leistungsproblem zu erkennen und zu beheben. Wir haben auch gesehen, wie selbst eine bekannte API Auswirkungen haben kann, die die Ausfuhrungszeiten eines Java-Programms ernsthaft beeinflussen. Dies zeigt uns, warum Profiling eine nutzliche Fahigkeit ist, selbst wenn du nicht fur Millionen von Transaktionen pro Sekunde optimierst.

In den kommenden Artikeln werden wir weitere Profiling-Anwendungsfalle und -Techniken betrachten. Bleib dran!

all posts ->

---

• Erstellt von Igor Kulakov. Viel Spaß!
• Duplikatfinder

• Abonnieren

• 
• 
• 
•