Beyond cProfile: Die Wahl des richtigen Tools zur Leistungsoptimierung

Hinweis: Dieser Artikel basiert auf einem Vortrag, den ich auf der PyGotham 2019 gehalten habe. Sie können sich das Video hier ansehen.

Ihr Python-Programm ist zu langsam.Vielleicht kann Ihre Webanwendung nicht mithalten, oder bestimmte Abfragen dauern sehr lange.Vielleicht haben Sie ein Batch-Programm, das Stunden oder sogar Tage braucht, um zu laufen.

Wie können Sie es beschleunigen?

Der grundlegende Prozess, den Sie wahrscheinlich befolgen werden, ist:

1. Wählen Sie das richtige Tool zur Geschwindigkeitsmessung.
2. Nutzen Sie das Tool, um den Engpass herauszufinden.
3. Den Engpass beheben.

Dieser Artikel konzentriert sich auf den ersten Schritt: die Wahl des richtigen Werkzeugs und behandelt insbesondere:

• cProfile: Der deterministische Profiler der Python-Standardbibliothek.
• Pyinstrument: Ein Sampling-Profiler.
• Eliot: Eine Logging-Bibliothek.

Ich werde nicht allzu sehr ins Detail gehen, wie man diese Werkzeuge benutzt, denn das Ziel ist es, Ihnen bei der Auswahl des richtigen Werkzeugs zu helfen. Aber ich werde erklären, was diese Werkzeuge tun und wann und warum Sie eines dem anderen vorziehen sollten.

cProfile: Ein deterministischer Profiler

Der cProfile-Profiler ist in Python integriert, also haben Sie wahrscheinlich schon davon gehört, und es ist vielleicht das Standardwerkzeug, das Sie verwenden.cProfile arbeitet, indem es jeden Funktionsaufruf in einem Programm verfolgt.

Deshalb ist es ein deterministischer Profiler: Wenn Sie es mit den gleichen Eingaben ausführen, wird es die gleiche Ausgabe liefern.

Standardmäßig misst cProfile die Prozess-CPU – wie viel CPU Ihr Prozess bisher verbraucht hat.Sie sollten sich immer fragen, was Ihr Profiler misst, denn verschiedene Messungen können verschiedene Probleme aufdecken.

Das Messen der CPU bedeutet, dass Sie Langsamkeit, die durch andere Ursachen verursacht wird, wie das Warten auf eine Antwort von einer Datenbankabfrage, nicht erkennen können.

Während cProfile immer in Ihrer Python-Installation verfügbar ist, hat es auch einige Probleme – und wie Sie sehen werden, wollen Sie es meistens nicht benutzen.

CProfile benutzen

CProfile zu benutzen ist ziemlich einfach.Wenn Sie ein Skript haben, das Sie normalerweise direkt wie folgt ausführen:

$ python benchmark.py7855 messages/sec

Dann können Sie einfach python -m cProfile voranstellen, um es unter dem Profiler auszuführen:

Es gibt auch eine Python-Profiling-API, so dass Sie bestimmte Funktionen in einer Python-Interpreter-Eingabeaufforderung oder einem Jupyter-Notebook profilieren können.

Das Ausgabeformat ist eine Tabelle, die nicht ideal ist: Jede Zeile ist ein Funktionsaufruf, der während der profilierten Zeitspanne ausgeführt wurde, aber man weiß nicht, wie dieser Funktionsaufruf mit anderen Funktionsaufrufen zusammenhängt.Wenn Sie also eine Funktion haben, die von mehreren Codepfaden aus erreicht werden kann, kann es schwierig sein, herauszufinden, welcher Codepfad für den Aufruf der langsamen Funktion verantwortlich war.

Was cProfile Ihnen sagen kann

Wenn Sie sich die obige Tabelle ansehen, können Sie sehen, dass:

