17.5 Zeitmessung von Programmen 

Gerne werden vor der Fertigstellung der Software die einen oder anderen Laufzeitoptimierungen am Quellcode durchgeführt. Ob dieses Tuning des Codes überhaupt Sinn macht, lässt sich mithilfe von Laufzeitanalysen bestimmen. Solche Analysen durchzuführen, ist wesentlich komplizierter als man denkt. Funktionen der <time.h>-Bibliothek können höchstens mit einer einfachen Wanduhr-Analyse mithalten, denn es müssen eigentlich auch die unterschiedlichsten Auslastungen des Systems beachtet werden. Und gerade das macht es schwierig, die Laufzeit von nur einer Anwendung zu ermitteln. Noch ein wenig schwieriger dürfte das Unterfangen sein, die Laufzeit von einzelnen Funktionen bzw. Codeabschnitten zu ermitteln. Zum Glück sind hierfür sehr effektive Tools zur Laufzeit- und Profiling-Analyse entwickelt worden, von denen Sie im folgenden Abschnitt drei Anwendungen etwas näher kennen lernen werden:

TIME oder /usr/time – Allgemeine Laufzeitermittlung von Prozessen

GPROF – Laufzeitermittlung einzelner Funktionen

GCOV – Laufzeitermittlung, wie häufig einzelne Zeilen ausgeführt werden.

17.5.1 Einfache Zeitmessung mit TIME – Laufzeit von Prozessen 

Für eine einfache Zeitmessung der Laufzeit von einzelnen Prozessen lässt sich TIME verwenden. TIME eignet sich hervorragend, um sich einen groben Überblick über die Laufzeit des Prozesses zu machen. Die allgemeine Laufzeitbestimmung mit TIME wird gerne verwendet, wenn der Quellcode mit eingeschaltetem Optimizer übersetzt wurde. Als einfaches Beispiel sei hier ein Quellcode namens optimize.c verwendet.

$ gcc -o optimize optimize.c
$ time ./optimize
real    0m5.841s
user    0m0.210s
sys     0m0.430s

Hier bekommen Sie von TIME drei verschiedene Zeiten mit der folgenden Bedeutung zurück:

real – Die gesamte verstrichene Ausführungszeit ab Ausführung der Kommandozeileneingabe

user – Die CPU-Zeit für Benutzerfunktionen, genauer die Zeit, welche die Anwendung im User-Level verbracht hat

sys – Die CPU-Zeit für Systemcalls; dies ist die Zeit, welche die Anwendung im Kernel-Level verwendet hat.

Hierzu sei nun derselbe Code mit Optimizer -O3 verwendet:

$ gcc -O3 -o optimize optimize.c
$ time ./optimize
real    0m7.779s
user    0m0.120s
sys     0m0.420s

Sie sehen, dass hiermit die CPU-Zeit für den Benutzerbereich verringert, aber dadurch die gesamte Ausführungszeit der Anwendung erhöht wurde. Leider ist hier keine genaue Aussage zu treffen, was hierbei länger gedauert hat – da es noch mehrere Prozesse auf dem System gibt, die ebenfalls Laufzeit (die CPU) benötigen und somit diese Zeitmessung immer ein wenig verfälschen können. Für eine genauere Zeitanalyse kommen Sie um das Profiling mittels GPROF zur Laufzeitmessung nicht herum.

17.5.2 Profiling mit GPROF – Laufzeit von Funktionen 

Mit TIME haben Sie gewiss ein einfaches Verfahren für eine Zeitanalyse des gesamten Programms. Aber sobald es sich um das Codetuning einzelner Funktionen handelt, taugt TIME nicht mehr viel. Denn wollen bzw. müssen Sie nur einzelne Funktionen optimieren, bringt Ihnen eine Zeitanalyse des gesamten Programms recht wenig, insbesondere wenn es darum geht, um wie viel schneller denn die einzelnen Funktionen nun ausgeführt wurden. Für solche Aufgaben werden Programmprofile (auch als Leistungsdiagramm bezeichnet) benötigt. Um ein solches Profil zu erzeugen, sind folgende Schritte nötig:

Beim Übersetzen des Quellcodes muss ein Profil erzeugt werden.

Dann wird das speziell mit Profilen übersetzte Programm ausgeführt, woraufhin Sie ein Programmprofil erhalten.

Dieses Programmprofil können Sie letztendlich mit dem Profiler GPROF auswerten.

