Nächste Seite: Der Library-Linker (M2LibLink) Aufwärts: Der Profiler Vorherige Seite: Der Profiler

## Aufruf und Bedienung

Der Profiler wird durch die Compileroption ,,`+p``` aktiviert. Mit dieser Option werden zusätzliche Anweisungen in den Code eingefügt, um die gewünschten Messwerte zu bekommen. Beim Linken werden automatisch die benötigten Moduln miteingebunden. Das vollständig gelinkte Programm ist nun wie gewohnt lauffähig. Durch die Messung wird die Absolutzeit des Programmlaufs natürlich erhöht, in Extremfällen läuft 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 ,,`.prf```. Diese enthält die Messdaten des Programms.

Diese Datei ist eine reine ASCII-Datei, die problemlos in den Editor geladen oder ausgedruckt werden kann.4.1Soll sie für Vergleiche mit verschiedenen Optimierungen herangezogen werden, muss sie vor einem erneuten Programmlauf gesichert werden; eine bereits bestehende Datei gleichen Namens wird ohne Warnung überschrieben.

Die Bedienung des Profilers besteht also nur aus der Angabe von der Compileroption beim Übersetzen. Die Handhabung des Programms ändert sich in keiner Weise und einzig die Erzeugung der Profiler-Ausgabedatei erinnert daran, dass eine Messung durchgeführt wurde.

Als Beispiel betrachten wir folgendes Programm:

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

`DEFINITION MODULE Modul1;
PROCEDURE AddSchleife;
END Modul1.
`

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

Nach Beendigung des obigen Programms enthält die Datei `prog.prf` die folgenden Tabellen:

`
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)
---+-----+------+-----+------+-----+-----
`

Das Programm in diesem Beispiel besteht aus dem Programm `prog`, welches das Modul `Modul1` verwendet. Der Profiler erzeugt für jedes Modul eine eigene Tabelle, in der nur diejenigen Prozeduren aufgeführt sind, die zu diesem Modul gehören. Danach folgt eine Tabelle, in der die Prozeduren aller Moduln aufgeführt sind.

Die erste Spalte jeder Tabelle zeigt an, wie gross der Anteil einer Prozedur an der Ausführungszeit des Moduls bzw. des Programms ist. Dabei werden natürlich immer nur diejenigen Moduln berücksichtigt, die mit der Option ,,`+p``` compiliert wurden.

Die zweite und dritte Spalte geben Auskunft über die Zeit in Millisekunden, die in einer Prozedur verbraucht wurde. Dabei wird nur die tatsächlich 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ährenddem die zweite Spalte die Gesamtzeit aller Aufrufe enthält, 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 `AddSchleife` total etwa 17.5 Sekunden CPU-Zeit. Diese Prozedur wird 1000 Mal aufgerufen, und somit ergibt sich eine durchschnittliche Ausführungszeit von 0.0175 Sekunden.

Die vierte und fünfte Spalte enthalten die Gesamtzeit, wiederum in Millisekunden, die in einer Prozedur verbraucht wird. Darin enthalten ist auch die Zeit, die für den Aufruf einer anderen Prozedur benötigt wird, sowie die in dieser anderen Prozedur benötigten Zeit.

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

Eine genau Rechnung zeigt nun, dass die Zeit für `Lokal` plus die Zeit für `AddSchleife` (0.007+17.454=17.461) kleiner als die Gesamtzeit von `Lokal` (17.476) ist. Die Differenz (17.476-17.461=0.015) ist diejenige Zeit, die für Aufruf und Rücksprung der Prozedur `AddSchleife` gebraucht wird.

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

Die letzte Spalte enthält den Namen der Prozedur. In der letzten Tabelle wird der Prozedurname durch den Modulnamen ergänzt.

erlaubt es, dass lokale Prozeduren verschiedener Gültigkeitsbereiche gleiche Namen haben können. In der Profilerausgabe werden dann zwei Zeilen den gleichen Prozedurnamen in dieser Spalte enthalten. Dies lässt sich zurzeit nicht vermeiden. Falls die Unterscheidung der Prozeduren durch ihr Zeitverhalten nicht möglich ist, müssen 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äre eine Zeitmessung, die auf ein paar Microsekunden genau ist, möglich. 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:

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

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

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:

`
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)
---+-----+------+-----+------+-----+-----
`

`
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)
---+-----+------+-----+------+-----+-----
`

Warum fehlen beim Programm `delay` 4 Sekunden? Dies liegt daran, dass die Prozedur `Delay` während den 4 Sekunden den Prozessor freigibt. In dieser Zeit können andere Tasks ausgeführt werden. Sind keine da, beschäftigt sich das Betriebssystem mit sich selbst.

Nächste Seite: Der Library-Linker (M2LibLink) Aufwärts: Der Profiler Vorherige Seite: Der Profiler