PHPGangsta - Der praktische PHP Blog

Vor einigen Tagen hatte ich mit einem meiner Kollegen in der Firma ein Gespräch über Profiler (XDebug). Dabei erzählte er dass er vor einiger Zeit einen rudimentären Profiler gebastelt hat der ähnliches kann wie XDebug heute: Sein Profiler konnte die Laufzeit eines jeden Befehls in einem Script feststellen und in eine Datenbank loggen. Außerdem bekam er Informationen wie oft jede Funktion von irgendwo aufgerufen wurde, er konnte auch sehen von wo genau. Somit war es ihm möglich die langsamsten Teile seiner Software herauszufinden und diese zu beschleunigen.

XDebug und auch der Zend Debugger können genau das selbe und noch viel mehr, trotzdem wollte ich wissen wie man das macht ohne eine entsprechende Extension. Dazu hält PHP die unbekannte Funktion register_tick_function() bereit, die man mit einem Callback füttern kann. Diese Callback-Funktion wird dann bei jedem Tick aufgerufen. Ein Tick ist einfach ausgedrückt jeder low-level-Befehl in einem Script, darunter fallen Zuweisungen, Funktionsaufrufe usw. Im Prinzip fast alles außer Kontrollstrukturen (if, switch, while etc).

Hier ein kleines Script, das die Funktionsweise erklärt:

<?php

function profiler()
{
    debug_print_backtrace();
}

register_tick_function('profiler');

echo "First echo\n";

declare(ticks = 1);
echo "Second echo\n";
echo "Third echo\n";
echo "Before function echo\n";
$i = md5('text');
echo "After function echo\n";

Die Ausgabe sieht wie folgt aus:

First echo
#0  profiler() called at [/private/tmp/tick.php:12]
#0  profiler() called at [/private/tmp/tick.php:12]
Second echo
#0  profiler() called at [/private/tmp/tick.php:13]
Third echo
#0  profiler() called at [/private/tmp/tick.php:14]
Before function echo
#0  profiler() called at [/private/tmp/tick.php:15]
#0  profiler() called at [/private/tmp/tick.php:16]
After function echo
#0  profiler() called at [/private/tmp/tick.php:17]

Man sieht dass profiler() nach jedem Befehl aufgerufen wird. In Zeile 12 wird sie zweimal aufgerufen, einmal für die Zuweisung und einmal für den Funktionsaufruf. Man erkennt auch dass das echo in Zeile 10 keinen profiler() Aufruf zur Folge hat. Das liegt daran dass mit dem Aufruf von declare() erst festgelegt wird wie oft die tick-Funktion aufgerufen werden soll. Diese Zeile aktiviert also das ganze. Auf php.net findet man auch einige Beispiele von Usern zu declare() und den Möglichkeiten.

Wer also nicht zu XDebug greifen möchte (oder kann) sollte, bevor er mühsam jede Menge microtime() und debug_backtrace() Aufrufe einbaut diese Möglichkeit in Betracht ziehen.

So, nun will ich das Thema nachholen, was ich am letzten Donnerstag hab anklingen lassen. Am Wochenende ist dann jedoch das Gewinnspiel dazwischengekommen, sodass ich nun etwas zum Thema PHP-Profiler schreibe.

Profiler? Sind das nicht die FBI-Psychiater, die anhand von Tatorten und den Opfern etwas über den Täter aussagen können, wie er lebt und denkt? Naja, vielleicht…

Profiler gibt es auch für die meisten Programmiersprachen. Profiler schauen „unter die Haube“ und untersuchen die kleinsten Einheiten und Funktionen einen PHP-Programms. Sie messen die Zeiten für die Kommandos, zählen die Anzahl der Aufrufe, merken sich welche Funktion andere Funktionen aufruft und kann daraus sehr ausführliche und interessante Tabellen und Graphen generieren. Diese nutzt man dann am häufigsten, um (zeitliche) Flaschenhälse bei der Programmierung zu finden.

Aber wie erhält man diese Zeiten? Wenn man nur einen kleinen Teil seines Programms beobachten möchte und die Zeit messen möchte, die es braucht, macht man das wahrscheinlich so:

$start = microtime(true);
 // Hier einige Befehle, die gemessen werden sollen
 $end = microtime(true);
 $diff = $end - $start;
 echo "Benötigte Zeit: " . $diff;

