PHPGangsta - Der praktische PHP Blog

PHP Blog von PHPGangsta


Archive for the ‘Backtrace’ tag

PHP hat Ticks

with 14 comments

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.

Written by Michael Kliewe

August 6th, 2010 at 7:39 pm