Statt hochgezüchteter Prozessoren helfen oft simple Programmiertricks, um Programme zu beschleunigen. Profiler-Tools helfen, sich auf Engpässe zu konzentrieren und keine Entwicklungszeit in Bereichen mit nur geringem Verbesserungspotential zu verschwenden.
Wer nicht gerade den ganzen Tag mit Videospielen verplempert, kommt auch mit langsamerer Hardware klar, die noch dazu Strom spart und die Umwelt schont. Läuft ein Programm auf zweitklassiger Hardware allerdings nicht schnell genug, stellt sich die Frage, wie man es mit möglichst geringem Aufwand schneller macht. Meist reichen ein, zwei gezielte Eingriffe an kritischen Stellen, um 90% der überhaupt möglichen Verbesserungen zu erzielen. Die restlichen 10% erfordern dann meist weitreichende architektonische Umbauarbeiten, die zehnmal so lang dauern und anschließend die Wartung erschweren, sodass erfahrene Entwickler dankend abwinken.
Um diese bottle necks oder hot spots zu finden, bieten sich Profiler an, die aufzeigen, wo ein Programm die meiste Zeit verbringt und die es dem Entwickler erlauben, diese Bereiche gezielt zu verbessern. Bevor aber schweres Geschütz zum Einsatz kommt, lohnt sich meist schon einen Blick auf bereits vorhandene Tools. Setzt ein Modul beispielsweise das Logging-Framework Log4perl ein, ist es einfach, verstrichene Sekunden zusammen mit den Lognachrichten anzuzeigen und so einen Überblick des zeitlichen Programmverlaufs zu erhalten.
Das simple Testskript amzntest holt zum Beispiel mittels des
CPAN-Moduls Net::Amazon Buchinformationen über die Web-API bei Amazon ab.
(Der ausgeixte Token ist vorher durch einen bei [1] abgeholten zu
ersetzen.)
Ein Request dauert etwa eine Sekunde, aber wo verbrät das Skript diese, beim
Einholen der Daten oder während der anschließenden Analyse der XML-Daten?
Ein am Kopf des Skripts eingefügtes
use Log::Log4perl;
Log::Log4perl->init("timer.l4p");
aktiviert das in Net::Amazon eingebettete Log4perl-Framework und lädt die
Konfigurationsdatei timer.l4p, die festlegt, dass zu jeder geloggten
Nachricht auch noch das Datum (%d) sowie die verstrichene Zahl der
Millisekunden seit dem Programmstart (%r) ausgegeben werden. Da der
Loglevel mit DEBUG relativ hoch und damit die ausgegebenen Nachrichten
recht lang sein können, definiert Listing timer.l4p auch noch eine
sogenannte ``custom cspec'' mit dem Kürzel %S. Dieses erscheint dann statt
dem sonst üblichen %m (für die Lognachricht) im Layout und schickt statt
dessen eine auf 25 Zeichen verkürzte Nachricht an den Screen-Appender.
Das Layout schließt mit einem plattformunabhängigen
Newline-Zeichen ab, das mit %n notiert.
01 #!/usr/bin/perl
02 use warnings;
03 use strict;
04 use Net::Amazon;
05 use Net::Amazon::Request::ASIN;
06
07 my $asin = "0132396556";
08
09 my $ua = Net::Amazon->new(
10 token => 'XXXXXXXXXXXXXXX',
11 );
12
13 my $req = Net::Amazon::Request::ASIN->new(
14 asin => $asin,
15 );
16
17 my $resp = $ua->request($req);
18
19 if($resp->is_success()) {
20 print $resp->as_string(), "\n";
21 } else {
22 print "Error: ",
23 $resp->message(), "\n";
24 }
1 log4perl.logger = DEBUG, App
2 log4perl.appender.App = Log::Log4perl::Appender::Screen
3 log4perl.appender.App.layout = PatternLayout
4 log4perl.appender.App.layout.ConversionPattern = %d %r %S%n
5 log4perl.PatternLayout.cspec.S = sub { substr($_[1], 0, 25) }
| |
| Abbildung 1: Log4perl gibt die Uhrzeit und die verstrichenen Millisekunden seit dem Programmstart an. |
 |
