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:
Nach Beendigung des obigen Programms enthält die Datei prog.prf die folgenden Tabellen:
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:
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:
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.