Bis in den roten Bereich (Linux-Magazin, August 1998)

Wieviele Seiten schafft mein Web-Server pro Sekunde? Wieviele Clients kann ich mit CGI-Skripts pro Sekunde bedienen? Was bringen die Apache-Beschleuniger fast-cgi und mod_perl wirklich? Ein Testskript simuliert parallel anstürmende Web-Browser und zeigt, wo die Grenzen des eigenen Web-Servers liegen.

Spricht man von der Performance eines Web-Servers, sind zwei Parameter ausschlaggebend. Da ist einmal die Verzögerung (Latency), die Zeit, die verstreicht, bis der Server die Anfrage eines Clients bearbeitet hat und die verlangte Seite ausliefert. Wichtiger noch ist allerdings der maximale Durchsatz (Throughput), der angibt, wieviele Anfragen der Server pro Sekunde bearbeiten kann, bis parallel anstürmende Clients die CPU des Servers so stark belasten, daß dieser mit der Abarbeitung nicht mehr nachkommt und manche Clients irgendwann die Geduld verlieren und einen Timeout melden.

So reicht es denn nicht, von einem Test-Client aus hintereinander Anfragen an den Server zu schicken und die verstrichene Zeit zu messen, denn viele Server sind zu merklich mehr imstande und handeln Requests parallel ab. Vielmehr muß der Test-Client eine einstellbare Anzahl von Requests quasi gleichzeitig an den Server stellen und deren Ergebnisse asynchron bearbeiten. Für diesen Zweck ist das Modul LWP::Parallel::UserAgent von Marc Langheinrich hervorragend geeignet, denn mit ihm lassen sich parallel laufende UserAgents erzeugen und kontrollieren.

Die neueste Version 2.32 liegt auf dem CPAN (wo sonst!) unter

    modules/by-module/LWP/ParallelUserAgent-2.32.tar.gz

vor. Es setzt die installierte libwww-Distribution voraus, die auf dem CPAN unter

    modules/by-module/LWP/libwww-perl-5.33.tar.gz

zur Abholung bereitliegt.

Genaue Zeitmessungen

Um die zwischen zwei Meßpunkten verstrichene Zeit nicht nur sekundengenau zu ermitteln, sondern auch Bruchteile von Sekunden zu erfassen, muß das Modul Time::HiRes von Douglas E. Wegscheid 'ran. Die neueste Version 1.16 liegt unter

    modules/by-module/Time/Time-HiRes-01.16.tar.gz

auf dem CPAN. Die Funktion Time::HiRes::gettimeofday ermittelt die aktuelle Uhrzeit so genau, daß ein anschließender Aufruf von Time::HiRes::tv_interval mit zwei Meßpunkten als Parametern die dazwischen verstrichene Zeit als Fließkommazahl in Millisekunden-Auflösung zurückliefert. Das Skript nach Listing hires.pl ermittelt die Zeit, die ein Aufruf von sleep(1) verbrät und gibt sie aus:

    Verstrichene Zeit: 0.99861 Sekunden

Hämmern mit dem parallelen UserAgent

Das Modul LWP::Parallel::UserAgent erzeugt UserAgents, die (beinahe) gleichzeitig auf einen Webserver losfeuern. Der Konstruktor

    $ua = LWP::Parallel::UserAgent->new();

erzeugt das Mutter-Objekt, das die wilde Horde unter Kontrolle hält. Jeder einzelne Request muß mit

    $ua->register($request);

beim Parallel::UserAgent registriert werden, wobei $request eine Referenz auf ein Objekt vom Typ HTTP::Request ist, das vorher zum Beispiel mit

    my $request = HTTP::Request->new('GET', $url);

erzeugt wurde. Die Methode

    $ua->wait($timeout);

startet dann den Ansturm. Jeder Client wartet maximal $timeout Sekunden auf prompte Bedienung. Dabei achtet der multiple UserAgent darauf, nur eine über

    $ua->max_req($max_clients);