Ein Profil für gprof erzeugen

Zuerst müssen Sie den Quellcode für ein Profil mit der Option -pg übersetzen:

$ gcc -pg -o fraktal fraktal.c berechnung.c \
  -L/usr/X11R6/lib -lX11  

Die so erzeugte ausführbare Datei ist natürlich erheblich größer als die Anwendung, die ohne die Compiler-Option -pg übersetzt wurde. Damit haben Sie quasi das Programm für die weiteren Schritte der Laufzeitanalyse mit GPROF eingerichtet.

Im nächsten Schritt müssen Sie diese Anwendung ausführen, womit ein Programmprofil mit dem Namen gmon.out erzeugt wird.

$ ./fraktal
$ ls -l gmon*
-rw-r--r--    1 tot   users       429 2004–04–12 13:41 gmon.out

Jetzt, im letzten Schritt, müssen Sie die Daten von gmon.out analysieren. Dazu müssen Sie lediglich GPROF mit dem Programm, das analysiert werden soll, als Argument übergeben. Anschließend gibt GPROF die Analyse auf die Standardausgabe aus, weshalb sich hierbei eine Umleitung in eine Datei hervorragend eignen würde (hier finden Sie die Ausgabe von GPROF in der Textdatei mytest_profil.txt).

$ gprof ./fraktal > mytest_profil.txt

Die nun folgende Ausgabe (oder, falls die Datei umgeleitet wurde, die Datei) besteht aus zwei Teilen:

dem flachen Profil, das auflistet, wie sich die Programmzeit auf die einzelnen Funktionen verteilt

dem Aufrufgraph-Profil, worin sich die aufrufenden und aufgerufenen Funktionen befinden

Das flache Profil

Im flachen Profil finden Sie aufgelistet, wofür die Programmzeit verwendet wurde. Der Zeitaufwand wird dabei für jede Funktion pro Aufruf berechnet. Am flachen Profil erkennen Sie die Funktionen, die am meisten Zeit verbrauchen und die es dann auch wert sind (zugegeben, es gibt auch Funktionen, die eben etwas mehr tun als andere ...), optimiert zu werden. Ein Beispiel des flachen Profils:

Flat profile:
Each sample counts as 0.01 seconds.
 %  cumulative  self             self     total
time  seconds  seconds   calls   s/call   s/call  name
99.90    30.91   30.91  798720     0.00     0.00  farbe
 0.06    30.93    0.02       1     0.02    30.94  fraktal
 0.03    30.94    0.01      52     0.00     0.59  berechne
 0.00    30.94    0.00       3     0.00     0.00  ermittle_shifts
 0.00    30.94    0.00       2     0.00     0.00  push_para
 0.00    30.94    0.00       1     0.00     0.00  init_colors
 0.00    30.94    0.00       1     0.00     0.00  posit

In der Ausgabe des flachen Profils lässt sich gleich erkennen, dass die Funktion farbe() die meiste Zeit (99.90 %) verwendet, weshalb diese Funktion in der Praxis auch ein Kandidat für die Codeoptimierung wäre. Für jede Funktion wird ein Zeileneintrag erstellt und entsprechend der benötigten Ausführungszeit sortiert. Die Zeit, die für die Interaktionen innerhalb von Funktionen verbraucht wird, wird allerdings nicht mitgezählt! Jede Funktion enthält bei dem Eintrag im flachen Profil folgende Informationen:

%time – Anteil in Prozent der gesamten Ausführungszeit des Programms für die Ausführung der Funktion.

cummulative seconds – Gesamtzeit in Sekunden, die für die Ausführung der Funktionen und alle im flachen Profil vorher aufgeführten Funktionen benötigt wurde.

self seconds – Gesamtzeit in Sekunden, die für die Ausführung der Funktionen benötigt wurde, ohne die Zeit, die für die Nachkommen der Funktion verbraucht wurde.

calls – Aufrufe der Funktion während des kompletten Programmablaufs

self ms/call – Durchschnittlicher Zeitaufwand für die Ausführung der Funktion in Millisekunden, der sich aus allen Funktionsaufrufen bildet, ohne die Funktionen, die eventuell aus dieser Funktion aufgerufen werden.

total ms/call – Durchschnittlicher Zeitaufwand für einen Funktionsaufruf mitsamt der weiteren Funktionen, die diese Funktion aufrufen.

