Tuning mod_perl

  Perl
  Shell
  Dateitransfer
  OS
  Home

  Links

  Impressum

Tunen im mod_perl-Umfeld

Das Problem

Die Aufgabe: Das Webfrontend von OpenSMART ist zu langsam.

Erste und häufigste Antwort: Nimm "mod_perl". Gesagt, getan, die Anpassungen im Script sind überschaubar, die Konfiguration von Apache auch. Etwas schneller kommt mir das ja schon vor, aber ist es das auch wirklich ? Und: Läuft es wirklich unter mod_perl ?

Regel 1: Umgebung für einfache, reproduzierbare Tests schaffen

Da kommen wir ja gleich zu einer der großen Regeln beim Tunen (von egal was): Schaff dir erstmal eine Umgebung, in der du aussagekräftige Werte möglichst einfach und möglichst reproduzierbar bekommst. Wie schafft man das in einer Web-Umgebung ?

Siege

Die Antwort heisst siege. Siege ist ein Stress-Tester / Antwortzeitmessungstool für Webserver und Webapplikationen. Damit kann ich also einfach mehrere Requests gleichzeitig und insgesamt viele hintereinander auf meine Applikation loslassen und bekomme hinterher vernünftige Laufzeitergebnisse.

Also lasse ich 

siege -c 5 -r 10 http://localhost/cgi-bin/monitorgui.cgi
5 gleichzeitige User mit 10 Wiederholungen auf meine Applikation los.

Das Ergebnis: 

Transactions:                     50 hits
Availability:                 100.00 %
Elapsed time:                  67.44 secs
Data transferred:             656400 bytes
Response time:                  5.85 secs
Transaction rate:               0.74 trans/sec
Throughput:                  9733.10 bytes/sec
Concurrency:                    4.34
Successful transactions:          50
Failed transactions:               0
Longest transaction:            8.13
Shortest transaction:           2.06
(die absoluten Zahlen sind eigenlich nebensächlich, wir wollen einfach später noch damit vergleichen).

Läuft die Applikation wirklich unter mod_perl ?

Nur: Läuft das jetzt unter mod_perl oder noch als normales CGI-Script ? Ein "top" bringt es an den Tag: Während siege läuft, sind viele "monitorgui.cgi"-Prozesse zu finden. Schade, mod_perl läuft noch nicht.

OK, Konfig geprüft, Fehler gefunden (hier: Es war ein Tippfehler in der Konfiguration), apache neu gestartet, siege nochmal angestartet.

Das Ergebnis: 

Transactions:                     50 hits
Availability:                 100.00 %
Elapsed time:                  34.98 secs
Data transferred:             652650 bytes
Response time:                  2.12 secs
Transaction rate:               1.43 trans/sec
Throughput:                 18657.80 bytes/sec
Concurrency:                    3.04
Successful transactions:          50
Failed transactions:               0
Longest transaction:           12.79
Shortest transaction:           0.28
Die durchschnittliche Antwortzeit hat sich halbiert, Allerdings gibt es immer noch vereinzelt sehr lange Transaktionen. Und: top zeigt, dass "httpd"-Prozesse laufen, nicht mehr monitorgui.cgi. Wir sehen: Aha, mod_perl hat unsere Antwortzeiten halbiert.

Regel 2: so viel Profilen wie möglich

Apache::DProf

Aber ist das alles, geht da nicht noch mehr ? Und wo werden die Antwortzeiten verbraten ? Die Antworten darauf liefert "Apache::DProf", ein Perl-Modul (zu finden auf CPAN) zum Profilen von mod_perl.

Apache::DProf installieren, konfigurieren, Apache neu starten, siege laufen lassen (und spätestens hier erkennen wir, dass es sinnvoll ist, automatische Lasttests zu bauen), und Apache::DProf-Ausgaben mit "dprofpp" auswerten.

Offensichtlich ist db_getStatus_Complete ein deutlicher Zeitfresser.

Benchmark, Devel::DProf

Mal sehen, wie können wir das auseinandernehmen ? Das können wir ja auch ohne mod_perl/apache einfach so auf der Kommandozeile profilen: 


use lib "/home/osmart/lib";
use Benchmark qw( :all );
use OpenSMART::dbaccess;

timethis(30,"db_getStatus_Complete");
Das liefert einem jetzt die Laufzeit für 30 Aufrufe von "db_getStatus_Complete" (da ist es wieder: Automatische Tests mit Zeitaussagen sind toll.)

Das jetzt noch gebündelt mit Profiling: 

perl -d:DProf ./benchmark
dprofpp -r tmon.out
Das erste Kommando läßt den Profiler mitlaufen (sehr ähnlich wie weiter oben Apache::DProf) und erzeugt eine Datei "tmon.out", die von "dprofpp" analysiert und in einem vernünftigem Format ausgegeben wird. "-r" gibt "echte Zeiten", nicht nur verbrauchte CPU-Minuten an. Das halte ich bei Datenbank-Abfragen für den besseren Weg, schließlich kostet IO keine CPU, aber trotzdem Zeit.

Ergebnis hier: 