voreingestellte Anzahl von Clients gleichzeitig zu starten und erst dann neue Clients nachzulegen, falls alte ihre Mission beendet haben.

Das ist genau, was das Skript zur Performance-Messung nach Listing pounder.pl tut: Die Zeilen 60 bis 71 erzeugen das Mutter-Objekt und pressen den gleichen Request so oft hinein, wie es die Variable $nof_requests_total aus der Konfigurationssektion ab Zeile 9 vorgibt. Die Zeilen dort sind vor dem Skriptstart an die lokalen Gegebenheiten anzupassen, $nof_parallel_connections legt die Anzahl ``gleichzeitig'' loslegender Clients fest, $url den URL der zu testenden Webseite und $timeout die maximale Anzahl von Sekunden, die ein Client auf Bedienung wartet.

Zeile 76 hält noch schnell die Startzeit fest, bevor die wait-Methode aus Zeile 77 den Massentest startet und erst zurückkehrt, wenn auch der letzte Client Erfolg oder Misserfolg gemeldet hat. Nach Abschluß des Rennens hält Zeile 78 die Stoppuhr an, indem es die Funktion tv_interval aus dem Paket Time::HiRes mit nur einem Parameter (der Startzeit) aufruft, was tv_interval dazu veranlaßt, die seit dem Startzeitpunkt vergangene Zeit in Sekunden plus Bruchteilen als Fließkommazahl zurückzugeben.

Die wait-Methode liefert eine Referenz auf einen Hash zurück, der als Values Referenzen auf Objekte vom Typ LWP::Parallel::UserAgent::Entry enthält: Das Ergebnis jeder während des Tests aufgebauten HTTP::Verbindung läßt sich so nochmal abfragen. Ein Entry-Objekt liefert, falls es mit der response-Methode dazu aufgefordert wird, eine Referenz auf ein HTTP::Response-Objekt zurück, das wiederum mit der Methode is_success Erfolg meldet oder im Fehlerfall mit den Methoden code und message Fehler-Code und -Meldung bereitstellt.

Im Erfolgsfall zählt pounder.pl die Variable $succeeded um Eins hoch, falls etwas schieflief, speichert der Hash %errors die Fehlermeldung als Key und die Häufigkeit des aufgetretenen Fehlers als Value (Zeile 93). Die Zeilen 100-102 machen daraus eine komma-separierte Liste von Fehlermeldungen und deren Häufigkeiten und legen sie im String $errors ab.

Die Ausgabe der Ergebnisse im Format

    URL:             http://localhost/perl/dump.cgi
    Total Requests:  100
    Parallel Agents: 5
    Succeeded:       100 (100.00%)
    Errors:          NONE
    Total Time:      22.75 secs
    Throughput:      4.39 Requests/sec
    Latency:         1.02 secs/Request

übernehmen die Zeilen 107 bis 143. Zunächst legt das Skript im Array @P die linken und rechten Seiten der Ausgabe als aufeinanderfolgende Elemente ab. Die korrekte Formatierung übernimmt anschließend die Formatanweisung aus den Zeilen 136-139, die die linke Spalte der ausgegebenen Tabelle jeweils 16 Zeichen breit linksbündig setzt und eine beliebig breite rechte Spalte daneben setzt.

Die Zeilen 141 bis 143 extrahieren jeweils zwei Elemente aus @P und die write-Anweisung gibt sie schön formatiert aus. Nun war ich bislang kein besonderer Fan von Perls Format-Befehlen, aber für diese Anwendung taugt's mir -- öfter mal was Neues! Näheres hierzu zeigt übrigens die Manualseite, die auf perldoc perlform zum Vorschein kommt.

Die wichtigste Ausgabe ist zweifellos der Durchsatz. Die Zeile

    Throughput:      4.39 Requests/sec

kommt dadurch zustande, daß das Skript die Zeit mißt, die zwischen dem Starten der $ua->wait-Methode und deren Beendigung vergeht und anschließend durch die Anzahl der erfolgreichen Requests teilt.

Wir lassen's krachen - mit einer abgeleitete Klasse

