
\section{Der Profiler}
\label{profiler}

Der Profiler ist kein eigenst"andiges Programm,
sondern ein spezielles Modul, das mit der Unterst"utzung
des Compilers verwendet wird.
Der Profiler ist jedoch ein n"utzliches Werkzeug,
um das Zeitverhalten eigener Programme entscheidend
zu verbessern.

Die Aufgabe des Profilers ist es, Prozedur-Aufrufe zu z"ahlen
und deren Laufzeit zu messen. Dem Programmierer hilft dies
in zwei Punkten:

\begin{itemize}
\item
  Er sieht, welche Prozeduren besonders h"aufig aufgerufen
  werden. Nur in solchen Prozeduren lohnt sich eine
  Optimierung, oder in Ex\-trem\-f"allen sogar die Einbindung
  von Assemblerteilen.
\item
  Ungew"ohnlich zeitaufwendige Prozeduren k"onnen
  ausfindig gemacht werden. Nicht immer erwartet
  man den gr"ossten Aufwand an den angezeigten Orten.
\end{itemize}


\subsection{Aufruf und Bedienung}

Der Profiler wird durch die Compileroption
"`{\tt +p}"' aktiviert.
Mit dieser Option werden zus"atzliche Anweisungen
in den Code eingef"ugt, um die ge"-w"unsch\-ten
Messwerte zu bekommen. Beim Linken
werden automatisch die ben"otigten Moduln miteingebunden.
Das vollst"andig gelinkte Programm ist nun wie
gewohnt lauf"|f"ahig. Durch die Messung wird die
Absolutzeit des Programmlaufs nat"urlich erh"oht, in
Extremf"allen l"auft ein Programm 5 mal langsamer ab.
Nach dem Programmende hat es im aktuellen Verzeichnis
eine Datei mit dem gleichen Namen des abgelaufenen
Programms, erweitert um die Endung "`{\tt .prf}"'. Diese
enth"alt die Messdaten des Programms.

