Entwicklertools: perf

Moderator: Moderatoren2

Antworten
Ed von Schleck
Soldat
Soldat
Beiträge: 15
Registriert: Mi 12. Dez 2012, 13:21

Entwicklertools: perf

Beitrag von Ed von Schleck »

Hallo wieder einmal,

im nächsten Teil des Einsteigerguides werden wir ein Tool benötigen, das und dabei hilft, festzustellen, welche Funktionen aufgerufen werden, von wem sie aufgerufen werden, wie oft und vor allem: Wie viel Zeit von der gesamten Ausführungszeit in welcher Funktion zugebracht wird.

Programme von oben genannten Art nennt man Profiler. In der Linux-Welt gibt es da einige: OProfile zum Beispiel oder gprof. Ich stelle hier ein recht neues Tool vor, das vor allem von Linux-Kernel-Entwicklern entwickelt wird, aber auch für uns Normalo-Anwendungs-Entwickler sehr brauchbar ist. Es heißt perf. Ich habe es ausgewählt, weil ich es für sehr einfach zu bedienen halte. Außerdem ist der Overhead (der Aufwand, der betrieben werden muss und daher das Programm, dass man untersuchen will, verlangsamt) geringer als in den anderen Profilern.

Zuvor ein paar Worte zur Erklärung: Nein, ich glaube nicht, dass das wesentliche Problem, das man im ASC-Quellcode lösen muss, die Performance ist. Aber ich glaube, dass man mit Profilern einen guten Einblick in ein Programm bekommen kann. Zudem findet man leicht einen Einstieg in einzelne Teile des Codes. Jedenfalls geht es mir so :)

Die Installation ist, wie bei allen solchen Tools unter Linux, sehr einfach: Benutzt Euren Paket-Manager (apt-get oder yum oder so).

Um perf mitzuteilen, dass es ASC profilen soll, schreibt man einfach (ich setze voraus, dass Ihr Euch gerade in dem Verzeichnis ~/code/asc befindet, oder eben dort, wohin Ihr den ASC-Quellcode geclont habt):

Code: Alles auswählen

perf record source/unix/asc/asc
Das Programm startet wie üblich. Wenn Ihr es wieder beendet, seht Ihr eine Statusmeldung von perf, die ungefähr so aussieht:

Code: Alles auswählen

[ perf record: Woken up 5 times to write data ]
[ perf record: Captured and wrote 1.437 MB perf.data (~62778 samples) ]
Alles gut soweit. Um zu sehen, was perf über unseren Code rausbekommen hat, tippt

Code: Alles auswählen

perf report
Es öffnet sich eine sehr spartanische TUI (die Terminal-Äquivalenz zu einer GUI). Wenn man direkt nach dem Staten das Programm wieder beendet hat, könnte es zum Beispiel so aussehen.

Code: Alles auswählen

  8,68%  asc  asc                          [.] tnbufstream::readdata(void*, int, bool)
  5,17%  asc  libc-2.16.so                 [.] __memcpy_ssse3
  4,89%  asc  asc                          [.] tanycompression::readlzwdata(void*, int, bool)
  3,93%  asc  libvorbis.so.0.4.6           [.] mdct_backward
  3,45%  asc  asc                          [.] tnstream::readInt()
  3,01%  asc  libvorbis.so.0.4.6           [.] vorbis_book_decodevv_add
  2,93%  asc  libvorbisfile.so.3.3.5       [.] ov_read_filter
  2,52%  asc  libSDL-1.2.so.0.11.4         [.] 0x0000000000010529
  2,32%  asc  asc                          [.] Surface::read(tnstream&)
  2,22%  asc  libvorbis.so.0.4.6           [.] vorbis_synthesis_blockin
  2,16%  asc  asc                          [.] tn_c_lzw_filestream::readcmpdata(void*, int, bool)
  1,96%  asc  asc                          [.] tanycompression::readdata(void*, int, bool)
  1,81%  asc  asc                          [.] tn_c_lzw_filestream::readdata(void*, int, bool)
  1,58%  asc  libc-2.16.so                 [.] __GI___strcasecmp_l_ssse3
  1,52%  asc  libbz2.so.1.0.6              [.] BZ2_decompress
  1,41%  asc  asc                          [.] zoomSurfaceRGBA(SDL_Surface*, SDL_Surface*, bool)
  1,17%  asc  libogg.so.0.8.0              [.] oggpack_look
  1,04%  asc  [kernel.kallsyms]            [k] clear_page
  0,96%  asc  libvorbis.so.0.4.6           [.] vorbis_book_decodev_add
Gehen wir die Spalten von rechts nach links durch: Die letzte Spalte zeigt den Namen und die Signatur einer Funktion. In manchen Fällen ist der Name der Funktion nicht bekannt, weil sie in einer Bibliothek definiert wurde und wir für diese Bibliothek keine Debug-Symbole installiert haben. Wir brauchen diese jetzt auch nicht unbedingt. Wenn wir wollten, dann könnten wir sie aber installieren - unsere Linux-Distribution, die uns die Bibliotheken zur Verfügung stellt, versorgt uns auch mit den entsprechenden Debug-Paketen. Ich verweise da auf die Wikis von Fedora und Ubuntu, in anderen Distros ist es ähnlich.

Die vorletzte Spalte zeigt den Namen der Bibliothek, aus der die Funktion ist. Wenn die Funktion in ASC selbst definiert wurde, steht da natürlich asc.

Die zweite Spalte zeigt den Namen der Binary, also des Programms, in dem die Funktion ausgeführt wurde. Bei uns ist das nur asc.