Wahrscheinlich hat sich der ein oder andere bislang schon gewundert -- ``Wieso ist das erzeugte Mutter-Objekt vom Typ MyParallelAgent?'' Der Grund dafür ist, daß es LWP::Parallel::UserAgent nicht gestattet, direkt Messungen der Latency vorzunehmen, also der Zeitspanne zwischen dem Absetzen eines (einzelnen!) Requests und dessen Abarbeitung. In weiser Voraussicht hat der Entwickler von LWP::Parallel::UserAgent jedoch eine Hintertür eingebaut: Objekte vom Typ LWP::Parallel::UserAgent rufen vor jedem Einzel-Request die Methode on_connect auf und springen nach getaner Arbeit je nach Erfolgsstatus on_return oder on_failure an. Diese Methoden läßt die Implementierung in LWP::Parallel::UserAgent bewußt leer -- abgeleitete Klassen dürfen sie überschreiben und zusätzliche Funktionalität integrieren.

Das Mutterobjekt ruft on_connect, on_return und on_failure mit drei zusätzlichen Parametern auf: Neben der für die objektorientierte Programmierung mit Perl obligatorischen Objektreferenz kommen

als Parameter herein.

In pounder.pl definieren die Zeilen 17 bis 51 eine neue, von LWP::Parallel::UserAgent abgeleitete Klasse MyParallelAgent, die folglich alles kann, wozu LWP::Parallel::UserAgent imstande ist. Der @ISA-Array aus Zeile 19 legt die Vererbungshierarchie fest. Die in der abgeleiteten Klasse überschriebene Methode on_connect bringt das Kunststück fertig, die Startzeit des jeweiligen Requests in einer Instanzvariablen für die spätere Latency-Berechnung abzulegen. Da das Mutter-Objekt die Startzeit aller Einzel-Requests speichern muß, speichert es die Einzel-Startzeiten in einem Hash __start_times, den sie mit der als letzten Parameter nach on_connect hereingereichten Referenz $entry indiziert, da diese Variable für jeden Einzel-Request eindeutig ist.

Der Name __start_times enthält deshalb zwei Unterstriche, damit es nicht zu unbeabsichtigten Überlappungen mit eventuell in LWP::Parallel::UserAgent schon definierten gleichnamigen Instanzvariablen kommt.

$self->{__start_times}->{$entry} enthält also für jeden Request eine für das Time::HiRes-Modul taugliche Startzeit.

Die on_return-Methode addiert im Erfolgsfall am Ende eines Requests die inzwischen verstrichene Zeit zu einer Instanzvariablen des Mutter-Objekts: __latency_total, einer Fließkommazahl, die einen Sekundenwert für alle bislang ausgeführten Requests festhält.

on_failure verhält sich analog -- da im Fehlerfall genau derselbe Ablauf erwünscht ist, ruft die überschriebene on_failure-Methode einfach on_return mit allen übergebenen Parametern auf.

Um die Definition der Klasse MyParallelAgent abzuschließen und mit dem eigentlichen Skript anzufangen, steht package main in Zeile 54.

Abbildung 1 zeigt Meßwerte für verschiedene URLs. Die erste Testserie holte ständig die statische Seite http://localhost/index.html und der Server lieferte mit mehr als 6 Requests pro Sekunde ein respektables Ergebnis. Für ein CGI-Skript, das noch dazu das CGI.pm-Modul einbindet, wird's schon sehr langsam: Die zweite Testreihe zeigt, daß der Server nur noch einen Requests pro Sekunde schafft und es etwa fünf Sekunden dauert, bevor der Anwender eine Antwort bekommt. Die dritte Testreihe spricht mit http://localhost/perl/dump.cgi dasselbe Skript an, nur daß dieses diesmal mit dem Apache-Beschleuniger mod_perl ausgeführt wird - das Ergebnis: Fast dreimal so schnell. Daß pounder.pl auch Fehlerfälle korrekt behandelt, zeigt die vierte Testserie: Für den nicht existierenden URL http://localhost/bogus meldet es korrekt 100 mal den Fehler File Not Found.

