4.3 Debugging

Nun zeigt das GP-Blog keinerlei PHP-Fehlermeldungen mehr an. Zum Zeitpunkt der Entwicklung und insbesondere beim Zurückverfolgen auftretender Fehler in Live- und Staging-Umgebungen wünscht sich der Entwickler jedoch ein ganz anderes Verhalten: Meist ist es ihm wesentlich lieber, zu viele Information zu einem Fehler zu erhalten als zu wenige. Aus diesem Grund soll das GP-Blog nun mit rudimentären Debugging-Funktionalitäten ausgerüstet werden.

Diese ersetzen natürlich keinen echten Debugger, wie Sie sich ihn als professioneller Entwickler wünschen. Allerdings lassen sich immerhin die wichtigsten Funktionen direkt in den Code integrieren, um sie im Notfall zur Hand zu haben.

4.3.1 Debug-Ausgaben

Der wichtigste Punkt beim Debugging ist wohl die Analyse von aufgetretenen Fehlern. An dieser Stelle wird das Galileo-Press-Blog so erweitert, dass beim Auftreten eines Fehlers neben der aktuellen Fehlermeldung auch ein Backtrace ausgegeben werden kann, sofern sich die Applikation im Debug-Modus befindet. Zunächst muss dazu definiert werden, wie der Debug-Modus einzuschalten ist, wozu erneut eine Konstante innerhalb der Datei index.php definiert wird:

define( "BASEDIR", "gpblog/htdocs" );
define( "SCRIPT",  "index.php" );
define( "DEFAULT_ACTION", "list_entries" );
define( "DEBUG", true );

Listing 4.7 Debug-Modus einschalten

Wird die Konstante DEBUG auf true gesetzt, sind die Debugging-Funktionalitäten aktiv, bei false befindet sich das GP-Blog im Benutzer-Modus und es werden keine Debugging-Informationen dargestellt.

Als Nächstes muss innerhalb der Datei index.php noch die eigentliche Debugging-Ausgabe erfolgen. Diese über ein Template zu realisieren, wäre nicht sinnvoll, da dann eine weitere Komponente involviert wäre, die für Fehler beim Debugging verantwortlich sein könnte. Daher werden die entsprechenden Informationen einfach ausgegeben:

// ...
$blog = gpBlogController::getInstance();
$blog->run();
if ( DEBUG )
{
    echo "<h1>Debugging output:</h1>\n";
    echo ezcDebug::getInstance()->generateOutput();
}

Listing 4.8 Ausgabe der Debugging-Informationen

An dieser Stelle kommt zum ersten Mal die Debug-Komponente und ihre Hauptklasse ezcDebug ins Spiel. Das Singleton Pattern (siehe Abschnitt 2.3.4, »Lazy-Initialization«), welches ezcDebug implementiert, haben Sie bestimmt sofort wiedererkannt. Die Methode generateOutput() auf dem ezcDebug-Objekt generiert standardmäßig eine HTML-Ansicht aller gesammelten Informationen.

Leider ist der Code zur Ausgabe von Debugging-Informationen noch nicht komplett, denn im Fall eines fatalen Fehlers wird eventuell diese Codestelle nicht mehr erreicht. Aus diesem Grund wird der gleiche Code zur Ausgabe auch in die onError()-Methode der Klasse gpBlogExecutionHandler eingefügt, um sicherzugehen, dass keine Debugging-Informationen verschluckt werden.

public static function onError( Exception $e = null )
{
    $signals = gpBlogController::getInstance()->mainSignals;
    $message = $e !== null ? $e->getMessage() : "Unknown";
    $signals->emit( "fatal", $message );
    if ( DEBUG )
    {
        echo "<h1>Debugging output:</h1>\n";
        echo ezcDebug::getInstance()->generateOutput();
    }
}

Listing 4.9 Ausgabe der Debug-Informationen im Falle eines fatalen Fehlers

4.3.2 Fehlerinformationen

Die Debug-Komponente gibt nun Informationen am Ende des Skripts aus. Allerdings wurden bisher noch keinerlei Informationen gesammelt, weshalb diese Funktionalität nun ergänzt wird. Primär ist es erwünscht, detaillierte Informationen zu aufgetretenen Fehlern bereitzustellen. Aus diesem Grund haken wir an der Stelle ein, wo Fehler verarbeitet werden: In der Error-Action. Deren registerSlots()-Methode zum Registrieren der Fehlersignalverarbeitung wird wie folgt erweitert:

public static function registerSlots()
{
    gpBlogController::getInstance()->mainSignals->connect(
        "error",
        array( __CLASS__, "error" )
    );
    gpBlogController::getInstance()->mainSignals->connect(
        "fatal",
        array( __CLASS__, "fatal" )
    );
    if ( DEBUG )
    {
        gpBlogController::getInstance()->mainSignals->connect(
         "error",
         array( __CLASS__, "debug" )
        );
        gpBlogController::getInstance()->mainSignals->connect(
         "fatal",
         array( __CLASS__, "debug" )
        );
    }
}

Listing 4.10 Zusätzliche Signalverarbeitung bei aktivem Debugging

Die Registrierung der beiden Slots fatal und error ist bereits bekannt. An dieser Stelle wird beiden Slots jeweils eine neue, statische Methode zur Verarbeitung angehängt. Sollten Sie also das Debugging des GP-Blogs aktivieren und sollte an irgendeiner Stelle der Applikation eines der Signale error oder fatal gesendet werden, wird jetzt zusätzlich die Methode debug() aufgerufen.

public static function debug( $message )
{
    ob_start();
    debug_print_backtrace();
    $backtrace = ob_get_clean();

    ezcDebug::getInstance()->log(
        "Error with message '$message' occured." .
        "\nBacktrace:\n$backtrace",
        1
    );
}

Listing 4.11 Ausgabe eines Backtraces im Debug-Modus

Die Methode erwartet nur einen Parameter, die Meldung des aufgetretenen Fehlers. Allerdings kann es vorkommen, wenn das Signal error gesendet wird, dass ein zweiter Parameter hinzukommt, nämlich die URL für den Fortsetzungslink. Da diese zum Debugging unnötig ist, wird sie an dieser Stelle ignoriert. Die ersten drei Zeilen dieser Methode stellen dar, was man landläufig einen fiesen Hack nennt. Verzichten Sie also in eigenen Implementation lieber auf ein solches Vorgehen. Wir tun dies lediglich, um den Beispielcode nicht zu sehr aufzublähen. Mittels Output-Buffering wird die Ausgabe der PHP-Funktion debug_print_backtrace() abgegriffen. In einer echten Applikation sollte hier Gebrauch von debug_backtrace() gemacht werden, was den kompletten aktuellen Aufruf-Stack zurückgibt. Da dieses Array erst einer aufwendigen Verarbeitung unterzogen werden müsste, um einen lesbaren Backtrace zu erhalten, bedienen wir uns des Tricks, diese Aufbereitung von PHP selbst vornehmen zu lassen und erhalten über den Ausgabepuffer einen lesbaren Backtrace. Glücklicherweise lassen sich Output-Buffering-Aufrufe in PHP verschachteln.

Die eigentliche Arbeit der Methode befindet sich im letzten Teil der Aktion. Hier wird eine Debug-Log-Nachricht abgesetzt. Dazu wird erneut der Singleton-Mechanismus der Klasse ezcDebug bemüht; auf der erhaltenen Instanz wird die Methode log() aufgerufen. Die Methode erhält als ersten Parameter die Log-Nachricht, danach folgt das sogenannte Verbosity-Level. Diese Option bestimmt, welche Gewichtung der Log-Meldung zukommt. Bei der späteren Ausgabe steht diese Information ebenfalls zur Verfügung und kann verwendet werden, um beispielsweise eine farbliche Hervorhebung einzelner Nachrichten zu erzielen. Als optionaler, dritter Parameter kann ein Array mit zusätzlichen Informationen übergeben werden, wovon an dieser Stelle kein Gebrauch gemacht wird.

Intern benutzt die Debug-Komponente die Log-Komponente, um Meldungen zu speichern. Hierher rührt auch der letzte Parameter für weitere Informationen her. In Kapitel 15, »Logging«, erfahren Sie mehr über die Log-Komponente. Wenn Sie das interne Logging der Debug-Komponente beeinflussen wollen, können Sie sich über die Methode getEventLog() die entsprechende Instanz der ezcLog-Klasse besorgen und diese beliebig manipulieren. Denkbar ist zum Beispiel, statt standardmäßig in den Speicher für die spätere Ausgabe direkt in eine Datei zu loggen.

Sie können zu Debugging-Zwecken an unterschiedlichsten Stellen der Applikation beliebige Informationen loggen lassen. Es empfiehlt sich, entweder auf ezcDebug direkt zuzugreifen oder aber ein weiteres Signal zu implementieren, welches intern das zentrale Einschalten des Loggings übernimmt, damit nicht an jeder Stelle die Abfrage auf die DEBUG-Konstante erfolgen muss und nicht für jede Meldung ein kompletter Backtrace angezeigt wird.

4.3.3 Timing-Informationen

