Wir haben gesehen, dass die Laufzeit unseres Programms von der Sortierfunktion dominiert war. Wie bekommt man so etwas heraus?
Wenn man eine Ahnung hat, wo man hinsehen muss, kann man in C die Funktion clock(), in Python time() aus dem Modul time verwenden.
Dabei ist clock in time.h deklariert. Die Funktion gibt die Zahl der “clock ticks” sein Programmstart in einem Typ clock_t zurück, den man in der Regel bedenkenlos auf long casten kann. Wie lang ein clock tick ist, hängt vom System ab und kann dem Makro CLOCKS_PER_SEC entnommen werden. Das kann dann etwa so aussehen:
#include <time.h>
...
long start;
...
start = (long)clock();
<Code, dessen Laufzeit man messen möchte>
printf("Laufzeit: %f\n", ((long)clock()-start)/(double)CLOCKS_PER_SEC);
...
In Python hat time.time() normalerweise schon ausreichend Auflösung. Ein entsprechendes Programmfragment könnte also sein:
import time ... start = time.time() <Code, dessen Laufzeit man messen möchte> print "Laufzeit": start-time.time()
Sollte die Laufzeit des Codes zu kurz sein, kann man ihn häufig 10, 100 oder 1000 Mal hintereinander laufen lassen – für unsere Sortierroutine müsste das allerdings mit einiger Sorgfalt gemacht werden, denn viele Sortieralgorithmen haben ein anderes Laufzeitverhalten, wenn sie auf schon sortierte Daten laufen, und quicksort gehört nachhaltig zu dieser Kategorie. Profis können in Python übrigens auch das timeit-Modul für solche Dinge benutzen.
Besser ist meistens der Einsatz eines Profilers. Ein Profiler ist ein Programm, das einem anderen Programm bei der Ausführung zusieht und dabei misst, wie viel Zeit dieses Programm für die Ausführung welcher Funktionen benötigt.
Profiling kann gibt es in zwei Geschmäckern: Deterministisches Profiling misst die Zeit jeweils beim Ein- und Austritt aus der Funktion und berechnet daraus ihre Laufzeit. Nachteil ist, dass das den Progammablauf erheblich verlangsamen kann, und auch, dass in Mulittasking-Umgebungen die Zeit nicht unbedingt in der Funktion selbst vergangen sein muss. Der Python-Profiler arbeitet so. Statistisches Profiling hingegen sieht in regelmäßigen Abständen nach, wo im Programm sich der Program Counter gerade befindet und berechnet endlich daraus individuelle Laufzeiten der Funktionen. Nachteil dieser Methode ist, dass sie als statistische Methode natürlich beliebig falsch liegen kann. Wenn wir z.B. alle 20 ms samplen und wir zwei Funktionen haben, die jeweils genau 10 ms laufen, so wird am Ende höchstwahrscheinlich der einen Funktion die ganze Rechenzeit zugeschlagen, der anderen gar keine, obwohl bei exakt die gleiche Menge Rechenzeit verbraucht haben. Der C-Profiler, den wir hier behandeln, gprof, ist ein statistischer Profiler.
Um ein C-Programm mit gprof zu profilen, muss es (mit allen Modulen) mit der Compileroption -pg kompiliert und gelinkt werden. Wir schreiben also CFLAGS += -pg im Makefile und machen make clean;make. Wenn das entstandene Programm gelaufen ist, steht die Profiling-Information in einer Datei gmon.out. Um deren Information auszuwerten, verwendet man das Programm gprof. Um auch Bibliotheksfunktionen profilen zu können, muss weiter LDFLAGS += -static -lc_p angegeben werden, damit eine fürs Profiling vorbereitete C-Bibliothek gelinkt wird. Dadurch wird das Binary im Allgemeinen erheblich größer und die Ausgabe des Profilers erheblich unübersichtlicher. Linux-Distributionen haben in der Regel ein eigenes Paket, das diese fürs Profilen gedachte Bibliothek enthält – Debian hat etwa libc6-prof.
examples> make; listSortTest ... examples> gprof listSortTest Flat profile: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls us/call us/call name 100.00 0.27 0.27 6178 43.70 43.70 getNodeAt 0.00 0.27 0.00 6179 0.00 0.00 getNextWord 0.00 0.27 0.00 6178 0.00 0.00 getNodeFro... 0.00 0.27 0.00 6178 0.00 0.00 list_append 0.00 0.27 0.00 6178 0.00 43.70 list_getAt 0.00 0.27 0.00 2 0.00 0.00 list_len 0.00 0.27 0.00 1 0.00 0.00 getNodeArr 0.00 0.27 0.00 1 0.00 0.00 list_new 0.00 0.27 0.00 1 0.00 0.00 list_quicksort 0.00 0.27 0.00 1 0.00 270000.00 printList ...
Entsprechend mit selection sort:
52.83 0.28 0.28 6178 45.32 45.32 findAndR... 47.17 0.53 0.25 6178 40.47 40.47 getNodeAt 0.00 0.53 0.00 6179 0.00 0.00 getNextWord 0.00 0.53 0.00 6178 0.00 0.00 getNodeFro... 0.00 0.53 0.00 6178 0.00 0.00 list_append 0.00 0.53 0.00 6178 0.00 40.47 list_getAt 0.00 0.53 0.00 1 0.00 0.00 list_len 0.00 0.53 0.00 1 0.00 0.00 list_new 0.00 0.53 0.00 1 0.00 280000.00 list_sort 0.00 0.53 0.00 1 0.00 250000.00 printList
Als erstes fällt auf, dass das ganz anders aussieht als wir das oben behauptet haben. Die Gesamtlaufzeit von list sort (Spalte total us/call) wird als 260 ms angegeben, im Gegensatz zum Ergebnis aus Messungen mit clock, die 3860 ms behauptet haben, die von list_quicksort als 0.0, obwohl wir 40 ms gemessen hatten. Wo ist die Rechenzeit hingekommen?
Sie steckt in den Bibliotheksfunktionen, vor allem in strcoll, für list_quicksort auch in qsort; linkt man diese nach obigem Rezept dazu, ergibt sich, dass beim selection sort 19073230 Aufrufe von strcoll gemacht werden, beim quicksort aber nur 70021, was schon ziemich viel des Laufzeitunterschiedes erklärt. Die Laufzeit von qsort selbst ist mit ein paar Mikrosekunden vernachlässigbar, ganz im Gegensatz zum findAndRemSmallest, das, da es jeweils ein gutes Stück Liste durchlaufen muss, im Mittel immerhin 42 Mikrosekunden pro Aufruf im eigenen Code läuft (die Zeit fürs strcoll kommt da natürlich noch dazu) und das 6171 Mal.
Dass die Zeiten für die Bibliotheksfunktionen ohne spezielle Standardbibliothek nicht einfach der aufrufenden Funktion zugeschlagen werden, liegt an der Funktionsweise von gprof – es mag zwar wissen, dass das Programm zu einem bestimmten Zeitpunkt in strcoll war, weiß aber nicht, woher strcoll aufgerufen wurde, denn strcoll steht nicht im so genannten call graph, einem Graphen, der zeigt, welche Funktion von welcher aufgerufen wurde und der in den sich eine Funktion sozusagen aktiv eintragen muss. Genau dafür aber muss eine Bibliothek modifiziert werden.
Die Bedeutung der Felder im oben gezeigten “flat profile”: Ganz vorne steht der Anteil der Zeit, den das Programm in der Funktion verbracht hat, danach die “cumulative seconds”, eine Summe der Zahlen in der dritten Spalte – sie ist hier weniger interessant. Die dritte Spalte, “self seconds” ist die Zeit, die in der Funktion selbst verbracht wurde (die Zeit aufgerufener Funktionen zählt also nicht mit). Die vierte Spalte sagt, wie oft eine Funktion aufgerufen wurde, die fünfte sagt, wie viele Mikrosekunden bei jedem Aufruf in der Funktion selbst verbraten wurden, die vorletzte, wie viele Mikrosekunden in der Funktion selbst und den von ihr dabei aufgerufenen Funktionen, soweit diese im call graph auftauchen.
Was man an obigem flat profile noch sieht: Die zweite große Bremse im Programm ist getNodeAt bzw. printList. Wenn die Programme komplexer werden, mag es sein, dass nicht von vorneherein klar ist, dass getNodeAt hier von printList aufgerufen wurde. Dann hilft der etwas weiter unten in der gprof-Ausgabe stehenden call graph weiter. Informationen dazu gibt die Info-Seite von gprof.
Wenn man gprof verstanden hat, ist auch der Python-Profiler kein Geheimnis mehr. Bei normaler Verwendung durch
python /usr/local/lib/python2.2/profile.py npbayes.py
– der Pfad zu den Modulen der Python-Bibliothek ist dabei natürlich systemabhängig, und npbayes.py ist hier das zu profilende Skript – oder direkt im Skript durch
import profile
profile.run('main()')
– main() ist hier die zu profilende Funktion – werden gleich ein dem flat profile des gprof entsprechende Daten ausgegeben:
Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1000 0.020 0.000 0.020 0.000 npbayes.py:10(binomial) 1000 0.020 0.000 0.050 0.000 npbayes.py:107(getProbability) 20 0.000 0.000 0.120 0.006 npbayes.py:111(oneMapStep) ...
– man ahnt schon, dass hier die Zahl der Aufrufe, die Zeit, die insgesamt in der Funktion vergangen ist, die Zeit in der Funktion pro Aufruf, die Gesamtzeit mit aufgerufenen Funktionen und die Gesamtzeit mit aufgerufenen Funktionen pro Aufruf stehen.
Man kann sich die Profile-Daten aber auch ausgeben lassen und mit allerlei raffinierten Methoden auswerten. Wie das geht, verrät der Abschnitt über das Profile-Modul in der Python Library Reference.