• _output.py(__call__) 50.000 Mal aufgerufen wurde. Dies ist eine gerade Zahl, da es sich um ein Benchmark-Skript handelt, das denselben Code in einer Schleife 10.000 Mal ausführt. Wenn Sie eine Funktion nicht absichtlich oft aufrufen, kann dies nützlich sein, um eine hohe Anzahl von Aufrufen zu erkennen, um ausgelastete innere Schleifen zu identifizieren.
• _output.py(send) verbrauchte 0,618 CPU-Sekunden (einschließlich CPU-Zeit der aufgerufenen Funktionen) und 0,045 CPU-Sekunden (ohne die aufgerufenen Funktionen).

Mit diesen Informationen können Sie langsame Funktionen aufspüren, die Sie optimieren können – jedenfalls, was die CPU angeht.

Wie es funktioniert

cProfile misst jeden einzelnen Funktionsaufruf, insbesondere wird jeder Funktionsaufruf im Lauf wie folgt verpackt:

start = process_time()try: f()finally: elapsed = process_time() - start

Der Profiler zeichnet die CPU-Zeit am Anfang und am Ende auf, und die Differenz wird dem Konto der jeweiligen Funktion zugewiesen.

Die Probleme mit cProfile

Während cProfile immer in jeder Python-Installation verfügbar ist, leidet es auch unter einigen signifikanten Problemen.

Problem Nr. 1: Hoher Overhead und verfälschte Ergebnisse

Wie Sie sich vorstellen können, hat jeder Funktionsaufruf zusätzliche Kosten:

$ python benchmark.py7855 messages/sec$ python -m cProfile benchmark.py5264 messages/sec... cProfile output ...

Beachten Sie, wie viel langsamer der cProfile-Lauf ist.Und was noch schlimmer ist, die Verlangsamung ist nicht gleichmäßig über das gesamte Programm verteilt: da sie an die Anzahl der Funktionsaufrufe gebunden ist, werden Teile des Codes mit mehr Funktionsaufrufen stärker verlangsamt.

Problem Nr. 2: Zu viele Informationen

Wenn Sie sich an die cProfile-Ausgabe erinnern, die wir oben gesehen haben, enthält sie eine Zeile für jede einzelne Funktion, die während des Programmlaufs aufgerufen wurde.

Die meisten dieser Funktionsaufrufe sind für unser Leistungsproblem irrelevant: Sie laufen schnell und nur ein- oder zweimal.

Wenn Sie also die cProfile-Ausgabe lesen, haben Sie es mit einer Menge zusätzlichen Rauschens zu tun, das das Signal maskiert.

Problem Nr. 3: Offline-Messung der Leistung

Häufig ist Ihr Programm nur dann langsam, wenn es unter realen Bedingungen und mit realen Eingaben ausgeführt wird.

Vielleicht verlangsamen nur bestimmte Abfragen von Benutzern Ihre Webanwendung, und Sie wissen nicht, welche Abfragen.

Vielleicht ist Ihr Batch-Programm nur mit realen Daten langsam.

Aber cProfile verlangsamt, wie wir gesehen haben, Ihr Programm ziemlich, und deshalb wollen Sie es wahrscheinlich nicht in Ihrer Produktionsumgebung laufen lassen.

Problem #4: Die Leistung wird nur für Funktionen gemessen

cProfile kann Ihnen sagen „slowfunc() ist langsam“, wobei es alle Eingaben zu dieser Funktion mittelt.Und das ist in Ordnung, wenn die Funktion immer langsam ist.

Aber manchmal hat man einen algorithmischen Code, der nur für bestimmte Eingaben langsam ist.

• slowfunc(100) kann durchaus schnell sein.
• slowfunc(0) langsam ist.

cProfile wird Ihnen nicht sagen können, welche Eingaben die Langsamkeit verursacht haben, was die Diagnose des Problems erschweren kann.

cProfile: In der Regel unzureichend

Aufgrund dieser Probleme sollte cProfile nicht das Performance-Tool Ihrer Wahl sein.

