In einer vor einigen Jahren programmierten Web-Applikation (ANIBILL; Übernachtungsstatistik und Rechnungsstellung für einen Tierstall) gab es vor einigen Wochen gewisse Performance-Engpässe, die sich in einer äusserst schleppenden Antwortzeit äusserten. Nach einigen ersten Untersuchungen isolierte ich MySQL (respektive unoptimierte Queries) als Ursache der Probleme.

Die richtige Vorgehensweise

Doch was nun? Klar konnte ich nun temporäre Änderungen an der Applikation auf einem Test-Server vornehmen und hoffen, dass ich den Fehler reproduzieren konnte. Oder aber: Ich änderte den Code dermassen, dass die Applikation künftig bei jedem Aufruf Zeitmessungen vornahm, mit denen ich ein aussagekräftigeres Bild erhielt. PHP-Programmierer werden es zu schätzen wissen, wenn sie Optimierungen auf Grund von 1’000 Messungen anstelle von 1-2 Probeläufen vornehmen können.

Die Lösung

Heraus kamen zwei Funktionen: anibill__get_db_data() und anibill__dump_microtime(). Durch die erste Funktion werden alle SQL-Queries „kanalisiert“, die mit SELECTs arbeiten. Zur Beruhigung der versierten Leser: Diese Funktion war seit Beginn der Applikation vorhanden, ich musste also nicht 1’000 Codezeilen nach mysql_query() durchstrählen …

Innerhalb dieser Funktion messe ich mittels microtime(), wie lange mysql_query() zum Ausführen meines SQL-Queries benötigt (und nur das, der Rest interessiert mich nicht). Bevor ich die aus der Datenbank gelesenen Daten zurückgebe, rufe ich die Benchmark-Funktion anibill__dump_microtime() auf, die mir einerseits die Laufzeit des Queries als auch gleich die aufrufende Funktion in eine Datenbank-Tabelle speichert. Bis zu diesem Zeitpunkt kannte ich die PHP-Funktion debug_backtrace() nicht – dabei ist sie äusserst mächtig. Ihre Ausgabe führt genau Buch, welche Funktionen seit dem Aufruf des Scripts ausgeführt wurden. Und nicht nur das – sogar die Zeilennummer des die Funktion enthaltenden PHP-Scripts ist angegeben. Ein Traum!

function anibill__get_db_data($str_sql_query,$bol_die_on_err = TRUE) {
 ...
 
 // Benchmark current MySQL query
 $arr_time[0] = microtime();
 $obj_db_data = mysql_query($str_sql_query,$res_db_conn);
 $arr_time[1] = microtime();
 
 ...
 
 // Store benchmark to database
 anibill__dump_microtime($arr_time,$str_sql_query);
 
 return $arr_db_data;
}

function anibill__dump_microtime($arr_time,$str_sql_query) {
 ...
 
 // Still using PHP4 and therefore wrestling with microtime()'s format
 $arr_start    = explode(" ", $arr_time[0]);
 $arr_end    = explode(" ", $arr_time[1]);

 $int_seconds            = $arr_end[1] - $arr_start[1];
 $flo_microseconds       = $arr_end[0] - $arr_start[0];

 $flo_runtime            = $int_seconds + $flo_microseconds;
 
 // Which function called anibill__get_db_data() in the first place?
 $arr_debug = debug_backtrace();
 if(isset($arr_debug[2]['function']))
   $str_function = $arr_debug[2]['function'];
 else
   $str_function = NULL;

 if(isset($arr_debug[1]['line']))
   $str_line = $arr_debug[1]['line'];
 else
   $str_line = NULL;
 
 ...
 
 return TRUE;
}

Ich möchte all die Christians, Andreas und Silvans da draussen um Gnade bitten – mein Coding-Stil wird wohl nicht der effektivste sein (zu viele Zeilen, zu viele Einzüge etc.), doch die Lesbarkeit liegt mir am Herzen. Und ja, von OOP keine Spur …

Selbstverständlich generiert das Benchmarken und Backtracen einen gewissen Overhead, doch aus meiner Sicht ist die vorgestellte Methode geeignet, die Performance kleinerer Web-Applikationen mit wenigen gleichzeitigen Zugriffen zu messen – ohne kostenpflichtige Tools einzukaufen und grosse Profiling-Sessions zu starten.

Zum Schluss

Erfinde ich das Rad neu? Gibt es elegantere Lösungen? Die Kommentarfunktion ist ab sofort geöffnet.