Neben der reinen Debugging-Information kann die Debug-Komponente auch Zeit-Informationen speichern, die Ihnen Aufschluss darüber geben, wie lang die Laufzeiten einzelner Teile einer Applikation sind: das zuvor ansprochene Profiling. Das Galileo-Press-Blog besteht bisher im Wesentlichen aus vier Ebenen, deren Ausführungszeiten nun gemessen werden sollen:

Dazu müssen an verschiedenen Stellen in der Applikation Aufrufe zu ezcDebug hinzugefügt werden. Zunächst in der Datei index.php, um die Laufzeit der gesamten Applikation zu messen:

// ...
if ( DEBUG ) ezcDebug::getInstance()->startTimer( "GP-Blog" );
$blog = gpBlogController::getInstance();
$blog->run();
if ( DEBUG ) ezcDebug::getInstance()->stopTimer( "GP-Blog" );
//...

Listing 4.12 Ausführungszeit festhalten

Bevor der Haupt-Controller des GP-Blogs seine Arbeit aufnimmt, wird mit Hilfe von ezcDebug ein Timer gestartet, der nach Beendigung des Controller-Laufs wieder beendet wird. Die Zeit zur Ausführung der Gesamtapplikation wurde somit erfolgreich gemessen. Als Nächstes sollen die Zeiten intern im Controller gemessen werden. Hierzu wird zunächst die init()-Methode des gpBlogControllers erweitert. Um die Übersichtlichkeit zu gewährleisten, werden einige Teile der Methode an dieser Stelle ausgeblendet. Den kompletten Sourcecode können Sie sich ohne die hier eingefügten Sequenzen in Abschnitt 3.3.2, »Initialisierung«, ansehen.

protected function init()
{
    if ( DEBUG ) ezcDebug::getInstance()->startTimer(
        "Main Controller Init",
        "Init"
    );
    // ...
    foreach ( $classes as $actionClass => $path )
    {
        if ( DEBUG ) ezcDebug::getInstance()->startTimer(
            "Action $actionClass init",
            "Init"
        );
        call_user_func(
            array( $actionClass, "registerSlots" ),
            $this->mainSignals,
            $this->actionSignals
        );
        if ( DEBUG ) ezcDebug::getInstance()->stopTimer(
            "Action $actionClass init"
         );
    }
   // ...
    if ( DEBUG ) ezcDebug::getInstance()->stopTimer(
        "Main Controller init"
    );
}

Listing 4.13 Zeitmessung für die Initialisierung der Aktionen

Zunächst wird erneut ein Timer gestartet. Wie Sie kurz zuvor gesehen haben, ist bereits ein anderer Timer aktiv. Da aber jeder Timer durch seinen Namen identifiziert wird, ist diese Verschachtelung kein Problem. Im Unterschied zum letzten Aufruf von startTimer() wird an dieser Stelle ein zweiter, optionaler Parameter übergeben, mit dessen Hilfe der Timer einer Gruppe namens Init zugeordnet wird. Die Gruppe dient später dazu, innerhalb der Anzeige eine Sortierung vorzunehmen.

Innerhalb der foreach-Schleife wird für jede Aktion die Methode registerSlots() aufgerufen und jeweils die Zeit gemessen, die eine Aktion dafür benötigt. Die jeweiligen Timer gehören ebenfalls zur Gruppe Init. Schließlich wird auch der Timer Main Controller Init am Ende der Methode gestoppt. Wie Sie sehen, können Zeitmessungen mittels startTimer() und stopTimer() beliebig tief verschachtelt und mehrere Messstrecken zu Gruppen zusammengefasst werden.

Zum Schluss soll die Ausführungszeit der run()-Methode gemessen werden. Auch hier werden große Teile der Methode der Übersichtlichkeit wegen ausgeblendet.

public function run()
{
    if ( DEBUG ) ezcDebug::getInstance()->startTimer(
        "Main Controller Run",
        "Run"
    );
   // ...
    if ( DEBUG ) ezcDebug::getInstance()->switchTimer(
        "Action Run",
        "Main Controller Run"
    );
    try
    {
        // ...
    }
    // ...
    if ( DEBUG ) ezcDebug::getInstance()->switchTimer(
        "Action Finished",
        "Action Run"
    );
    if ( DEBUG ) ezcDebug::getInstance()->stopTimer(
        "Action Finished"
    );
}

Listing 4.14 Zeitmessung der Ausführung