• Stattdessen werden wir im Folgenden über zwei Alternativen sprechen:
  • Pyinstrument löst die Probleme #1 und #2.
  • Eliot löst die Probleme #3 und #4.

  Pyinstrument: ein Sampling-Profiler

  Pyinstrument löst zwei der Probleme, die wir oben behandelt haben:

  • Es hat einen geringeren Overhead als cProfile, und es verfälscht die Ergebnisse nicht.
  • Es filtert irrelevante Funktionsaufrufe heraus, so dass es weniger Rauschen gibt.

  Pyinstrument misst die verstrichene Wallclock-Zeit, nicht die CPU-Zeit, so dass es Langsamkeit, die durch Netzwerkanfragen, Schreibvorgänge auf der Festplatte, Sperrkonflikte und so weiter verursacht wird, abfangen kann.

  Wie man es verwendet

  Die Verwendung von Pyinstrument ist ähnlich wie bei cProfile; fügen Sie einfach ein Präfix zu Ihrem Skript hinzu:

  $ python benchmark.py7561 messages/sec$ python -m pyinstrument benchmark.py6760 messages/sec... pyinstrument output ...

  Beachten Sie, dass es etwas Overhead hat, aber nicht so viel wie cProfile – und der Overhead ist gleichmäßig.

  Pyinstrument hat auch eine Python-API, so dass Sie es verwenden können, um bestimmte Codestücke in einem interaktiven Python-Interpreter oder einem Jupyter-Notebook zu profilieren.

  Die Ausgabe

  Die Ausgabe von Pyinstrument ist ein Baum von Aufrufen, der die Wanduhrzeit misst:

  Im Gegensatz zu cProfile’s row-per-function gibt Pyinstrument einen Baum von Funktionsaufrufen aus, so dass man den Kontext der Langsamkeit sehen kann.Eine Funktion kann mehrfach erscheinen, wenn die Langsamkeit durch mehrere Codepfade verursacht wird.

  Als Ergebnis ist die Ausgabe von Pyinstrument viel einfacher zu interpretieren und gibt Ihnen ein viel besseres Verständnis der Leistungsstruktur Ihres Programms als die Standardausgabe von cProfile.

  Wie es funktioniert (Katzenausgabe)

  Stellen Sie sich vor, Sie haben eine Katze und möchten wissen, wie diese Katze ihre Zeit verbringt.

  Du könntest ihr jeden Moment nachspionieren, aber das wäre eine Menge Arbeit.

  Deshalb beschließt du, Stichproben zu nehmen: alle 5 Minuten steckst du deinen Kopf in den Raum, in dem die Katze ist, und schreibst auf, was sie gerade tut.

  Zum Beispiel:

  • 12:00: Schlafen 💤
  • 12:05: Schlafen 💤
  • 12:10: Fressen 🍲
  • 12:15: Katzenklo benutzen 💩
  • 12:20: Schlafen 💤
  • 12:25: Schlafen 💤
  • 12:30: Schlafen 💤

  Ein paar Tage später kannst du deine Beobachtungen zusammenfassen:

  • 80%: Schlafen 💤
  • 10%: Fressen 🍲
  • 9%: Die Katzentoilette benutzen 💩
  • 1%: Sehnsüchtig durch das Fenster auf die Vögel starren 🐦

  Wie genau ist also diese Zusammenfassung?Sofern es Ihr Ziel ist, zu messen, wo die Katze die meiste Zeit verbracht hat, ist sie wahrscheinlich genau.und je häufiger die Beobachtungen (==Stichproben) und je mehr Beobachtungen Sie machen, desto genauer ist die Zusammenfassung.

  Wenn Ihre Katze die meiste Zeit mit Schlafen verbringt, würden Sie erwarten, dass die meisten Beobachtungen zeigen, dass sie schläft.und ja, Sie werden einige schnelle und seltene Aktivitäten verpassen – aber für die Frage „womit hat die Katze die meiste Zeit verbracht“ sind diese schnellen und seltenen Aktivitäten irrelevant.

  Wie es funktioniert (Software-Edition)

  Gleich wie unsere Katze nimmt Pyinstrument das Verhalten eines Python-Programms in Intervallen unter die Lupe: alle 1ms wird geprüft, welche Funktion gerade läuft.

  • Wenn eine Funktion kumulativ langsam ist, wird sie oft auftauchen.
  • Wenn eine Funktion kumulativ schnell ist, sehen wir sie normalerweise überhaupt nicht.

  Das bedeutet, dass unsere Leistungszusammenfassung weniger Rauschen hat: Funktionen, die kaum benutzt werden, werden meistens übersprungen.

  Eliot: Eine Logging-Bibliothek

  Das letzte Tool, das wir im Detail behandeln werden, ist Eliot, eine Logging-Bibliothek, die ich geschrieben habe. Sie löst die beiden anderen Probleme, die wir mit cProfile gesehen haben:

  • Logging kann in der Produktion verwendet werden.
  • Logging kann Argumente für Funktionen aufzeichnen.

  Wie Sie sehen werden, bietet Eliot einige einzigartige Fähigkeiten, die es besser bei der Aufzeichnung der Leistung als normale Logging-Bibliotheken machen.Das heißt, mit etwas zusätzlicher Arbeit können Sie die gleichen Vorteile auch von anderen Logging-Bibliotheken erhalten.

  Hinzufügen von Logging zu bestehendem Code

  Betrachten Sie die folgende Skizze eines Programms:

  Wir können diesen Code nehmen und ihm etwas Logging hinzufügen:

  Genauer gesagt, tun wir zwei Dinge:

  1. Sagen Sie Eliot, wo die Log-Meldungen ausgegeben werden sollen (in diesem Fall eine Datei namens „out.log“).
  2. Wir dekorieren die Funktionen mit einem @log_call Dekorator.Dieser protokolliert die Tatsache, dass die Funktion aufgerufen wurde, ihre Argumente und den Rückgabewert (oder die ausgelöste Ausnahme).

  Eliot hat andere, feinere APIs, aber @log_call reicht aus, um die Vorteile der Protokollierung zu demonstrieren.

  Eliots Ausgabe

  Nachdem wir das Programm ausgeführt haben, können wir uns die Protokolle mit einem Tool namens eliot-tree ansehen:

  Beachte, dass wir, ähnlich wie bei Pyinstrument, einen Baum von Aktionen betrachten.Ich habe die Ausgabe ein wenig vereinfacht – ursprünglich, damit sie auf eine Folie passt, die ich in der Vortragsversion dieses Artikels verwendet habe – aber selbst in einem Prosaartikel können wir uns auf den Leistungsaspekt konzentrieren.

  In Eliot hat jede Aktion einen Start und ein Ende und kann andere Aktionen starten – daher der resultierende Baum.Da wir wissen, wann jede protokollierte Aktion beginnt und endet, wissen wir auch, wie lange sie gedauert hat.

  In diesem Fall entspricht jede Aktion eins-zu-eins einem Funktionsaufruf.

  1. Anstatt mehrere Funktionsaufrufe zu kombinieren, sehen Sie jeden einzelnen Aufruf separat.
  2. Sie können die Argumente und das Rückgabeergebnis jedes Aufrufs sehen.
  3. Sie können die verstrichene Wallclock-Zeit jeder Aktion sehen.

  Zum Beispiel können Sie sehen, dass multiplysum() 10 Sekunden dauerte, aber der Großteil der Zeit wurde in multiply() verbracht, mit den Eingaben von 3 und 4.Sie wissen also sofort, dass Sie sich bei der Leistungsoptimierung auf multiply() konzentrieren sollten, und Sie haben einige Starteingaben (3 und 4), mit denen Sie herumspielen können.

  Die Grenzen der Protokollierung

  Die Protokollierung allein reicht als Quelle für Leistungsinformationen nicht aus.

  Erstens erhalten Sie nur Informationen aus dem Code, dem Sie explizit Protokollierungsaufrufe hinzugefügt haben.Ein Profiler kann auf jedem beliebigen Stück Code ohne Vorbereitung laufen, aber bei der Protokollierung müssen Sie im Voraus etwas Arbeit leisten.

  Wenn Sie keinen Protokollierungscode hinzugefügt haben, erhalten Sie keine Informationen.Eliot macht dies etwas besser, da die Struktur des Aktionsbaums Ihnen ein Gefühl dafür gibt, wo Zeit verbracht wurde, aber es ist immer noch nicht ausreichend, wenn die Protokollierung zu spärlich ist.

  Zweitens kann man die Protokollierung nicht überall einbauen, weil das das Programm verlangsamt.Logging ist nicht billig – es ist ein höherer Overhead als cProfile.Also muss man es mit Bedacht einbauen, an Schlüsselpunkten, wo es die Informationen maximiert, ohne die Leistung zu beeinträchtigen.

  Auswahl der richtigen Werkzeuge

  Wann sollte man also jedes Werkzeug verwenden?

  Immer Protokollierung hinzufügen

  Jedes nicht-triviale Programm braucht wahrscheinlich etwas Protokollierung, wenn auch nur, um Bugs und Fehler zu finden.

  Und wenn man schon Protokollierung hinzufügt, kann man sich die Mühe machen, die Informationen zu protokollieren, die man braucht, um auch Performance-Debugging zu betreiben.

  Eliot macht es einfacher, da die Protokollierung von Aktionen von Haus aus die verstrichene Zeit angibt, aber Sie können dies mit etwas zusätzlicher Arbeit mit jeder Protokollierungsbibliothek tun.

  Die Protokollierung kann Ihnen helfen, die spezifische Stelle zu finden, an der Ihr Programm langsam ist, und zumindest einige Eingaben, die die Langsamkeit verursachen, aber sie ist oft nicht ausreichend.Der nächste Schritt ist die Verwendung eines Profilers, insbesondere eines Sampling-Profilers wie Pyinstrument:

  • Er hat einen geringen Overhead und, was noch wichtiger ist, er verfälscht die Ergebnisse nicht.
  • Er misst die Wallclock-Zeit, so dass er nicht davon ausgeht, dass die CPU der Engpass ist.
  • Er gibt nur die langsameren Funktionen aus und lässt die irrelevanten schnellen Funktionen weg.

  Benutzen Sie cProfile, wenn Sie eine benutzerdefinierte Kostenmetrik benötigen

  Wenn Sie jemals einen benutzerdefinierten Profiler schreiben müssen, können Sie mit cProfile verschiedene Kostenfunktionen einfügen, was es zu einem einfachen Werkzeug für die Messung ungewöhnlicher Metriken macht.

  Sie können messen:

  • Nicht-CPU, die gesamte Zeit, die mit dem Warten auf Nicht-CPU-Ereignisse verbracht wird.
  • Die Anzahl der freiwilligen Kontextwechsel, d.h. die Anzahl der Systemaufrufe, die viel Zeit in Anspruch nehmen.
  • Speicherzuweisungen.
  • Allgemeiner, jeder Zähler, der ansteigt.

  TL;DR

  Als guten Ausgangspunkt für Tools zur Leistungsoptimierung schlage ich vor, dass Sie:

  1. Schlüsseleingaben und -ausgaben sowie die verstrichene Zeit von Schlüsselaktionen mit Eliot oder einer anderen Protokollierungsbibliothek protokollieren.
  2. Verwenden Sie Pyinstrument – oder einen anderen Sampling-Profiler – als Ihren Standard-Profiler.
  3. Verwenden Sie cProfile, wenn Sie einen benutzerdefinierten Profiler benötigen.