35.5    Analyse des Laufzeitverhaltens 

Die Optimierung eines Programms kann viel Zeit in Anspruch nehmen. In der Regel wird zunächst ein lauffähiges Programm erstellt, das alle gewünschten Anforderungen erfüllt, bei dem jedoch noch nicht unbedingt Wert auf die Optimierung der Algorithmik gelegt wird. Das liegt vor allem daran, dass man oftmals erst beim fertigen Programm die tatsächlichen Engpässe erkennt und im frühen Stadium somit eventuell viel Zeit in die Optimierung unkritischer Bereiche investiert hätte.

Um das Laufzeitverhalten eines Python-Programms möglichst genau zu erfassen, existieren die drei Module timeit, profile und cProfile in der Standardbibliothek von Python. Diese Module sind das Thema der nächsten Abschnitte.

 

35.5.1    Laufzeitmessung – timeit 

Das Modul timeit der Standardbibliothek ermöglicht es, genau zu messen, wie lange ein Python-Programm zur Ausführung braucht. Üblicherweise wird timeit dazu verwendet, die Laufzeit zweier verschiedener Algorithmen für dasselbe Problem zu vergleichen.

Sie erinnern sich sicherlich noch, dass im Kapitel über Funktionen ein rekursiver Algorithmus zur Berechnung der Fakultät angegeben wurde. Es wurde gesagt, dass ein laufzeitoptimierter iterativer Algorithmus im Vergleich zu seinem rekursiven Pendant stets effizienter ist. Das wollen wir in diesem Abschnitt anhand des timeit-Moduls überprüfen und zusätzlich testen, um wie viel Prozent die iterative Variante tatsächlich schneller ausgeführt werden kann.

Um die Laufzeit eines Python-Codes zu testen, muss die im Modul timeit enthaltene Klasse Timer instanziiert werden. Der Konstruktor der Klasse Timer hat die im Folgenden beschriebene Schnittstelle:

Timer([stmt, setup])

Hiermit wird eine Instanz der Klasse Timer erzeugt. Der zu analysierende Python-Code kann dem Konstruktor in Form des Parameters stmt als String übergeben werden. Für den zweiten Parameter setup kann ebenfalls ein String übergeben werden, der den Python-Code enthält, der zur Initialisierung von stmt benötigt wird. Demzufolge wird setup auch vor stmt ausgeführt. Beide Parameter sind optional und mit dem String "pass" vorbelegt.

Nachdem eine Instanz der Klasse Timer erzeugt wurde, besitzt sie drei Methoden, die im Folgenden besprochen werden.

t.timeit([number])

Diese Methode führt zunächst den setup-Code einmalig aus und wiederholt danach den beim Konstruktor für stmt übergebenen Code number-mal. Wenn der optionale Parameter number nicht angegeben wurde, wird der zu messende Code 1.000.000-mal ausgeführt.

Die Funktion gibt die Zeit zurück, die das Ausführen des gesamten Codes (also inklusive aller Wiederholungen, jedoch exklusive des Setup-Codes) in Anspruch genommen hat. Der Wert wird in Sekunden als Gleitkommazahl zurückgegeben.

t.repeat([repeat, number])

Diese Methode ruft die Methode timeit repeat-mal auf und gibt die Ergebnisse in Form einer Liste von Gleitkommazahlen zurück. Der Parameter number wird dabei der Methode timeit bei jedem Aufruf übergeben.

t.print_exc([file])

Sollte im zu analysierenden Code eine Exception geworfen werden, wird die Analyse sofort abgebrochen und ein Traceback ausgegeben. Der Stacktrace dieses Tracebacks ist jedoch nicht immer optimal, da er sich nicht auf den tatsächlich ausgeführten Quellcode bezieht.

Um einen aussagekräftigeren Stacktrace auszugeben, können Sie eine geworfene Exception abfangen und die Methode print_exc aufrufen. Diese Methode gibt einen Traceback auf dem Bildschirm aus, der sich direkt auf den zu analysierenden Code bezieht und damit die Fehlersuche erleichtert. Durch Angabe des optionalen Parameters file leiten Sie die Ausgabe in eine Datei um.

Beispiel

Eingangs wurde erwähnt, dass wir das Modul timeit dazu verwenden werden zu prüfen, um wie viel Prozent die iterative Fakultätsberechnung schneller ist als die rekursive. Dazu binden wir zunächst das Modul timeit ein und implementieren die beiden Berechnungsfunktionen:

import timeit
def fak1(n):
    res = 1
    for i in range(2, n+1): 
        res *= i
    return res
def fak2(n): 
    if n > 0: 
        return fak2(n-1)*n
    else: 
        return 1

Danach erzeugen wir für beide Funktionen jeweils eine Instanz der Klasse Timer:

t1 = timeit.Timer("fak1(50)", "from __main__ import fak1")
t2 = timeit.Timer("fak2(50)", "from __main__ import fak2")

Beachten Sie, dass wir im Setup-Code zunächst die gewünschte Berechnungsfunktion aus dem Namensraum des Hauptprogramms __main__ in den Namensraum des zu testenden Programms importieren müssen. Im eigentlich zu analysierenden Code wird nur noch die Berechnung der Fakultät von 50 unter Verwendung der jeweiligen Berechnungsfunktion angestoßen.

Schließlich wird die Laufzeitmessung mit 1.000.000 Wiederholungen gestartet und das jeweilige Ergebnis ausgegeben:

print("Iterativ: ", t1.timeit())
print("Rekursiv: ", t2.timeit())

Die Ausgabe des Programms lautet:

Iterativ:  3.3135700230195653
Rekursiv:  9.360691823996603

Das bedeutet, dass der iterative Algorithmus etwa doppelt so schnell ist wie der rekursive. Doch diese Daten sind noch nicht wirklich repräsentativ, denn es könnte sein, dass der Test der rekursiven Funktion durch einen im System laufenden Prozess ausgebremst wurde. Aus diesem Grund starten wir einen erneuten Test:

print("Iterativ: ", min(t1.repeat(100, 10000)))
print("Rekursiv: ", min(t2.repeat(100, 10000)))

Dieses Mal führen wir eine Testreihe durch, die einen Test mit 10.000 Einzelwiederholungen 100-mal wiederholt und das kleinste der Ergebnisse ausgibt. Die Ergebnisse sind annäherungsweise deckungsgleich mit denen der vorherigen Tests:

Iterativ:  0.031242681987350807
Rekursiv:  0.09040119699784555

Die absoluten Zahlenwerte hängen stark vom verwendeten System ab. Auf einem schnelleren Computer sind sie dementsprechend kleiner.

 

35.5.2    Profiling – cProfile 

Um eine Laufzeitanalyse eines vollständigen Python-Programms anzufertigen, wird ein Profiler verwendet. Ein Profiler überwacht einen kompletten Programmdurchlauf und listet nach Beenden des Programms detailliert auf, wie viel Prozent der Laufzeit in welcher Funktion verbraucht wurden. Auf diese Weise kann der Programmierer die laufzeittechnischen Engpässe des Programms erkennen und an sinnvollen Stellen mit der Optimierung des Programms beginnen.

Grundsätzlich gilt: Je mehr Prozent der Laufzeit in einer bestimmten Funktion verbracht werden, desto mehr Zeit sollten Sie investieren, um diese Funktion zu optimieren.

Im Modul cProfile sind zwei wichtige Funktionen enthalten, die im Folgenden besprochen werden.

run(command, [filename, sort])

Diese Funktion führt den als command übergebenen String mithilfe einer exec-Anweisung aus und nimmt während der Ausführung eine detaillierte Laufzeitanalyse vor. Üblicherweise wird für command ein Funktionsaufruf der Hauptfunktion eines größeren Programms übergeben.

Über den zweiten, optionalen Parameter filename kann eine Datei angegeben werden, in die das Ergebnis der Laufzeitanalyse geschrieben wird. Wenn dieser Parameter nicht angegeben wurde, wird das Ergebnis auf dem Bildschirm ausgegeben. Bei diesem Ergebnis der Analyse handelt es sich um eine tabellarische Auflistung aller Funktionsaufrufe. Wie diese Tabelle aussieht und wie sie zu lesen ist, erfahren Sie anhand des nächsten Beispiels.

Der Parameter sort steuert, wonach die Ergebnistabelle sortiert werden soll. Die folgenden Werte sind möglich:

Tabelle 35.6    Mögliche Werte für den Parameter sort

runctx(command, globals, locals, [filename])

Diese Funktion verhält sich wie run, mit dem Unterschied, dass über die Parameter globals und locals der globale und lokale Kontext festgelegt werden können, in denen command ausgeführt wird. Für die Parameter globals und locals kann ein Dictionary übergeben werden, wie es von den Built-in Functions globals und locals zurückgegeben wird.

Beispiel

Im Folgenden wird eine Laufzeitanalyse für ein kleines Beispielprogramm erstellt. Dazu betrachten wir zunächst den Quelltext des Programms:

import math
def calc1(n):
    return n**2
def calc2(n): 
    return math.sqrt(n)
def calc3(n): 
    return math.log(n+1)
def programm():
    for i in range(100): 
        calc1(i) 
        for j in range(100): 
            calc2(j) 
            for k in range(100): 
                calc3(k)
programm()

