Schneller, schneller! (Linux-Magazin, Dezember 2008)

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.

Flaschenh├Ąlse zuerst

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.

Listing 1: amzntest

    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 }

Listing 2: timer.l4p

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

Listing 3: webcache

    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 );

Schneller Fix

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.

Line-Profiler SmallProf

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.

Schlimmste Zeitfresser

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.

NYTProf

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.

Analyse per Klick

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.


Nicht ohne Nebenwirkungen

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.

Listing 4: l4ptest

    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.

Infos

[1]
Listings zu diesem Artikel: ftp://www.linux-magazin.de/pub/listings/magazin/2008/12/Perl

[2]
Amazon Web Service (Entwicklertoken abholen) http://amazon.com/soap

[3]
Tim Bunce, ``NYTProf v2 - the background story'', http://blog.timbunce.org/2008/07/16/nytprof-v2-the-background-story/

Michael Schilli

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