name – Name der Funktion

Im Großen und Ganzen kann man zum Programm oben sagen, dass hier eine Codeoptimierung nicht dem Aufwand trotzen kann, den man hierfür aufwenden muss. Rentabel sollte es hierbei werden, wenn eine Funktion mehrere Sekunden benötigt. Um hierbei den Code einer Funktion zu verbessern, haben Sie folgende Möglichkeiten:

Den Algorithmus verbessern, damit der Code schneller abläuft.

Die Routine so umschreiben, dass eine Funktion nicht so häufig aufgerufen werden muss.

Funktionen, die relativ häufig aufgerufen werden, können auch direkt im Code der aufrufenden Funktion eingebaut werden.

Compiler-Optionen zur Optimierung des Codes verwenden

Das Aufrufgraph-Profil

Für eine noch detailliertere Auflistung des Programmprofils lohnt sich ein Blick in das Aufrufgraph-Profil (auch strukturiertes Profil genannt). Hier erhalten Sie noch ein wesentlich genaueres Programmprofil. Hier wird für jede einzelne Funktion angezeigt:

Anteil der Gesamtlaufleistung in Prozent (time).

Aufrufende Funktion, und zwar von welchen Funktionen eine bestimmte Funktion wie oft aufgerufen wurde.

Aufgerufene Funktionen. Hier wird gezeigt, welche Funktion die aktuelle Funktion wiederum wie oft aufgerufen hat.

Um hierbei den Überblick zu bewahren, finden Sie auch einen Indexeintrag zu jeder Funktion in diesem Profil. Betrachten Sie z. B. im anschließenden Aufrufgraph-Profil die erste Funktion mit dem Index [1], können Sie ganz unten im Profil den Namen der Funktion des entsprechenden Indexeintrags herauslesen. Im Beispiel wäre die Funktion mit dem Index [1] fraktal(), mit dem Index [3] berechne() usw. Hierzu das strukturierte Profil des Programmbeispiels fraktal:

Call graph (explanation follows)
granularity: each sample hit covers 4 byte(s) for 0.03 % of 30.94 seconds
index % time    self  children    called     name
                0.02   30.92       1/1       main [2]
[1]    100.0    0.02   30.92       1         fraktal [1]
                0.01   30.91      52/52      berechne [3]
-----------------------------------------------
                                             <spontaneous>
[2]    100.0    0.00   30.94                 main [2]
                0.02   30.92       1/1       fraktal [1]
                0.00    0.00       3/3       ermittle_shifts [5]
                0.00    0.00       2/2       push_para [6]
                0.00    0.00       1/1       init_colors [7]
                0.00    0.00       1/1       posit [8]
---------------------------------------------
                0.01   30.91      52/52      fraktal [1]
[3]     99.9    0.01   30.91      52         berechne [3]
               30.91    0.00  798720/798720  farbe [4]
---------------------------------------------
               30.91    0.00  798720/798720  berechne [3]
[4]     99.9   30.91    0.00  798720         farbe [4]
---------------------------------------------
                0.00    0.00       3/3       main [2]
[5]      0.0    0.00    0.00       3         ermittle_shifts [5]
---------------------------------------------
                0.00    0.00       2/2       main [2]
[6]      0.0    0.00    0.00       2         push_para [6]
---------------------------------------------
                0.00    0.00       1/1       main [2]
[7]      0.0    0.00    0.00       1         init_colors [7]
---------------------------------------------
                0.00    0.00       1/1       main [2]
[8]      0.0    0.00    0.00       1         posit [8]
---------------------------------------------
...
...
Index by function name
   [3] berechne                [1] fraktal
   [6] push_para               [5] ermittle_shifts
   [7] init_colors             [4] farbe
   [8] posit

17.5.3 Analyse mit GCOV 

Welche Codeteile innerhalb des Programms, genauer, innerhalb einer Funktion wie häufig ausgeführt wurden, kann mit GCOV ausgewertet werden. Damit wird eine Abdeckungsanalyse ausgeführt, die mitzählt, wie oft eine Programmzeile durchlaufen wurde. Eine solche Abdeckungsanalyse wird in den folgenden Schritten erstellt:

Die Angabe des Listings fraktal.c von 71,01 % sagt aus, dass der komplette Quellcode bis auf 29,99 % der 207 Zeilen ausgeführt wurde. Beim zweiten Quellcode, der berechnung.c, ist die Abdeckung des Quellcodes gar 100 %. Das heißt, hier wurde jede Zeile ausgeführt. Das alleine sagt natürlich noch nichts aus. Daher müssen Sie auch noch die erzeugten Dateien berechnung.c.gcov und fraktal.c.gcov genauer unter die Lupe nehmen. Ein Ausschnitt aus der Abdeckungsdatei fraktal.c.gcov sieht etwa so aus (ein für das Buch angepasstes Beispiel):

...
#####:  336: rueck = posit();
    -:  337: }
   52:  338: if (rueck == NORMAL_WEITER) {
   52:  339:         parainfo.br_par = breite;
   52:  340:         parainfo.y_par = yr0;
   52:  341:         parainfo.x_par = xr0 + xdelta * breite * 
                     (segmentzahl - 1);
   52:  342: parainfo.delx_par = xdelta;
   52:  343: parainfo.dely_par = ydelta;
   52:  344: laenge = berechne(parainfo, punktfeld);
   52:  345: prozess.xbb     = breite  * (segmentzahl - 1);
   52:  346: prozess.ybb     = 0;
   52:  347: segmentzahl--;
798772: 348: for(ptr = punktfeld; laenge; laenge--) {
    -:  349: /* Punkt fuer Punkt zeichnen: */
798720: 350: XSetForeground(display, gcs,
              SETZE_FARBE(*ptr++));
798720: 351: XDrawPoint(display, ZIEL, gcs, 
               prozess.xbb, prozess.ybb);
798720: 352: if (++prozess.ybb >= MAXY) { /* aktualisieren */
  1040: 353: prozess.ybb = 0;
  1040: 354: prozess.xbb++;
    -:  355: }
    -:  356: }
    -:  357: #ifdef BACKUP
    -:  358: XCopyArea(display, backup, windowId, gcs,
             prozess.xbb - breite, 0,
    -:  359: breite, MAXY, prozess.xbb - breite, 0);
    -:  360: #endif
    -:  361: }
    -:  362: }
    1:  363: printf("Zeitdauer: %d Sekunden\n", 
             time(NULL) - zeit);
    1:  364: XFlush(display); /* Displaypuffer raeumen */
...

Dies lässt sich folgendermaßen lesen. Ganz links finden Sie die Anzahl der Durchläufe, wie oft diese Codezeile ausgeführt wurde. Steht hier #####, bedeutet dies, dass diese Codezeile nicht ausgeführt wurde. Hier könnten Sie z. B. die for()-Schleife optimieren, die 798772 mal aufgerufen wird und worin auch 798772 mal ein Pixel gezeichnet wird. Ein kurzer Blick in die Datei berechnung.c.gov zeigt weitere Optimierungsmöglichkeiten:

   798720:   44:   a = xr0; b = yr0; /* a + bi = Z0 */
   798720:   45:   zaehler = 0;
   798720:   46:   qua = a * a; qub = b * b;
839599651:   47:   do {
839599651:   48:   b = 2 * a * b - yr0; /* neuer Imaginaerteil */
839599651:   49:   a = qua - qub - xr0; /* neuer Realteil      */
839599651:   50:   qu=(qua=a* a) + (qub = b * b); /* qu = |Z| */
839599651:   51:   }
        -:   52:   while(qu<DIVERGENZGRENZE&&qu>KONVERGENZGRENZE
        -:   53:          && zaehler++ < ZYKLEN);
   798720:   54:   return(zaehler & 0xff);

Die do-while-Schleife wird hier 839599651 mal durchlaufen. Dabei lässt sich sicherlich mit einigen mathematischen Operationen und Compiler-Flags noch etwas Leistung herauskitzeln. Häufig aufgerufene Berechnungen und Funktionsaufrufe gilt es, besonders im Auge zu behalten und eventuell zu optimieren.

Zusammenfassung

Natürlich lässt sich zu den Tools GPROF und GCOV noch eine Menge mehr schreiben. Aber die grundlegenden Arbeiten dieser Werkzeuge wurden hier erwähnt und hoffentlich auch verstanden. Sie wissen jetzt zumindest, wie Sie kritische Stellen im Quellcode finden können, um diese zu optimieren. Wie Sie Programme und Quellcode optimieren können, ist, bis auf bestimmte Optionen des Compilers, nicht Diskussionspunkt dieses Buchs.