Im Programm existieren drei kleine Funktionen namens calc1, calc2 und calc3, die jeweils eine ganze Zahl als Parameter übergeben bekommen, dann eine mathematische Operation auf diese Zahl anwenden und das Ergebnis zurückgeben. In der Hauptfunktion programm befinden sich drei ineinander verschachtelte Schleifen, die jeweils über alle ganzen Zahlen von 0 bis 99 iterieren und eine der drei Berechnungsfunktionen aufrufen. Die Frage, die wir mithilfe des Profilers lösen möchten, lautet, an welcher Stelle sich eine Optimierung des Programms besonders lohnen würde und wo sie überflüssig wäre.

Der Profiler wird folgendermaßen in das Programm eingebunden:

import cProfile
# Beispielprogramm
cProfile.run("programm()")

Dabei steht Beispielprogramm für den Code des Beispielprogramms. Die Code-Zeile programm() des Beispielprogramms ist jetzt überflüssig. Das Ausführen der Laufzeitanalyse gibt folgendes Ergebnis aus:

         2020104 function calls in 0.576 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.576    0.576 <string>:1(<module>)
      100    0.000    0.000    0.000    0.000 test.py:10(calc1)
    10000    0.002    0.000    0.003    0.000 test.py:12(calc2)
  1000000    0.203    0.000    0.407    0.000 test.py:14(calc3)
        1    0.166    0.166    0.576    0.576 test.py:16(programm)
        1    0.000    0.000    0.576    0.576 {built-in method builtins.exec}
  1000000    0.204    0.000    0.204    0.000 {built-in method math.log}
    10000    0.001    0.000    0.001    0.000 {built-in method math.sqrt}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

• Jede Zeile dieser Tabelle bezieht sich auf eine Funktion des Beispielprogramms. Die Spaltenbeschriftungen der Tabelle sind vielleicht nicht ganz klar, weswegen sie kurz erläutert werden sollen:
• ncalls steht für die Anzahl von Funktionsaufrufen der Funktion.
• tottime steht für die Gesamtzeit in Sekunden, die in der Funktion verbracht wurde. Dabei werden Aufrufe von Unterfunktionen nicht einbezogen.
• percall steht für den Quotienten von tottime und ncalls.
• cumtime steht für die Gesamtzeit in Sekunden, die in der Funktion verbracht wurde. Dabei werden Aufrufe von Unterfunktionen einbezogen.
• percall steht für den Quotienten von cumtime und ncalls.
• filename:lineno(function) steht für den Funktionsnamen inklusive Angabe der Programmdatei und der Zeile, an der die Funktion im Quellcode steht.

Die vom Profiler angezeigte Tabelle gibt Ihnen einen guten Überblick darüber, wo die zeitkritischen Funktionen des Programms liegen. In diesem Fall sticht die Funktion calc3 hervor, die insgesamt 1.000.000-mal aufgerufen wird und in der sich satte 70 % der Laufzeit abspielen. Die 10.000-mal aufgerufene Funktion calc2 macht hingegen nur 0,5 % der Gesamtlaufzeit aus. Die restliche Laufzeit wird, abgesehen von einem verschwindend geringen Prozentsatz in calc1, in der Hauptfunktion programm verbracht.

Zugegebenermaßen hätte man dieses Ergebnis auch anhand des Programms abschätzen können. Jede Schleife iteriert über 100 Zahlen und ruft in jedem Iterationsschritt »ihre« Funktion auf. Damit wird die innerste Funktion 100³=1.000.000-mal aufgerufen. Auch die prozentuale Laufzeit der Funktionen calc3 und calc2 liegt in etwa um Faktor 100 auseinander. Etwaige Schwankungen ergeben sich daraus, dass unterschiedliche Berechnungen durchgeführt werden.

Auch wenn dieses Beispiel etwas künstlich wirkt, lässt sich die Vorgehensweise auf ein größeres, zeitkritisches Projekt übertragen. Im Falle unseres Beispiels soll das Augenmerk auf die Optimierung der Funktion calc3 gelegt werden, da diese mit 1.000.000 Aufrufen und 70 % Laufzeitanteil stark dominiert.

 

35.5.3    Tracing – trace 

Im letzten Abschnitt haben wir besprochen, welche Möglichkeiten Python bietet, ein Programm mithilfe eines Profilers zu untersuchen. Dies funktioniert im besprochenen Beispiel sehr gut, hat aber auch einen großen Nachteil: Der Profiler arbeitet auf der Funktionsebene. Das bedeutet, dass immer nur die Laufzeit ganzer Funktionen gemessen wird. Häufig ist es aber so, dass es auch innerhalb einer größeren Funktion Teile gibt, die laufzeittechnisch gesehen bedeutungslos sind, und Teile, die sehr laufzeitintensiv sind. In einem solchen Fall greift man zu einem anderen Hilfsmittel, dem Tracer.

Ein Tracer, in Python über das Modul trace verfügbar, überwacht einen Programmlauf und registriert dabei, wie oft jede einzelne Code-Zeile des Programms ausgeführt wurde. Eine solche Überdeckungsanalyse wird im Wesentlichen aus zwei Gründen durchgeführt:

• Mithilfe einer Überdeckungsanalyse lassen sich Code-Zeilen ausfindig machen, die besonders häufig aufgerufen werden und daher möglicherweise besonders laufzeitintensiv sind. Diese Zeilen könnten Sie dann gezielt optimieren. Beachten Sie aber, dass ein Tracer nicht die tatsächliche Laufzeit einer Code-Zeile misst, sondern nur, wie oft diese Zeile im Programmfluss ausgeführt wurde.
• Häufig muss bei sicherheitsrelevanten Programmen eine Überdeckungsanalyse vorgelegt werden, um zu beweisen, dass bei einem Test jede Code-Zeile mindestens einmal ausgeführt wurde. Auf diese Weise versucht man zu vermeiden, dass beispielsweise der Autopilot eines Flugzeugs ausfällt, weil ein Fall eingetreten ist, an den man beim Testen der Software nicht gedacht hat.

In diesem Abschnitt möchten wir die Überdeckungsanalyse durchführen, um laufzeitkritische Stellen in einem Programm zu identifizieren. Dazu erstellen wir eine leicht modifizierte Version des Beispielprogramms aus dem vorangegangenen Abschnitt. »Modifiziert« bedeutet, dass der Code ohne Unterfunktionen geschrieben wurde.

import math
def programm():
    for i in range(100): 
        i**2
        for j in range(100): 
            math.sqrt(j) 
            for k in range(100): 
                math.log(k+1)

Die Überdeckungsanalyse wird mithilfe des Moduls trace durchgeführt. Dazu ist folgender zusätzlicher Code nötig:

import trace
import sys
tracer = trace.Trace(ignoredirs = [sys.prefix, sys.exec_prefix], trace = 0) 
tracer.run("programm()")
r = tracer.results()
r.write_results(show_missing=True, coverdir="ergebnis")

Zunächst wird eine Instanz der Klasse Tracer erzeugt. Diese bekommt zwei Schlüsselwortparameter übergeben. Über den Parameter ignoredirs wird eine Liste von Verzeichnissen übergeben, deren enthaltene Module nicht in die Überdeckungsanalyse einbezogen werden sollen. In diesem Fall möchten wir keine Module der Standardbibliothek übergeben und fügen deshalb die entsprechenden Verzeichnisse sys.prefix und sys.exec_prefix an. Den zweiten Parameter, trace, setzen wir auf 0, da sonst jede während des Programmlaufs ausgeführte Zeile auf dem Bildschirm ausgegeben wird.

Danach führen wir analog zum Profiler die Methode run der Trace-Instanz aus und übergeben dabei den auszuführenden Python-Code. Nachdem der Tracer durchgelaufen ist, können die Ergebnisse über die Methode results der Trace-Instanz abgeholt werden. Wir möchten die Ergebnisse in diesem Fall nicht weiterverarbeiten und speichern sie deshalb mithilfe der Methode write_results auf der Festplatte. Dabei geben wir über den Parameter coverdir das Unterverzeichnis an, in dem die Ergebnisse gespeichert werden sollen. Wenn für den Parameter show_missing der Wert True übergeben wird, werden Code-Zeilen, die während des Programmlaufs niemals ausgeführt wurden, mit einem Pfeil gekennzeichnet.

Das Ergebnis wird im Unterordner ergebnis als Textdatei mit dem Dateinamen modulname.cover abgespeichert, wobei modulname durch den Namen Ihres getesteten Moduls ersetzt wird.

In unserem Beispiel sieht das Ergebnis folgendermaßen aus:

       import trace
>>>>>> import sys
>>>>>> import math
>>>>>> def programm():
  101:     for i in range(100): 
  100:         i**2
10100:         for j in range(100): 
10000:             math.sqrt(j) 
1010000:             for k in range(100): 
1000000:                 math.log(k+1)
>>>>>> tracer = trace.Trace(
>>>>>>     ignoredirs = [sys.prefix, sys.exec_prefix], 
>>>>>>     trace = 0)
>>>>>> tracer.run("programm()")
>>>>>> r = tracer.results()
>>>>>> r.write_results(show_missing=True, coverdir="ergebnis")

Sie sehen, dass die Ergebnisse zu einer gut lesbaren Datei aufbereitet werden. Im Prinzip ist die Datei in zwei Spalten aufgeteilt: Rechts steht der Quellcode des Programms und links die Anzahl der Aufrufe jeder Code-Zeile. Die Pfeile in der linken Spalte weisen auf Code-Zeilen hin, die während des überwachten Programmlaufs niemals ausgeführt wurden. Diese Zeilen wurden natürlich nur nicht ausgeführt, solange die Überwachung des Programms aktiv war.

for i in range(100):