Das ist meistens völlig ausreichend für den Anfang, um einen kurzen Überblick zu finden. Wenn das Programm aber sehr groß ist, und man nicht tausende dieser Messungen einbauen möchte, kann man gleich das ganze Script profilen lassen.

Wir machen das ganze mal praktisch an einem kleinen Beispiel:

class User
{
	private $username;
	private $newsletter;

	public function __construct() {
		$this->username = $this->getRandomString(8);
		$this->newsletter = rand(0, 1);
	}

	public function getUsername() {
		usleep(500000);
		return $this->username;
	}

	public function getNewsletter() {
		return $this->newsletter;
	}

	private function getRandomString($stringLength) {
	    //srand ((double)microtime() * 1000000);
	    return substr(md5(rand()), 0, $stringLength);
	}
}

for ($i = 0; $i < 5; $i++) {
	$user = new User();
	if (rand(0, 1)) {
		echo $user->getUsername()."\n";
	} else {
		echo $user->getNewsletter()."\n";
	}
}

Nun muß ich noch XDebug in der php.ini aktivieren. Dazu aktiviert man einfach die PHP-Extension XDebug wie folgt in der php.ini:

[XDebug]
; Only Zend OR (!) XDebug
zend_extension_ts=“C:\xampp\php\ext\php_xdebug.dll“
xdebug.remote_enable=true
xdebug.remote_host=127.0.0.1
xdebug.remote_port=9000
xdebug.remote_handler=dbgp
xdebug.profiler_enable=1
xdebug.profiler_output_dir=“C:\xampp\tmp“

Natürlich sollte man vorher die php_xdebug.dll downloaden und in den entsprechenden Ordner legen. Nachdem man die php.ini so geändert hat, wird für jedes PHP-Script ein sogenannter CacheGrind-Dump im Output-Dir abgelegt. Diese Datei kann, je nach Komplexität und Umfang des Script, auch mehrere hundert MB groß werden.

Nun führe ich das Script ganz normal aus, im Hintergrund wird dann die CacheGrind Datei erzeugt.

Die generierte cachegrind.out.2916 sieht so aus, und ist (noch) nicht wirklich brauchbar:

Öffnen und tabellarisch bzw. grafisch darstellen kann man diese Textdatei dann zum Beispiel mit dem Windows Programm WinCacheGrind:

Hier erkennt man zwar schon etwas, aber viel besser ist unter Linux KCachegrind, das sieht dann so aus:

Man schaue sich nun die Anzahl der Aufrufe sowie die Zeitwerte an, und kann unzweifelhaft feststellen, dass in unserem einfachen Beispiel die usleep-Funktion die meiste Zeit gebraucht hat. Aber auch getRandomString() ist nicht zu vernachlässigen, vielleicht könnte man da noch etwas optimieren. Bei großeren Programmen mit SQL-Abfragen und komplexeren Algorithmen und Abläufen wird das ganze natürlich noch viel interessanter, probiert es einfach mal bei euren großen Projekten aus!

Man kann sowohl nach den absoluten als auch den prozentualen Zeitwerten sortieren, sieht Callees und Caller, kann sich einen Call Graph anzeigen lassen usw, ein wirklich tolles Programm.

Ich würde auf jeden Fall für ernsthafte Profiler das KCachegrind empfehlen. Falls man gerade kein laufendes Linux-System zur Hand hat, ist es höchste Zeit, mittels VirtualBox und Ubuntu schnell eins aufzusetzen. Beides ist natürlich kostenlos, und nach einer Stunde ist es lauffähig. Man braucht auch keine umständlichen Dual-Boot-Sachen und zerschießt sich wohlmöglich sein System, VirtualBox kann „ein Betriebssystem in einem Fenster“ laufen lassen. Einfach mal ausprobieren und informieren.

Mittels Profiling kann man sehr einfach herausfinden, wie oft welche Funktion aufgerufen wird. Man erkennt ziemlich schnell, wieviele Datenbank-Queries gemacht werden und von wo diese kommen. Man sieht, wieviele Objekte erstellt werden und wo dies passiert (und wie lang das dauert).

Die gefundenen Flaschenhälse kann man dann beseitigen. Entweder durch effizientere SQL-Abfragen, bessere Algorithmen, Caching oder oder. Das ist von Fall zu Fall verschieden.

Mich würde interessieren, ob und wie ihr profiled, und was ihr dadurch für gewöhnlich an Fehlern/Flaschenhälsen findet und wie ihr sie behebt.