%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 32.6   2.380  2.380     30   0.0793 0.0793  DBI::st::execute
 29.1   2.124  7.586     30   0.0708 0.2529  OpenSMART::dbaccess::db_getStatus_
                                             Complete
 13.9   1.018  1.514  37050   0.0000 0.0000  OpenSMART::debugmod::logit
 6.81   0.496  0.496  74100   0.0000 0.0000  Log::Log4perl::Logger::__ANON__
 5.35   0.390  0.390     30   0.0130 0.0130  DBD::Pg::db::_login
 4.93   0.359  1.039  12330   0.0000 0.0001  OpenSMART::debugmod::logit_dumper
 3.71   0.270  0.270     30   0.0090 0.0090  DBI::st::fetchall_arrayref
Wir sehen, dass wir ein Drittel der Zeit in der Datenbank und ein weiteres knappes Drittel in der Logik von db_getStatus_Complete verbringen. Ausserdem ist offensichtlich logit (das ist ein Wrapper um Log4perl) nicht wirklich performant).

Regel 3: Die größten Verbraucher zuerst tunen

Wir haben jetzt 3 Möglichkeiten, weiter vorzugehen:

  • Tunen der Datenbank / des Select-Statements
  • Tunen von db_getStatus_Complete
  • logit tunen

Tun wir mal so für diese Beschreibung, als ob das SQL-Statement und die Datenbank-Einstellungen getuned wären. Bleibt noch die Logik von db_getStatus_Complete und logit.

Weil's einfacher und schneller geht, ziehen wir das Tunen von logit vor, auch wenn das im Gegensatz zu Regel 3 steht. :-)

Tunen von logit:

logit ist ein OpenSMART interner Wrapper um Log4perl. Eigentlich sollen die Aufrufe nur im Debug-Fall dazu dienen, sinnvolle Log-Ausgaben zu bekommen.

Der fragliche Code innerhalb von db_getStatus_Complete sieht so aus:

  my $rows = $sth->fetchall_arrayref();
  while ( my $row = ( shift(@$rows)) ) {

    logit_dumper($logger,'debug',
                 "Host/check/cp: in maintenance ?",$row);

    ... # Irgendwelche Logik

    logit($logger,'debug',"In Maintenance: $maintenance_found");
    ... # Noch mehr Logik
    }
  }

Wir sehen, innerhalb einer Schleife, die über die gesamten Datenbank-Ergebnisse geht, wird einmal logit und einmal logit_dumper (das wiederum hauptsächlich logit aufruft) aufgerufen.

Regel 4: In große Schleifen nur das hineinschreiben, was wirklich hinein muß!

Nun, wir haben etwa 1300-1500 Ergebnis-Zeilen zu bearbeiten, also 2600-3000 logit-Aufrufe. Aber eigentlich kann die Log-Ausgabe auch vor der Schleife erfolgen. Gesagt, getan, 13% Laufzeit gespart.

Tunen der Logik innerhalb von db_getStatus_Complete

Der Code sieht inzwischen so aus:

  my $rows = $sth->fetchall_arrayref();
  logit_dumper($logger,'debug',
               "All host/check/cp from database",$rows);

  while ( my $row = ( shift(@$rows)) ) {


    my $maintenance_found=0;
    for my $x (0 .. $#{$maint}) {
      if ($row->[0] =~ m/$maint->[$x]->[0]/
          and
          $row->[1] =~ m/$maint->[$x]->[1]/
          and
          $row->[2] =~ m/$maint->[$x]->[2]/
         ) {
         .... # Mach irgendwas damit.
        last;
      }
    }
    ... # Noch mehr Logik
  }

Innerhalb der großen (1300-1500-fach)-while-Schleife gibt es eine weitere for-Schleife mit ca. 5-20 Durchläufen, in denen einige reguläre Ausdrücke überprüft werden.

Regel 5: Statische Reguläre Ausdrücke sind oftmals schneller als dynamische.

Ich weiss über die Applikation, dass in den 1300-1500 Durchläufen der äußeren Schleife nur in sehr wenige (5-20) Durchläufen die if-Bedingung erfüllt wird. Also liegt es nahe, die einzelnen 

$maint->[$x]->]0]
Ausdrücke von Hand in einen großen, statischen regulären Ausdruck zusammenzubauen:

  my $host_regex;
  my $x;
  for $x (0 .. $#{$maint}) {
    $host_regex .= "$maint->[$x]->[0]|";
  }
  $host_regex =~ s/\|$//;

In der Schleife wird dann zuerst auf diesen großen regulären Ausdruck geprüft und dann kann ja meistens schon nach der IF-Bedingung weitergemacht werden: 

  while ( my $row = ( shift(@$rows)) ) {


    my $maintenance_found=0;
    if ($row->[0] =~ m/$host_regex/o) {
      for my $x (0 .. $#{$maint}) {
        if ($row->[0] =~ m/$maint->[$x]->[0]/
            and
            $row->[1] =~ m/$maint->[$x]->[1]/
            and
            $row->[2] =~ m/$maint->[$x]->[2]/
           ) {
          ... # mach irgendwas
          last;
        }
      }
    }
    ... # Noch mehr Logik
  }

Voila, 5-10% schneller.

Zusammenfassung

Natürlich tuned sich jede Applikation anders, aber die Hilfsmittel Apache::DProf, Devel::DProf und Benchmark können Nadelöhre doch zielgerichtet auffinden.