| Abbildung 2: Bei einem eingesetzten Webcache entfällt der Webrequest für Wiederholer und reduziert die Laufzeit um 75%. |
01 use Cache::File;
02 my $cache = Cache::File->new(
03 cache_root => '/tmp/mycache',
04 default_expires => '30 min',
05 );
06
07 my $ua = Net::Amazon->new(
08 token => '0AQN5ZBDW6NXV9M60N82',
09 cache => $cache,
10 );
Die Ausgabe in Abbildung 1 zeigt, dass Net::Amazon bereits 79 Millisekunden
nach dem Programmstart einen Web-Request an Amazon absetzt, und erst
zum Zeitpunkt 739 msec der XML-Parser seine Arbeit beginnt. Von den
insgesamt vom Skript verbrauchten 800 msec nimmt also 75% der Webrequest
in Anspruch. Es bietet sich an, für häufig eingeholte ASIN-Nummern einen
Cache einzusetzen, den Net::Amazon, wie in Listing webcache gezeigt,
standardmäßig unterstützt. Und in der Tat reduziert sich die Skriptlaufzeit
mit File::Cache als persistentem Zwischenspeicher bei Wiederholern
auf 180 msec, wie Abbildung 2 zeigt.
Nun lässt sich freilich argumentieren, dass derlei Tricks nicht immer möglich sind, aber entscheidend ist doch, dass durch 5 Zeilen Code und einer Minute Nachdenkens eine Geschwindigkeitsverbesserung um den Faktor 4 erzielt wurde -- und das ist doch nicht von Pappe.
Nicht jedes Modul verfügt über derlei ausgeklügelte Loggingmechanismen und deswegen stehen in Perl eine Reihe von Profilern zur Verfügung, die messen, welche Sourcecodezeilen wieviel Zeit verbraten. Abbildung 3 zeigt die wichtigsten CPAN-Profiler, aufgeschlüsselt nach Funktionen und Entwicklungsgeschichte.
 |
| Abbildung 3: Weitere Profiler, verfügbar auf dem CPAN. |
Der Line-Profiler Devel::SmallProf vom CPAN erstellt während des
Programmlaufs selbständig Messdaten und formatiert diese anschließend
für eine Analyse. Das zu messende Skript wird mit
perl -d:SmallProf ./amzn gestartet und der Profiler erzeugt
die Datei smallprof.out, die zu jeder
Zeile in jedem benutzten Modul die verstrichene Zeit angibt.
Bei einem
recht komplexen Vorgang wie einem Webrequest und anschließender XML-Analyse
der zurückkommenden Daten nimmt diese Datei natürlich monströse Ausmaße
an und im vorliegenden Fall maß sie glatt 25.792 Zeilen.
Es ist gar nicht so einfach, per Hand die schlimmsten Zeitfresser herauszufinden. Aber das Shell-Kommando
sort -k 2nr,2 smallprof.out | less
sortiert die Datei nach dem zweiten Feld von links, und zwar numerisch. Dort stehen die von einer Source-Code-Zeile in Anspruch genommenen Wall-Time-Sekunden, also die tatsächlich verstrichene Zeit, egal, ob die Task aktiv CPU verbrauchte oder nur untätig herumhing, weil sie auf externe Ereignisse wie eintrudelnde Netzwerkpakete warten musste. Zusätzlich stehen im dritten Feld auch noch die CPU-Sekunden, also die tatsächlich genutzte Rechenzeit, mit ebenfalls fünf Nachkommastellen.
 |
