Profiling von zsh-Shell-Skripten

Bei der rasend schnellen Hardware von heute erstaunt mich immer wieder unsere Fähigkeit, Dinge langsam zu machen. Auf meinem System gibt es zum Beispiel eine merkliche Verzögerung zwischen dem Öffnen eines Terminalfensters und dem Moment, in dem die Eingabeaufforderung tatsächlich angezeigt wird. In diesem Beitrag erfahren Sie, wie wir das Problem schnell quantifizieren und die Hauptursachen für die Verzögerung ermitteln können.

Quantifizierung des Problems

Lassen Sie uns zunächst sehen, wo das Problem liegen könnte. Ein wahrscheinlicher Kandidat ist natürlich meine ~/.zshrc, also habe ich 2 Log-Anweisungen hinzugefügt: eine am Anfang und eine am Ende:

Datum "+%s.%N"

Dies zeigte in der Tat, dass meine ~/.zshrc etwa 300ms benötigte, genug, um eine spürbare Verzögerung zu verursachen.

Schneller Einblick: zprof

Der schnellste Weg, sich ein Bild von dem Übeltäter zu machen, ist das zprof-Modul, das mit zsh geliefert wird. Fügen Sie einfach zmodload zsh/zprof am Anfang Ihrer ~/.zshrc ein, und der eingebaute Befehl zprof zeigt eine gprof-ähnliche Zusammenfassung der Profildaten an. Ein bemerkenswerter Unterschied zwischen gprof und zprof besteht darin, dass gprof die CPU-Zeit misst, während zprof die Wanduhrzeit misst. Das ist ein Glücksfall: Die CPU-Zeit ist die Zeit, in der ein Programm tatsächlich CPU-Zyklen verbraucht hat, und schließt die Zeit aus, in der das Programm zum Beispiel auf E/A gewartet hat. Es wäre ziemlich nutzlos, ein Profil von zsh auf diese Weise zu erstellen, da es wahrscheinlich die meiste Zeit damit verbringt, auf die Rückkehr von aufgerufenen Befehlen zu warten. zprof bietet eine ziemlich umfangreiche Ausgabe, einschließlich Informationen über die Aufrufhierarchie zwischen Funktionen. Leider wird die Leistung pro Funktion gemessen, so dass Sie sich bei langen Funktionen immer noch fragen müssen, welche Zeile so lange gebraucht hat.

Tiefer gehend: xtrace

Ein Ansatz für das Profiling von zsh-Skripten, der Metriken pro Zeile liefert, ist die Verwendung von xtrace. Mit xtrace wird jeder Befehl, den zsh ausführt, auch in den Dateideskriptor 3 gedruckt, und zwar unter Verwendung einer speziellen Eingabeaufforderung, die mit der Umgebungsvariablen PS4 so angepasst werden kann, dass sie Dinge wie den aktuellen Zeitstempel enthält. Wir können diese detaillierten Statistiken sammeln, indem wir sie oben in unsere ~/.zshrc einfügen:

PS4=$'\11%D{%s%6.}11%x11%I11%N11%e11'
Ausführung 3>&2 2>/tmp/zshstart.$$.log
setopt xtrace prompt_subst

Und nach unten:

unsetopt xtrace
Ausführung 2>&3 3>&-

Es gibt 2 Probleme mit dieser detaillierten Rückverfolgung:

• Dieser Ansatz liefert verwirrende Ergebnisse, wenn Parallelität im Spiel ist: Trace-Nachrichten von verschiedenen Threads der Ausführung werden einfach verschachtelt.
• Es ist eine überwältigende Menge an Daten, die schwer zu verdauen ist

Wenn Sie es mit Parallelität zu tun haben, können Sie vielleicht zuerst zprof verwenden und dann nur die Funktion xtracen, von der Sie wissen, dass sie einen Engpass darstellt. Wenn Sie von der Datenmenge überwältigt sind, lesen Sie weiter...

Visualisierung: kcachegrind

Wenn wir davon ausgehen, dass keine Parallelität vorliegt, können wir unser zsh-Skriptprofil mit kcachegrind visualisieren. Dieses Tool ist für die Visualisierung der Aufrufdiagramme gedacht, die vom Tool callgrind von valgrind erzeugt werden. Da das verwendete Dateiformat jedoch recht einfach ist, können wir ein kleines Tool schreiben, das unsere xtrace-Ausgabe konvertiert.

Zusammenfassung

zprof ist die einfachste und zuverlässigste Methode, um ein Profil eines zsh-Skripts zu erstellen. Ein benutzerdefinierter Kleber kombiniert mehrere vorhandene Tools (xtrace von zsh und kcachegrind), um einen tiefgreifenden Einblick zu erhalten. Dies auf die Startzeit der Shell anzuwenden, ist natürlich eine ziemlich dumme Übung - obwohl ich mit dem Ergebnis recht zufrieden bin: Ich bin von ~300ms auf ~70ms gekommen (die ich jetzt hauptsächlich für die Autovervollständigungsfunktionen verwende, die es wert sind). Die wichtigste Lektion: Die Kombination von Tools, die ursprünglich nicht für die gemeinsame Verwendung gedacht waren, kann mächtige Ergebnisse liefern.

Referenzen:

• profiling-zsh-startup-time hat mir gezeigt, wie ich %D{%.} verwenden kann, um Zeitstempel zu erhalten, ohne den Overhead des Aufrufs von 'date' zu verursachen
• die freundlichen Leute in #zsh auf freenode haben mich auf das zsh/zprof Plugin hingewiesen