Diese Datei ist eine reine ASCII-Datei, die problemlos
in den Editor geladen oder ausgedruckt werden kann.\footnote{Es
gilt allerdings zu beachten, dass die Zeilenl"ange dieser
Datei {\em immer\/} mehr als 80 Zeichen betr"agt}
Soll sie f"ur Vergleiche mit verschiedenen Optimierungen
herangezogen werden, muss sie vor einem erneuten Programmlauf
gesichert werden; eine bereits bestehende Datei gleichen Namens
wird ohne Warnung "uberschrieben.

Die Bedienung des Profilers besteht also nur aus der
Angabe von
der Compileroption beim "Ubersetzen.
Die Handhabung des Programms "andert sich in keiner Weise
und einzig die Erzeugung der Profiler-Ausgabedatei erinnert daran,
dass eine Messung durchgef"uhrt wurde.

\begin{warning}
Da das Profiler-Modul im \far-Modell compiliert
ist, kann ein solches Programm niemals reentrant sein.
Davon abgesehen ist es wie gewohnt ablauf"|f"ahig.
\end{warning}

Als Beispiel betrachten wir folgendes Programm:
\begin{alltt}
MODULE prog;

IMPORT Modul1;

CONST loops=1000;

PROCEDURE Lokal;
VAR i:CARDINAL;
BEGIN
 FOR i:=1 TO loops DO Modul1.AddSchleife; END;
END Lokal;

BEGIN
 Lokal;
END prog.
\end{alltt}

~\hrulefill~

\begin{alltt}
DEFINITION MODULE Modul1;

PROCEDURE AddSchleife;

END Modul1.
\end{alltt}

~\hrulefill~

\begin{alltt}
IMPLEMENTATION MODULE Modul1;

CONST loops=10000;

PROCEDURE AddSchleife;
VAR a,b,c,i:CARDINAL;
BEGIN
 b:=5; c:=7;
 FOR i:=1 TO loops DO a:=b+c; END;
END AddSchleife;

END Modul1.
\end{alltt}

Nach Beendigung des obigen Programms enth"alt die Datei
{\tt prog.prf} die folgenden Tabellen:

\begin{alltt}\smalltt\renewcommand{\baselinestretch}{0.8}
Modul Modul1
~~~~~~~~~~~~

Anteil|    Prozedur selbst:  |    Prozedur gesamt:  |  Anzahl  | Prozedur
  %   |   Zeit   |Zeit/Aufruf|   Zeit   |Zeit/Aufruf|  Aufrufe |
------+----------+-----------+----------+-----------+----------+---------
100.0 |  17454.2 |     17.45 |  17454.2 |     17.45 |     1000 | AddSchleife
  0.0 |      0.0 |      0.01 |      0.0 |      0.01 |        2 | <Modul1>
------+----------+-----------+----------+-----------+----------+---------


Modul prog
~~~~~~~~~~
Anteil|    Prozedur selbst:  |    Prozedur gesamt:  |  Anzahl  | Prozedur
  %   |   Zeit   |Zeit/Aufruf|   Zeit   |Zeit/Aufruf|  Aufrufe |
------+----------+-----------+----------+-----------+----------+---------
 99.7 |      7.4 |      7.43 |  17476.1 |  17476.14 |        1 | Lokal
  0.3 |      0.0 |      0.01 |  17476.2 |   8738.09 |        2 | <prog>
------+----------+-----------+----------+-----------+----------+---------


Gesamtes Programm
~~~~~~~~~~~~~~~~~
Anteil|    Prozedur selbst:  |    Prozedur gesamt:  |  Anzahl  | Prozedur
  %   |   Zeit   |Zeit/Aufruf|   Zeit   |Zeit/Aufruf|  Aufrufe | (Modul)
------+----------+-----------+----------+-----------+----------+---------
100.0 |  17454.2 |     17.45 |  17454.2 |     17.45 |     1000 | AddSchleife (Modul1)
  0.0 |      7.4 |      7.43 |  17476.1 |  17476.14 |        1 | Lokal (prog)
  0.0 |      0.0 |      0.01 |  17476.2 |   8738.09 |        2 | <prog> (prog)
  0.0 |      0.0 |      0.01 |      0.0 |      0.01 |        2 | <Modul1> (Modul1)
------+----------+-----------+----------+-----------+----------+---------
\end{alltt}\renewcommand{\baselinestretch}{1}

Das Programm in diesem Beispiel besteht aus dem Programm {\tt prog},
welches das Modul {\tt Modul1} verwendet. Der Profiler erzeugt f"ur jedes
Modul eine eigene Tabelle, in der nur diejenigen Prozeduren aufgef"uhrt sind,
die zu diesem Modul geh"oren. Danach folgt eine Tabelle, in der die Prozeduren
aller Moduln aufgef"uhrt sind.

Die erste Spalte jeder Tabelle zeigt an, wie gross der Anteil einer Prozedur an
der Ausf"uhrungszeit des Moduls bzw.\ des Programms ist.
Dabei werden nat"urlich immer nur diejenigen Moduln ber"ucksichtigt,
die mit der Option "`{\tt +p}"' compiliert wurden.

Die zweite und dritte Spalte geben Auskunft "uber die Zeit in Millisekunden,
die in einer Prozedur
verbraucht wurde. Dabei wird nur die tats"achlich
in dieser Prozedur verbrauchte
Zeit gemessen. Darin ist die Zeit, die zum Aufruf
einer anderen Prozedur verwendet
wird, sowie die in der anderen Prozedur verbrauchte Zeit nicht enthalten.

W"ahrenddem
die zweite Spalte die Gesamtzeit aller Aufrufe enth"alt, ist in der dritten
Spalte die durchschnittliche Zeit pro einzelnen
Prozeduraufruf enthalten. Wie man
aus der ersten Zeile der ersten Tabelle entnehmen kann,
verbraucht die Prozedur
{\tt AddSchleife} total etwa 17.5 Sekunden CPU-Zeit.
Diese Prozedur wird 1000 Mal aufgerufen,
und somit ergibt sich eine durchschnittliche
Ausf"uhrungszeit von 0.0175 Sekunden.

Die vierte und f"unfte Spalte enthalten die Gesamtzeit,
wiederum in Millisekunden, die in einer Prozedur
verbraucht wird. Darin enthalten ist auch die Zeit, die f"ur den Aufruf einer
anderen Prozedur ben"otigt wird,
sowie die in dieser anderen Prozedur ben"otigten
Zeit.

Den Unterschied zwischen der Zeit in der zweiten und
der vierten Spalte
wird bei der Prozedur {\tt Lokal} deutlich.
Diese Prozedur ruft 1000 mal die Prozedur
{\tt AddSchleife} auf. F"ur die Ausf"uhrung der
{\tt FOR}-Schleife selbst werden 0.007 Sekunden
verbraucht (siehe Spalte 2). Die Gesamtzeit ist aber
17.476 Sekunden, weil darin
auch die in Prozedur {\tt AddSchleife} verbrauchte Zeit enthalten ist.

Eine genau Rechnung zeigt nun, dass die Zeit f"ur {\tt Lokal}
plus die Zeit f"ur {\tt AddSchleife}
(0.007+17.454=17.461) kleiner als die
Gesamtzeit von {\tt Lokal} (17.476) ist.
Die Differenz (17.476-17.461=0.015) ist diejenige Zeit,
die f"ur Aufruf und R"ucksprung
der Prozedur {\tt AddSchleife} gebraucht wird.

Die sechste Spalte enth"alt die Zahl der Aufrufe einer Prozedur. Etwas komisch
mutet die Zahl 2 bei den Modulinitialisierungsteilen an. Dies h"angt damit
zusammen, dass jedes Modul neben dem Initialisierungsteil
auch einen {\tt CLOSE}-Teil
besitzt. Der Profiler ist nicht in der Lage,
diese beiden Teile auseinanderzuhalten.
Die Zeit, die bei {\tt ModuleInit} angegeben wird,
beinhaltet also die Summe der verbrauchten
Zeit des Initialisierungsteils und des {\tt CLOSE}-Teils.

Die letzte Spalte enth"alt den Namen der Prozedur.
In der letzten Tabelle wird
der Prozedurname durch den Modulnamen erg"anzt.

\mtwo\ erlaubt es, dass lokale Prozeduren verschiedener
G"ultigkeitsbereiche gleiche Namen haben k"onnen.
In der Profilerausgabe werden dann zwei Zeilen den gleichen Prozedurnamen
in dieser Spalte enthalten. Dies l"asst sich zurzeit nicht vermeiden.
Falls die Unterscheidung der Prozeduren durch ihr Zeitverhalten
nicht m"oglich ist, m"ussen  Sie
die Prozeduren so umbenennen, dass die Namen eindeutig sind.


Die vom Profiler gemessenen Zeiten sind sehr genau. Die Zeitmessung erfolgt
mit Hilfe eines Timers im CIA-Baustein. Damit w"are eine Zeitmessung, die
auf ein paar Microsekunden genau ist, m"oglich.
Durch den Overhead, der durch die
Messung selbst produziert wird, wird die Genauigkeit etwas gemindert.
Durch eine geschickte Anordnung der Messinstruktionen
wird trotzdem eine Genauigkeit
der Messung auf etwa 100 Microsekunden erreicht. Dem Multitasking auf dem
Amiga wird ebenfalls Rechnung getragen.
Der Timer wird bei jedem Wechsel zu einem
anderen Task ausgeschaltet und erst wieder eingeschaltet,
wenn wieder ein Wechsel
zu diesem Task erfolgt!
Ein Grundsatz des Profilers ist, dass nur die CPU-Zeit im eigenen Prozess
gemessen wird.
Dies sieht man sehr deutlich, wenn man die zwei folgenden Programme
vergleicht:

\begin{alltt}
MODULE loop;

VAR
 i:LONGINT;
BEGIN
 FOR i:=1 TO 3500000 DO END;
 (*ca. 4 Sekunden (Amiga 3000, 25MHz, AmigaDOS 2.0)*)
END loop.
\end{alltt}

\begin{alltt}
MODULE delay;

IMPORT DosL;

VAR
 i:LONGINT;
BEGIN
 FOR i:=1 TO 3500000 DO END;
  (*ca. 4 Sekunden (Amiga 3000, 25MHz, AmigaDOS 2.0)*)
 DosL.Delay(4*50);
  (*nochmals 4 Sekunden*)
END delay.
\end{alltt}

Die Laufzeit des ersten Programms ist 4 Sekunden, die des zweiten Programms ist
8 Sekunden. Vergleicht man nun die Profilerausgaben der beiden Programme, dann
sieht man fast keinen Unterschied:

\begin{alltt}\smalltt\renewcommand{\baselinestretch}{0.8}
Modul loop
~~~~~~~~~~
Anteil|    Prozedur selbst:  |    Prozedur gesamt:  |  Anzahl  | Prozedur
  %   |   Zeit   |Zeit/Aufruf|   Zeit   |Zeit/Aufruf|  Aufrufe |
------+----------+-----------+----------+-----------+----------+---------
100.0 |   3966.8 |   1983.42 |   3966.8 |   1983.42 |        2 | <loop>
------+----------+-----------+----------+-----------+----------+---------


Gesamtes Programm
~~~~~~~~~~~~~~~~~
Anteil|    Prozedur selbst:  |    Prozedur gesamt:  |  Anzahl  | Prozedur
  %   |   Zeit   |Zeit/Aufruf|   Zeit   |Zeit/Aufruf|  Aufrufe | (Modul)
------+----------+-----------+----------+-----------+----------+---------
100.0 |   3966.8 |   1983.42 |   3966.8 |   1983.42 |        2 | <loop> (loop)
------+----------+-----------+----------+-----------+----------+---------
\end{alltt}\renewcommand{\baselinestretch}{1}

\begin{alltt}\smalltt\renewcommand{\baselinestretch}{0.8}
Modul delay
~~~~~~~~~~~
Anteil|    Prozedur selbst:  |    Prozedur gesamt:  |  Anzahl  | Prozedur
  %   |   Zeit   |Zeit/Aufruf|   Zeit   |Zeit/Aufruf|  Aufrufe |
------+----------+-----------+----------+-----------+----------+---------
100.0 |   3967.0 |   1983.50 |   3967.4 |   1983.71 |        2 | <delay>
------+----------+-----------+----------+-----------+----------+---------


Gesamtes Programm
~~~~~~~~~~~~~~~~~
Anteil|    Prozedur selbst:  |    Prozedur gesamt:  |  Anzahl  | Prozedur
  %   |   Zeit   |Zeit/Aufruf|   Zeit   |Zeit/Aufruf|  Aufrufe | (Modul)
------+----------+-----------+----------+-----------+----------+---------
100.0 |   3967.0 |   1983.50 |   3967.4 |   1983.71 |        2 | <delay> (delay)
------+----------+-----------+----------+-----------+----------+---------
\end{alltt}\renewcommand{\baselinestretch}{1}

Warum fehlen beim Programm {\tt delay} 4 Sekunden?
Dies liegt daran, dass die Prozedur
{\tt Delay} w"ahrend den 4 Sekunden den Prozessor freigibt.
In dieser Zeit k"onnen
andere Tasks ausgef"uhrt werden. Sind keine da, besch"aftigt sich das
Betriebssystem mit sich selbst.


