Performance Profile erstellen

[Judge]

Hallo zusammen!

Ich habe @work ein Python Script "geerbt", welches grundsätzlich tut was es soll und fehlerfrei funktioniert. Allerdings wurde ich gebeten mir das hinsichtlich Performance mal genauer anzuschauen, da es derzeit eine Laufzeit von etwas mehr als 3 Stunden hat (zuletzt: 3:10).

Wenn ich Scripte entwickle, dann tue ich das in der Regel mit PyCharm und nutze den eingebauten Profiler; scheinbar ist dieses intern und per default `yappi` oder `cProfiler`. Also habe ich auf dem entfernten System, auf welchem das Script jeden Tag 1x läuft, `yappi` installiert (da dieser scheinbar "multithreading aware" ist) und wie folgt eine PSTAT Datei damit erzeugt:

Code: Alles auswählen

python3 -m yappi -o run.pstat /code/main.py

Diese kann ich dann ja auch in PyCharm öffnen um es mit der Visualisierung etwas komfortabler zu haben; das Ganze sieht dann da so aus:



Ich bin nun vom Ergebnis sehr verwirrt; scheinbar mache ich da grundlegend etwas falsch:

1. Das Ganze beginnt mit `Thread.run` und nicht etwa mit `main.py` als Ausgangspunkt.
2. Die "Total" Time ist "850308 milliseconds", was in etwa 14 Minuten und 10 Sekunden entspricht. Das Script läuft aber auf dem nicht gerade schwachen Host, wie gesagt, über 3 Stunden.

Ich kann das Script auch nicht lokal oder nur in Teilen auf meiner Workstation laufen lassen, da es mit einer nur von dort aus zu erreichenden API spricht und die Anfragen auch komplett durchgeführt werden müssen, um sinnvolle Ergebnisse zu haben.
Leider gibt es aufgrund der Art und Menge der verwalteten Daten kein Testsystem davon ...

Ich hoffe ich konnte meine Fragen nachvollziehbar darstellen.
Wie kriege ich bei einer Threaded Applikationen ein Performance Profil erstellt in dem ich sehe, was genau da diese 3 Stunden braucht?

Meine Vermutung ist, das ein Großteil der Laufzeit einfach daher kommt, das die API des abgefragten Systems einfach seine Zeit braucht und "mein" Script daher recht lange auf Antworten warten lässt. Nur das würde ich gerne in einem Profiler-Ergebnis sehen und dokumentieren statt es nur zu vermuten. Auch, ob und wie häufig neue sessions aufgebaut werden müssen würde ich gerne auswerten.

Vielen Dank schonmal für alle Ideen und Feedbacks.

[__blackjack__]

Gibt es denn in der `main.py` auch eine Hauptfunktion, oder wird da Code auf Modulebene ausgeführt?

Es sind anscheinend insgesamt 55.597 HTTP-Anfragen. Bei 3 Stunden sind das ca. 0,2s pro Anfrage. Also komplett mit Verbindungsauf- und abbau und was immer Du da an Verarbeitung noch so machst. So krass langsam klingt das IMHO gar nicht.

[Judge]

Es gibt mehrere Funktionen die aus mehreren Dateien heraus importiert werden.
Die Hauptfunktion liegt in `main.py` und wird über das klassische main() Konstrukt gestartet:

Code: Alles auswählen

if __name__ == "__main__":
    main()

Daher hatte ich auch erwartet, das `main()` in solch einem Profile meinen Ausgangspunkt darstellt ...

Sobald Threads ins Spiel kommen scheint es aber zu sein als verschiebt man ein Bild in Word um einen Pixel zur Seite ...
Ich habe, damit wir konkret über Code und Profiling-Ergebnis reden können (und ich den Original Code nicht zeigen kann) mal Nonsense-Code geschrieben:

main.py:

Code: Alles auswählen

from functions import waste_time
import threading


def main():
    threads = [threading.Thread(target=waste_time) for x in range(10)]
    for thread in threads:
        thread.start()
    for thread in threads:
        thread.join()


if __name__ == "__main__":
    main()

functions.py:

Code: Alles auswählen

import time


def waste_time():
    time.sleep(5)

Es werden also 10 Threads gestartet, die einfach parallel je 5 Sekunden warten. Das Script läuft auch 5 Sekunden lang, wie zu erwarten war. Der Graph (mit yappi erstellt) dazu sieht so aus:



Ich lasse mich sehr, sehr gerne korrigieren, denn offensichtlich sind die folgenden Schlüsse falsch; aber wenn ich mir den Graphen angucke, steht für mich da:

• Das ganze Script main.py lief in Summe nur ca. 3 millisekunden.
• Die Funktion "waste_time" lief zwar 10 Mal, wurde aber durch nichts ausgeführt, weil von Ihr/Zu Ihr keinerlei Verbindung abgeht.
• Die Funktion "waste_time" macht nur einen sleep von 5 Sekunden, führt das aber innerhalt von 0 millisekunden aus.

Wie zieht man denn aus so etwas nun Erkenntnisse?

[__blackjack__]

Gute Frage. Offenbar wird nur die Prozessorzeit gemessen, also wo der Prozess wirklich Zeit verbraucht hat. `sleep()`, egal wie lange, verbraucht ja keine Prozesszeit, das wird ja im Kernel (nicht) ausgeführt. Genau so verbaucht `join()` keine Prozessorzeit.