Allgemein

Informationen

  • 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.

Call count statistics can be used to identify bugs in code (surprising counts), and to identify possible inline-expansion points (high call counts). Internal time statistics can be used to identify “hot loops” that should be carefully optimized. Cumulative time statistics should be used to identify high level errors in the selection of algorithms.

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.
ButtonFunktion
SofortanalyseDas Ergebnis direkt in einer MessageBox anzeigen
Datei generierenDas Ergebnis als Datei abspeichern
AbbrechenDas 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:
ModusBegrenzung
Normal25 Zeilen
Callers15 Zeilen
Callees15 Zeilen
  • Die Messagebox gliedert sich wie folgt:

NummerErklärung
1Zeit der Analyse und Pfad, an dem die Profile-Datei liegt. Bei der Sofortanalyse befindet sich die Datei immer in einem temporären Ordner
2Die Anzahl der Funktionsaufrufe mit Rekursion, ohne und die gesamte Dauer
3Nach was wird sortiert und wieviel wird angezeigt
4Die Profile-Tabelle
5, 6, 7, 8Nach der entsprechenden Spalte sortieren
9Zwischen den Ansichten Normal, Callers und Callees umschalten
10Anzeige abbrechen und MessageBox schließen
  • Die Spalten umschreiben Folgendes:
SpalteErklärung
ncallsDie Anzahl der Aufrufe und Anzahl ohne rekursive Aufrufe durch einen Slash getrennt
tottimeGesamte Zeit, die in dieser Funktion verbrachte wurde, ohne Aufrufe der Unterfunktionen
percalltottime/ncalls
cumtimeZeit, die innerhalb der Funktion von Aufruf bis Abschluss verbracht wurde, einschließlich aller Unterfunktionen
percallcumtime/ncalls
filename:lineno(function)Name der Datei: Zeilennummer (Funktionsname)
  • Die verschiedenen Ansichten:
AnsichtBedeutung
NormalZeigt Funktionsaufrufe mit Werten für die oben genannten Spalten
CallersZeigt an, von was eine Funktion aufgerufen wurde sowie die ncalls, tottime und cumtime
CalleesZeigt 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)
PY
  • 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}
CODE

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>)
CODE

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