Die erste Spalte die die interessanteste für das Performance Profiling: Sie zeigt, wie viel Prozent der Gesamtzeit in eben jener Funktion verbracht wurde. Dabei wird nicht draufaddiert, wie viel Zeit in Funktionen verbracht wird, die diese Funktion aufgerufen hat.

Angenommen, wir interessieren uns nur für den Teil der Funktionen, die in ASC definiert sind, dann navigieren wir mit den Cursortasten ↓ und ↑ über eine Funktion, die in asc definiert ist, und drücken die Taste d. Damit filtern wir alle Funktionen von anderen Quellen aus.

Wollen wir Details über diese Funktion erfahren, dann drücken wir Enter oder →. Man kann sich hier ein paar Dinge anschauen, auf die ich nicht näher eingehen will. Interessant ist vorerst mal nur der erste Punkt - drücken wir wieder Enter oder →.

Hier sehen wir jede Menge Zeug, das Euch vermutlich erst einmal unverständlich ist. Das ist OK :) Auf was Ihr hier blickt, ist der Programmcode der Funktion zusammen mit dem Assembly des entsprechenden Codes. Assembly ist das, was auf der CPU ausgeführt wird. Jedes dieser mov, add, cmp usw. steht für einen Binärcode (01000111...), der vom Prozessor verstanden wird.

Es sei hier mal deutlich gesagt: Es gibt für Euch, wenn Ihr für ASC entwickeln wollt, überhaupt keinen Grund, Assembly zu lernen (außer natürlich, dass es Spaß macht :) ). Trotzdem kann diese Ausgabe hilfreich sein. Sie sagt uns, wo genau die Funktion ihre Zeit verplempert. In der ersten Zeile steht eine Zahl; sie gibt an, wie viel Prozent der Zeit, die in dieser Funktion (über alle Funktionsaufrufe hinweg gerechnet) an genau dieser Instruktion verbraucht wird. perf kennzeichnet besonders teure Instruktionen rot.

(Wer sich jetzt wundert: Brauchen nicht alle Instruktionen gleich viel Zeit? Dem sei gesagt: Seit mindestens 20 Jahren nicht mehr. Erstens entspricht heutzutage eine Instruktion nicht mehr einer Hardwareschaltung, zweitens wird die Programmperformance häufig darüber entschieden, ob Daten im CPU-Cache liegen oder nicht. Wer sich für so etwas interessiert, dem empfehle ich das hervorragende Paper von Ulrich Drepper What Every Programmer Should Know About Memory.)

Wenn man weiß, in welchen Funktionen viel Zeit zugebracht wird, kann man zwei Dinge tun, um den Programmcode zu beschleunigen - erstens: Man macht die Funktion schneller, oder zweitens: Man ruft sie nicht so oft auf. perf report verrät uns bisher aber leider nicht, von welchen Funktionen unsere problematischen Funktionen aufgerufen werden. Aber auch das geht: Machen wir eines neuerliches Profiling unseres Programmes, diesmal so:

Code: Alles auswählen

perf record -g -- source/unix/asc/asc
und rufen nach Beenden des Programms die Ausgabe von perf so auf:

Code: Alles auswählen

perf report -g
Wenn Ich jetzt eine Funktion markieren und Enter drücke, dann sehe öffnet sich ein Zweig. Auf diesem kann ich jeweils die Funktionen markieren, die meine Funktion aufgerufen haben, und wieder Enter drücken. So öffnet sich die ganze sogenannte Callchain für diese Funktion.

Drücke ich E (also SHIFT+e), dann werden alle Callchains aller Funktionen angezeigt. Mit C schließe ich sie wieder.

Wäre es jetzt nicht nett, wenn ich den kompletten Callgraph sehen könnte? Als Grafik, mit Kästchen, Pfeilen und so? Auch dazu gibt es wieder eine Lösung, und natürlich hilft uns unsere Distro (und apt-get oder yum) mit der Installation eines netten kleines Skriptes names gprof2dot. Anders als der Name sagt kann gprof2dot nicht nur mit gprof, sondern auch mit perf oder anderen Profilern erstellte Profile lesen. gprof2dot Wandelt das dann in ein dot-File um. dot ist ein Beschreibungsformat für Graphen, und mit dem Programm dot (das wahrscheinlich mit gprof2dot mitinstalliert wurde, ansonsten müsst Ihr das selber machen). Gebt nun an der Kommandozeile folgendes ein:

Code: Alles auswählen

perf script | gprof2dot -f perf | dot -Tpng -o callgraph.png
Die | nennt man Pipe und schleusen die Ausgabe eines Programms in die Eingabe des nächsten. Wir rufen hier also perf über die Skript-Schnittstelle auf, füttern gprof2dot mit diesen Daten (und sagen dem Programm, dass es sich um perf-Daten handelt). Das Ergebnis übergeben wir dem Programm dot und sagen diesem: Mach eine png-Grapfik draus und nenne sie callgraph.png.

Jetzt habt Ihr eine Datei namens callgraph.png in Eurem Ordner liegen. Das Ergebnis sieht ungefähr so aus:
http://dl.dropbox.com/u/7261613/callgraph.png

Nett, oder? Ich gehe jetzt nicht mehr im Detail auf diesen Callgraph ein, aber wenn Ihr Fragen dazu (oder zu sonstwas) habt, dann postet sie einfach.

In der nächsten Ausgabe unseres Einsteigerguides werden wir perf verwenden, um eine Funktion zu identifizieren, die wir optimieren können. Bis dahin könnt Ihr ja schon ein wenig in den Funktionen von ASC herumstöbern und Euch verschiedene Callgraphs ausgeben lassen für z.B. nur ASC starten und beenden, nur einen Zug machen, nur den Computergegner einen Zug machen lassen, ...

Viel Spaß
Antworten