Weitere Einflüsse

Bei Performance-Messungen spielt natürlich auch die Netzwerkverbindung eine wichtige Rolle: Kommen die übertragenen Daten nicht schnell genug durch die Leitung, spiegelt das Meßergebnis letztlich die Bandbreite der Leitung wider und nicht die Serverleistung.

Laufen, wie bei den durchgeführten Tests, Client und Server auf ein und demselben Rechner, zieht auch der Client nicht unerheblichen Saft aus der CPU. Zwar hält sich dies beim LWP::Parallel::UserAgent-Client in Grenzen, da dieser alle parallelen Verbindungen mit nur einem einzigen Prozeß und dem guten alten select-Trick kontrolliert, doch sollten für exakte Messungen Client und Server auf getrennten Maschinen mit guter Netzwerkverbindung laufen.

Noch eine Bitte

Und noch eine persönliche Bitte, meine lieben Leser: pounder.pl belastet einen angesprochenen Web-Server erheblich -- tut mir den Gefallen und testet damit nur Eure eigenen Installationen. Ich denke, wer genügend Grips besitzt, das Skript zu starten und anzupassen, ist auch ein guter Netizen. Daran denken: Wir sind alle gute Freunde! Bis zum nächsten Mal!

Listing hires.pl

    01 #!/usr/bin/perl -w
    02 ######################################################################
    03 # Michael Schilli, 1998 (mschilli@perlmeister.com)
    04 ######################################################################
    05 
    06 use Time::HiRes;
    07 
    08            # Zeit erfassen ...
    09 $start = [Time::HiRes::gettimeofday];
    10 
    11 sleep(1);  # ... schlafen ...
    12 
    13            # ... und abermals die Zeit erfassen
    14 $stop  = [Time::HiRes::gettimeofday];
    15 
    16            # Verstrichene Zeit ermitteln
    17 $elapsed = Time::HiRes::tv_interval($start, $stop);
    18 
    19 print "Verstrichene Zeit: $elapsed Sekunden\n";