Auch in dieser Methode wird zu Beginn ein Timer gestartet und einer Gruppe zugeordnet, welcher die komplette Ausführungszeit der run()-Methode misst. Im Anschluss wurde die Initialisierung der Url-Komponente ausgeblendet, die Sie schon kennen. Als Nächstes erfolgt die Ausführung des Action-Controllers, die separat gemessen werden soll. Allerdings wird an dieser Stelle kein neuer Timer verwendet, sondern im soeben erzeugten Timer wird eine Zwischenzeit gestoppt. Mit dem Aufruf von switchTimer() wird ezcDebug mitgeteilt, dass die Zeit des vorhergehenden Timers gestoppt und gleichzeitig ein weiterer Timer gestartet werden soll. Der erste Parameter ist hierbei der Name des neuen Timers, der zweite entsprechend der Name des alten. Einen Timer zu wechseln, führt bei der späteren Ausgabe dazu, dass die aktuelle Zeit des Wechsels notiert wird, anstatt eine völlig neue Messung zu starten. Es handelt sich also um eine Zwischenzeit.

Zum Ende der Methode wird erneut der Timer gewechselt, um dezidiert das Ende der Action-Ausführung zu dokumentieren. Anschließend wird der Timer beendet.

4.3.4 Debug-Ausgabe

In den vorhergehenden Abschnitten haben Sie gesehen, wie man mit Hilfe von ezcDebug zum einen Debug-Nachrichten loggt und zum anderen Zeitmessungen vornimmt. Natürlich interessiert nun noch, wie die entsprechende Ausgabe dazu aussieht. Am besten eignet sich zur Vorführung eine Aktion, die einen Fehler erzeugt: zum Beispiel die Aktion show_entry ohne ID-Parameter.

Abbildung 4.1 Debugging Output mit ezcDebug

An erster Stelle auf der dargestellten Webseite sehen Sie die Standardfehlerausgabe, wie sie in Abschnitt 4.2.2, »Die Fehler-Aktion«, realisiert wurde. Im Anschluss daran folgt die passende Debugging-Ausgabe des Fehlers aus Abschnitt 4.3.1, »Debug-Ausgabe«. Eingeleitet von der Überschrift »Debugging Output« wird der Backtrace der Fehlermeldung angezeigt, vorangestellt ein paar Daten zum Logging, nämlich die Nummer der Nachricht sowie der Log-Level. Der Backtrace zeigt alle aktuellen Elemente des Aufruf-Stacks an, angefangen bei 0. Mit dem Aufruf der debug()-Methode können Sie die aufgerufenen Methoden zurückverfolgen.

Unter dem Call-Stack werden die Messdaten der gestarteten Timer ausgegeben. Zu jedem Timer werden der Bezeichner dargestellt, die Zeit, die der Aufruf benötigt hat (in Sekunden), die Anzahl der aufgetretenen Aufrufe sowie die durchschnittliche Ausführungszeit pro Aufruf. Zunächst sehen Sie die Sektion Init, welche die Initialisierung gemessen hat. Wie in Abschnitt 4.3.3, »Timing-Informationen«, gezeigt, wurde die Initialisierung der einzelnen Aktionen gemessen sowie die Initialisierungszeit des Haupt-Controllers insgesamt. Es überrascht nicht, dass alle Action-Controller ungefähr die gleiche Zeit zur Initialisierung benötigen, denn jede dieser Klassen registriert ja lediglich ein paar Signale und führt keine weiteren zeitraubenden Aktionen aus. Die Initialisierung des Haupt-Controllers benötigt hingegen mehr als die dreifache Zeit, auch wenn die Zeitspanne von 0,002 Sekunden nicht wirklich lang ist. Zuletzt wird noch die aggregierte Gesamtzeit der Initialisierung angezeigt, welche die vier enthaltenen Timer summiert und den Durchschnitt anzeigt.

In der zweiten Sektion der Timer-Ausgabe wird die Zeitmessung der run()-Methode dargestellt. Sie erinnern sich, dass in dieser Methode nicht mehrere verschachtelte Timer verwendet wurden, sondern der aktuelle Timer mehrfach Zwischenzeiten nahm. Dies ist auch unmittelbar erkennbar: Anstatt mehrere einzelne Timer zu zeigen, wird der Timer »Main Controller Run« mit 100 % der Zeit dargestellt und untergeordnet die Wechselzeitpunkte mit den Bezeichnern »Action Run« und »Action Finished«. Beeindruckend ist, dass die Ausführung des Aktion-Controllers mehr als 90 % der Ausführungszeit der run()-Methode in Anspruch nimmt: Der Timer »Action Run« wurde nach circa 7 % der Ausführungszeit gestartet und nach circa 99,9 % der Zeit wieder gewechselt. Der Lauf der Aktion hat also grob geschätzt 93 % der Ausführungszeit beansprucht.

Zum Schluss wird die Gesamtausführungszeit, die mit Hilfe des Timers in der Datei index.php gemessen wurde, angezeigt.

Ihr Kommentar