| Abbildung 4: Die 25.000 Zeilen lange Ausgabe von SmallProf enthüllt, dass das Warten auf den Amazon-Server die meiste Zeit in Anspruch nahm. |
Fährt man dann, wie in Abbildung 4 gezeigt, in der Datei smallprof.out
zur Zeile 17.104 herunter, zeigt sich, dass die für das Warten
verantwortliche Zeile einen select-Befehl absetzt. Die Funktion
can_read im Modul LWP::Protocol::http::SocketMethods zeichnet
dafür verantwortlich.
Eine relativ neue Entwicklung ist Devel::NYTProf vom CPAN. Der etwas merkwürdige Name rührt daher, dass das Modul im Auftrag der Zeitung ``New York Times'', ausgehend von der Codebasis von Devel::FastProf, entwickelt wurde. Die IT-Abteilung entschloss sich dazu, den Sourcecode freizugeben. Dieser hervorragende Profiler wird heutzutage von DBI-Erfinder Tim Bunce gepflegt, der ihn auf der OSCON 2008 der baffen Perl-Community vorstellte. Im Publikum saß auch der Autor dieser Zeilen, der allerdings unruhig auf seinem Hosenboden hin und herrutschte, da er gleich danach mit seinem Log4perl-Vortrag auf die Bühne musste!
Nach der CPAN-Shell-gestützten Installation mit
perl -MCPAN -e'install Devel::NYTProf'
ruft man den Profiler mit
perl -d:NYTProf amzn auf
und wandelt dessen binäre Logdatei nytprof.out mit dem ebenfalls
beiliegenden Skript nytprofhtml in professionell formatiertes
HTML um. Nordet man anschließend einen Browser auf die Datei index.html
im neu erzeugten Verzeichnis nytprof (URL file:///...nytprof/index.html)
ein, ist schön zu erkennen, was soeben ablief. Die Tabelle in Abbildung 5
listet die Hotspots auf. Sie zeigt die Anzahl der Aufrufe (Calls), die
Zahl der Aufrufstellen (P=Places) und -dateien (F=Files), sowie die
in der jeweiligen Funktion verstrichene Zeit. Hierbei unterscheidet
sie zwischen ``Exclusive Time'' und ``Inclusive Time'', wobei ersterer
Wert die ausschließlich im Code der Funktion verbrachte Zeit anzeigt
und letzterer die Gesamtzeit, einschließlich von der Funktion
aufgerufener Unterfunktionen.
 |
| Abbildung 5: Die 15 Funktionen, die am meisten Zeit verbraten. |
Das HTML verlinkt Funktionsnamen praktischerweise mit weiteren HTML-Seiten,
auf denen
Details zum Funktionscode stehen. So kann der Anwender schnell hin-
und hermanövrieren, was die Analyse erheblich vereinfacht.
Abbildung 5 zeigt zum Beispiel, was mit SmallProf vorher nur mühsam
ermittelt werden konnte, nämlich, dass der select()-Befehl in der
Funktion can_read() im einem LWP-Modul für die Zeitverzögerung
verantwortlich ist. Er lauscht auf einem offenen Network-Socket auf
das erste Anzeichen der von Amazon eintrudelnden Antwort.
NYTProf unterstützt drei verschiedene Report-Modi, um die im Sourcecode verstrichene Zeit anzuzeigen: ``line'' (eine Zeitraumangabe pro Zeile), block (pro Perlblock) und sub (pro Funktion). Per Mausklick schaltet der Performance-Detektiv zwischen den verschiedenen Displayvarianten hin und her.
 |
| Abbildung 6: Das select-Kommando im LWP-Code wartet auf eine Antwort von Amazon und zeichnet dadurch für einen Großteil der Programmlaufzeit verantwortlich. |
Auch die in Abbildung 7 gezeigte Sicht des Profilers auf der Modulebene
enthüllt interessante Tatsachen. Die XML-Analyse der Webantwort von Amazon nahm
ganze 9963 Codezeilen und 400 Aufrufe der XML::Simple-Funktion collapse()
in Anspruch! Da diese mit voller Geschwindigkeit liefen,
war der Fall in 35 Millisekunden erledigt, aber hier zeigt sich, wie
aufwändig XML zu parsen ist.
 |
| Abbildung 7: Die Modulebene zeigt an, wieviel Zeit der Code in welchem Modul verbrachte und wieviele Statements dort abgearbeitet wurden. |
Wie jeder andere Profiler erzeugt auch Devel::NYTProf einen gewissen Overhead, der die Messergebnisse teilweise erheblich verfälschen kann. Besonders wenn ein Program nicht auf externe Ereignisse wie Netzwerkverkehr oder Festplatten wartet, die um Größenordnungen langsamer laufen, spielen die Aktivitäten des Profilers eine tragende Rolle. Läuft ein Programm mit voller CPU-Geschwindigkeit, kann sich die Programmlaufzeit mit dem eingeschalteten Profiler durchaus verzehnfachen.
1 #!/usr/local/bin/perl -w
2 use strict;
3
4 use Log::Log4perl qw(:easy);
5 Log::Log4perl->easy_init($INFO);
6
7 for(1..100_000) {
8 DEBUG "waah!";
9 }
 |
| Abbildung 8: NYTProf verlangsamt schnelle Programme teilweise extrem. |
Abbildung 7 zeigt zum Beispiel die Auswirkungen des
NYT-Profilers auf das kurze Testprogramm l4ptest. Dieses konfiguriert
Log4perl auf die Logpriorität $INFO, und arbeitet dann Log-Befehle
der niedrigeren Priorität $DEBUG ab, die naturgemäß alle
unterdrückt werden. Log4perl hat diesen Fall stark optimiert, denn
ein deaktiviertes Logsystem sollte keinen messbaren Einfluss auf das
Gesamtsystem ausüben. Ohne Profiler aufgerufen, schafft das Skript dann auch
100.000 Aufrufe in etwa 100 Millisekunden, aber mit aktiviertem NYTProf
erhöht sich die Skriptlaufzeit auf mehr als das Zehnfache. Dies
tut der Qualität des Profilers keinen Abbruch, es ist nur wichtig,
beim Messen daran zu denken und die Ergebnisse entsprechend zu
interpretieren.
Auch im Apache-Server unter mod_perl findet sich das Modul zurecht. Die
Konfigurationszeile PerlModule Devel::NYTProf::Apache lädt es und
lässt es bei eingehenden Requests Profiledaten an die Datei
/tmp/nytprof.$$.out anhängen, wobei $$ die pid des den Request
bearbeitenden Apache-Prozesses ist. Und auch hier erzeugt das anschließend
aufgerufene Skript
nytprofhtml eine Kollektion von Webseiten, die die Performance des
Webservers detailliert unter die Lupe nehmen und wertvolle Hinweise zu
eventuell möglichen Codeverbesserungen geben.
 |
Michael Schilliarbeitet als Software-Engineer bei Yahoo! in Sunnyvale, Kalifornien. Er hat "Goto Perl 5" (deutsch) und "Perl Power" (englisch) für Addison-Wesley geschrieben und ist unter mschilli@perlmeister.com zu erreichen. Seine Homepage: http://perlmeister.com. |