Listing pounder.pl

    001 #!/usr/bin/perl -w
    002 ##################################################
    003 # Michael Schilli, 1998 (mschilli@perlmeister.com)
    004 ##################################################
    005 
    006 use LWP::Parallel::UserAgent;
    007 use Time::HiRes qw(gettimeofday tv_interval);
    008 
    009 ###
    010 # Configuration
    011 ###
    012 $nof_parallel_connections = 1;
    013 $nof_requests_total       = 1000;
    014 $url =              "http://localhost/perl/dump.cgi";;
    015 $timeout                  = 10;
    016 
    017 ##################################################
    018 # Derived Class for latency timing
    019 ##################################################
    020 package MyParallelAgent;
    021 
    022 @ISA = qw(LWP::Parallel::UserAgent);
    023 
    024 ###
    025 # Is called when connection is openend
    026 ###
    027 sub on_connect {
    028     my ($self, $request, $response, $entry) = @_;
    029     $self->{__start_times}->{$entry} = 
    030                       [Time::HiRes::gettimeofday];
    031 }
    032 
    033 ###
    034 # Are called when connection is closed
    035 ###
    036 sub on_return {
    037     my ($self, $request, $response, $entry) = @_;
    038 
    039     my $start = $self->{__start_times}->{$entry};
    040 
    041     $self->{__latency_total} += 
    042                  Time::HiRes::tv_interval($start);
    043 }
    044 
    045 sub on_failure {
    046     on_return(@_);  # Same procedure
    047 }
    048 
    049 ###
    050 # Access function for new instance var
    051 ###
    052 sub get_latency_total {
    053     return shift->{__latency_total};
    054 }
    055 
    056 ##################################################
    057 package main;
    058 ##################################################
    059 
    060 ###
    061 # Init parallel user agent
    062 ###
    063 $ua = MyParallelAgent->new();
    064 $ua->agent("pounder/1.0");
    065 $ua->max_req($nof_parallel_connections);
    066 $ua->redirect(0);    # No redirects
    067 
    068 ###
    069 # Register all requests
    070 ###
    071 foreach (1..$nof_requests_total) {
    072     my $request = HTTP::Request->new('GET', $url);
    073     $ua->register($request);
    074 }
    075 
    076 ###
    077 # Launch processes and check time
    078 ###
    079 $start_time = [gettimeofday];
    080 $results = $ua->wait($timeout);
    081 $total_time = tv_interval($start_time);
    082 
    083 ###
    084 # Requests all done, check results
    085 ###
    086 $succeeded     = 0;
    087 foreach $entry (values %$results) {
    088     my $response = $entry->response();
    089 
    090     if($response->is_success()) {
    091         $succeeded++; # Another satisfied customer
    092     } else {
    093             # Error, save the message
    094         $response->message("TIMEOUT") 
    095                          unless $response->code();
    096         $errors{$response->message}++;
    097     }
    098 }
    099 
    100 ###
    101 # Format errors if any from %errors 
    102 ###
    103 $errors = 
    104   join(',', map "$_ ($errors{$_})", keys %errors);
    105 $errors = "NONE" unless $errors;
    106 
    107 ###
    108 # Format results
    109 ###
    110 @P = (
    111 "URL" => $url,
    112 
    113 "Total Requests" => "$nof_requests_total",
    114 
    115 "Parallel Agents" => $nof_parallel_connections,
    116 
    117 "Succeeded" =>
    118    sprintf("$succeeded (%.2f%%)\n",
    119           $succeeded * 100 / $nof_requests_total),
    120 
    121 "Errors" => $errors,
    122 
    123 "Total Time" => 
    124     sprintf("%.2f secs\n", $total_time),
    125 
    126 "Throughput" =>
    127     sprintf("%.2f Requests/sec\n", 
    128             $nof_requests_total / $total_time),
    129 
    130 "Latency" => 
    131     sprintf("%.2f secs/Request", 
    132             $ua->get_latency_total() / 
    133               $nof_requests_total),
    134 );
    135  
    136 ###
    137 # Print out statistics
    138 ###
    139 format STDOUT =
    140 @<<<<<<<<<<<<<<< @*
    141 "$left:",        $right
    142 .
    143 
    144 while(($left, $right) = splice(@P, 0, 2)) {
    145     write;
    146 }

Abbildung 1: Schnell, schneller, am schnellsten

Die Meßwerte aus einer Testreihe mit 100 Requests und 5 parallelen User-Agents. Dargestellt sind die Ergebnisse für eine statische Seite (index.html), ein CGI-Skript (cgi-bin/dump.cgi), ein CGI-Skript unter dem Apache-Beschleuniger mod_perl (perl/dump.cgi) und einen Fehlerfall, der nach einem nicht existierenden URL verlangt.

    URL:             http://localhost/index.html
    Total Requests:  100
    Parallel Agents: 5
    Succeeded:       100 (100.00%)
    Errors:          NONE
    Total Time:      15.75 secs
    Throughput:      6.35 Requests/sec
    Latency:         0.67 secs/Request
     
    URL:             http://localhost/cgi-bin/dump.cgi
    Total Requests:  100
    Parallel Agents: 5
    Succeeded:       100 (100.00%)
    Errors:          NONE
    Total Time:      106.73 secs
    Throughput:      0.94 Requests/sec
    Latency:         5.22 secs/Request
     
    URL:             http://localhost/perl/dump.cgi
    Total Requests:  100
    Parallel Agents: 5
    Succeeded:       100 (100.00%)
    Errors:          NONE
    Total Time:      38.07 secs
    Throughput:      2.63 Requests/sec
    Latency:         1.84 secs/Request
     
    URL:             http://localhost/bogus
    Total Requests:  100
    Parallel Agents: 5
    Succeeded:       0 (0.00%)
    Errors:          File Not Found (100)
    Total Time:      12.86 secs
    Throughput:      7.77 Requests/sec
    Latency:         0.57 secs/Request

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.