Python-Profiling Neu ab DB 39.5.0

Allgemein

• Das Profiling dient dazu, Bottlenecks im Code zu finden.
• Anhand der Profiling-Daten kann leichter bestimmt werden, an welchen Stellen optimiert werden muss, um dann mit einem genaueren Tool wie z.B.Timeit Optimierungen zu vergleichen.
  • Siehe dazu den folgenden Auszug aus der profile.py Dokumentation:

Innerhalb von PLANTA

• Der Profiler kann messen, welche Python-Funktionen ausgeführt werden, wenn mit einem Feld interagiert wird.
• Wurden die Menüpunkte R39 Gesamt (CU) dem Benutzer zugeordnet und das DI Customizerrechte für den Benutzer aktiviert, so ist die Funktion im Menü unter Tools oder über den Shortcut F10 zu erreichen.

Anwendung

• Klick auf ein Eingabefeld, um den Fokus auf dieses zu setzen.
• F10 betätigen
• Je nach DF-Verhalten des Felds wird nun entweder das Profiling gestartet oder eine Dialogmeldung angezeigt, die nach einer Eingabe verlangt.

Feld mit DF-Verhalten i

• Wird nach einer Eingabe verlangt, wird analysiert, was passiert, wenn der eingegebene Wert in das Feld eingetragen wird.
• Bei Feldern, die nur einen Klick benötigen, wie z.B. Buttons oder Links, wird einfach der Klick simuliert.
• Nachdem das Profiling abgeschlossen wurde, erscheint erneut eine Dialogmeldung, die einem mehrere Optionen bietet, das Ergebnis des Profilings auszuwerten.

Button	Funktion
Sofortanalyse	Das Ergebnis direkt in einer MessageBox anzeigen
Datei generieren	Das Ergebnis als Datei abspeichern
Abbrechen	Das Ergebnis verwerfen

Sofortanalyse

• Die Sofortanalyse bietet einem Customizer ein schnelles Interface, um problematische Code-Stellen zu analysieren.
• Für komplexere Probleme bietet es sich an, bei jeder Version des Codes eine Profile-Datei abzuspeichern und die Ergebnisse in einem externen Tool zu analysieren (z.B. in RunSnakeRun oder mit dem Standard-Python-Modul).

Details

• Damit die Messagebox nicht zu umfangreich wird, ist die Anzahl der angezeigten Zeilen pro Anzeigemodus wie folgt limitiert:

Modus	Begrenzung
Normal	25 Zeilen
Callers	15 Zeilen
Callees	15 Zeilen

• Die Messagebox gliedert sich wie folgt:

Nummer	Erklärung
1	Zeit der Analyse und Pfad, an dem die Profile-Datei liegt. Bei der Sofortanalyse befindet sich die Datei immer in einem temporären Ordner
2	Die Anzahl der Funktionsaufrufe mit Rekursion, ohne und die gesamte Dauer
3	Nach was wird sortiert und wieviel wird angezeigt
4	Die Profile-Tabelle
5, 6, 7, 8	Nach der entsprechenden Spalte sortieren
9	Zwischen den Ansichten Normal, Callers und Callees umschalten
10	Anzeige abbrechen und MessageBox schließen

• Die Spalten umschreiben Folgendes:

Spalte	Erklärung
ncalls	Die Anzahl der Aufrufe und Anzahl ohne rekursive Aufrufe durch einen Slash getrennt
tottime	Gesamte Zeit, die in dieser Funktion verbrachte wurde, ohne Aufrufe der Unterfunktionen
percall	tottime/ncalls
cumtime	Zeit, die innerhalb der Funktion von Aufruf bis Abschluss verbracht wurde, einschließlich aller Unterfunktionen
percall	cumtime/ncalls
filename:lineno(function)	Name der Datei: Zeilennummer (Funktionsname)

• Die verschiedenen Ansichten:

Ansicht	Bedeutung
Normal	Zeigt Funktionsaufrufe mit Werten für die oben genannten Spalten
Callers	Zeigt an, von was eine Funktion aufgerufen wurde sowie die ncalls, tottime und cumtime
Callees	Zeigt an, welche Unterfunktionen von einer Funktion aufgerufen wurden sowie die gleichen Spalten wie die Ansicht Callers

Beispiel

• Folgendes Makro wurde profiled:

from ppms import ppms

projects = [item for sublist in ppms.db_select("SELECT DI001001 FROM DT461") for item in sublist]

for project in projects:
    project_rec = ppms.search_record(461, [project], [1001], True)

• Ein Auszug aus dem Ergebnis, sortiert nach Call Count:

   ncalls  tottime  percall  cumtime  percall 
      209    0.573    0.003    0.573    0.003 {built-in method search_record}
       11    0.000    0.000    0.000    0.000 ppms_.
        2    0.007    0.004    0.007    0.004 {built-in method db_select}

Details

• Es ist zu sehen, dass search_record 209 aufgerufen wurde und damit 0.573 Sekunden verbraucht wurden.
• db_select wurde zweimal aufgerufen, was hier seltsam erscheint, denn das Makro ruft db_select nur einmal auf.
• Durch Klick auf den Normal-Button kann in eine andere Ansicht gewechselt werden.

• Das gleiche Profile von der Perspektive Callers aus betrachtet:

Function                                   was called by...
                                               ncalls  tottime  cumtime
{built-in method search_record}            <-       4    0.003    0.003  MACRO_MOD_009ATM.py:1(<module>)
                                                  204    0.569    0.569  MACRO_MOD_009BQX.py:1(<module>)
                                                    1    0.000    0.000  ppms_cu.
{built-in method db_select}                <-       1    0.006    0.006  MACRO_MOD_009BQX.py:1(<module>)
                                                    1    0.001    0.001  ppms_cu.
ppms_cu.        <-       1    0.000    0.016  MACRO_MOD_009ATM.py:1(<module>)

Hinweise

• 009BQX ist das Makromodul.
• 009ATM ist das Makro hinter dem Button in 00855 Module, welches das ausgewählte Modul aufruft.

Details

• Es ist zu sehen, dass db_select wirklich nur einmal von dem Modul aufgerufen wurde.
  • Das Makro, welches hinter dem Button zum Modulaufruf steckt, musste jedoch auch indirekt eine Datenbankabfrage absetzen, weil es die Methode get_global_setting aus ppms_cu verwendet.

Sonstiges

• Python-Modul
• Profiling-Beispiel