21.4 Profiling
Eine andere Möglichkeit, sein Programm (oder das von anderen Entwicklern) zu untersuchen, ist das Profiling. Dabei wird untersucht, wie viel Zeit ein Programm mit welchen Tätigkeiten verbringt, welche Funktionen wie oft aufgerufen werden und wie viel Zeit diese dabei benötigen.
Der primäre Einsatzzweck des Profilings ist also kurz gesagt das Performance-Tuning.
21.4.1 Compileroption
Zum Profiling wird ein Programm, der sogenannte Profiler eingesetzt. Unter Linux und BSD ist das standardmäßig der GNU-Profiler gprof. Um diesen jedoch zu nutzen, muss bei der Übersetzung des Quellcodes, ähnlich wie beim GNU-Debugger, die Compileroption für das Profiling (-gp) eingebaut werden.
$ gcc -o myprog myprog.c -pg
Listing 21.24 Beispiel zur Übersetzung mit Profiling
21.4.2 gprof verwenden
Führt man ein für das Profiling übersetztes Programm nun aus, erzeugt dieses Programm im Arbeitsverzeichnis eine Datei namens gmon.out. In dieser sind die Informationen enthalten, die der Profiler benötigt, um dem Entwickler daraus einen Report zu generieren.
Um diese Datei nun zu interpretieren, verwendet man das Tool gprof. Dabei werden sehr viele Informationen auf dem Bildschirm ausgegeben, weshalb man am besten eine Ausgabeumlenkung verwendet und sich die Ausgabe mit einem Editor ansieht.
$ gprof myprog >report
Listing 21.25 gprof aufrufen
21.4.3 Profiling-Daten lesen
Nachdem man nun einen Profiling-Report erzeugt hat, muss man nur noch wissen, wie dieser Profiling-Report eigentlich zu verstehen ist. Einen Ausschnitt eines fertigen Reports zeigt Ihnen das folgende Listing:
called/total parents index %time self descendents called+self name index called/total children <spontaneous> [1] 100.0 0.01 0.00 write [1] ----------------------------------------------- [2] 0.0 0.00 0.00 4+4 <cycle 1 as a whole> [2] 0.00 0.00 5 imalloc <cycle 1> [9] 0.00 0.00 3 malloc_bytes <cycle 1> [11] ----------------------------------------------- [3] 0.0 0.00 0.00 12+2 <cycle 2 as a whole> [3] 0.00 0.00 13 vfprintf <cycle 2> [6] 0.00 0.00 1 __sbprintf <cycle 2> [468] ----------------------------------------------- ... ... ... % cumulative self self total time seconds seconds calls ms/call ms/call name 100.0 0.01 0.01 write [1] 0.0 0.01 0.00 406 0.00 0.00 mbtowc [4] 0.0 0.01 0.00 20 0.00 0.00 __sfvwrite [457] 0.0 0.01 0.00 20 0.00 0.00 __sprint [458] 0.0 0.01 0.00 13 0.00 0.00 localeconv [5] 0.0 0.01 0.00 13 0.00 0.00 vfprintf <cycle 2> [6] 0.0 0.01 0.00 12 0.00 0.00 __sflush [459] 0.0 0.01 0.00 12 0.00 0.00 __swrite [460] 0.0 0.01 0.00 12 0.00 0.00 fflush [7] 0.0 0.01 0.00 9 0.00 0.00 printf [8]... ...
Listing 21.26 Profiling-Report (Auszug)
Der Report ist in zwei Teile, den call graph und das flat profile, gegliedert. Im oberen Listing ist zunächst ein Auszug aus dem call graph und darunter ein Auszug aus dem flat profile zu sehen.
call graph
Der call graph gibt dem Entwickler Aufschluss darüber, wie viel Zeit eine Funktion und die von ihr aufgerufenen Funktionen benötigt haben. Dabei kann es durchaus vorkommen, dass eine Funktion selbst nicht viel Zeit verbraucht hat, die von ihr aufgerufenen Funktionen jedoch äußerst viel Zeit benötigten. Auf diese Weise lässt sich hervorragend feststellen, an welchen Stellen die Software am langsamsten ist.
Die Spalte index gibt dabei den Index einer Funktion an, und %time gibt den prozentualen Zeitanteil der Gesamtlaufzeit des Programms an, der für diese Funktion verwendet wurde.
self gibt die Zeit an, die die Funktion selbst benötigte, und descendents die Zeit, die für die Funktionen verwendet wurde, die von dieser Funktion aufgerufen wurden.
Die called-Spalte zeigt dem Entwickler, wie oft die Funktion aufgerufen (und dabei von sich selbst aufgerufen (self)) wurde. Die beiden letzten Spalten geben den Funktionsnamen bzw. die Namen der von der Funktion aufgerufenen Funktionen sowie deren Index-Nummer an.
flat profile
Das flat profile gibt Ihnen die gesamte Zeit an, die ein Programm zur Ausführung einer Funktion verwendete. Dabei sind die Funktionen in der Reihenfolge ihres Zeitbedarfs sortiert.
Die erste Spalte gibt dabei eben diesen prozentualen Zeitanteil an, und in Spalte Nummer zwei (cumulative seconds) steht die dafür (und für die von dieser Funktion aufgerufenen Funktionen) notwendige Zeit in Sekunden. Die Spalte self seconds gibt hingegen nur die Zeit an, die für die Funktion selbst verbraucht wurde, was also die von ihr aufgerufenen Funktionen ausschließt.
calls ist die Anzahl der Aufrufe einer Funktion. self ms/call steht für die Millisekunden, die für einen Aufruf der Funktion selbst gebraucht wurden, und total ms/call steht für die Millisekunden, die für einen Aufruf der Funktion sowie der von ihr aufgerufenen Funktionen gebraucht wurden. Die letzte Spalte gibt wie beim call graph den Funktionsnamen sowie deren call graph-Index an.