Path

ez components / documentation / api reference / 2008.2 / debug

eZ Components 2008.2

Debug

[ Tutorial ] [ Example stylesheet ] [ Class tree ] [ Element index ] [ ChangeLog ] [ Credits ]

Introduction

The Debug component provides an API to log and time debug events. This component depends mainly on the EventLog component. The functionality of the Debug component is divided into two parts:

  • Writing debug messages.
  • Measuring the execution time.

Writing a debug message is almost the same as writing a message with the EventLog component. However, there is one major distinction: messages written with the EventLog component are intended to be written to a storage element (such as a log file or database). Messages written with the Debug component are usually directly formatted and displayed. Note that the Debug::log() method has a slightly different signature than the EventLog::log() method.

Timing information is captured by starting and stopping timers using the public methods from ezcDebug. The timing information is stored in a structure with raw data. This structure should be formatted and displayed at the end of the script.

The Debug summary output can be formatted with an implementation from ezcDebugOutputFormatter. The default, and currently only, formatter is ezcDebugHtmlFormatter. This HTML formatter transforms the raw log messages and raw timing information into a HTML string for display.

Class overview

The following classes are the most important to use, extend or implement:

ezcDebug
This provides the public API for writing Debug messages and capturing timing information.
ezcDebugOptions
Allows you to switch on debug stack traces and to configure their appearance.
ezcDebugOutputFormatter
ezcDebugOutputFormatter provides an interface for the debug output format. New implementations can format the raw log messages and timing information to any output format.
ezcDebugHtmlFormatter
ezcDebugHtmlFormatter is an implementation of the ezcDebugOutputFormatter interface. This formatter reads the raw log and timing information and returns it as an HTML string. This string can be output directly to an HTML page.

See the API documentation for more information.

Usage

Writing a log message to file

The following script writes a message to the Debug component. At the end of the script, the log message is formatted and printed.

  1. <?php
  3. require_once 'tutorial_autoload.php';
  4. date_default_timezone_set( "UTC" );
  6. // Get the one and only instance of the ezcDebug.
  7. $debug = ezcDebug::getInstance();
  9. // Write a log message with verbosity 1.
  10. $debug->log( "Connecting with the Payment server", 1 );
  12. $debug->log( "Connected with the Payment server", 2, array( "source" => "shop", "category" => "payment" ) );
  14. // Get HTML output.
  15. $output = $debug->generateOutput();
  17. echo $output;
  18. ?>

Writing log messages is almost the same as writing them to the EventLog component. As a matter of fact, the EventLog component is internally used by Debug.

Further information about writing log messages can be found in the EventLog component.

Timers

The timers from ezcDebug can be used for two purposes:

  • Timers measure the time between two points in the program.
  • Accumulators get the current time after a certain point (for example after starting the script).

Both methods are executed with ezcDebug::startTimer(), ezcDebug::stopTimer() and ezcDebug::switchTimer(). The next script demonstrates the usage of these methods:

  1. <style type="text/css">@import url("example_stylesheet.txt");</style>
  2. <?php
  4. require_once 'tutorial_autoload.php';
  5. date_default_timezone_set( "UTC" );
  7. // Get the one and only instance of the ezcDebug.
  8. $debug = ezcDebug::getInstance();
  10. // Start the accumulator.
  11. $debug->startTimer( "Program runtime", "Accumulators" );
  12. $debug->switchTimer( "Start", "Program runtime" );
  14. // Measure the time of writing "hello world".
  15. // The name of the timer is: "Hello world" and it will be placed in the group: "output".
  16. $debug->startTimer ("Hello world", "output" );
  17. echo "Hello world<br/>";
  18. $debug->stopTimer( "Hello world" );
  20. // Replace the "Start" timer for "Half the way".
  21. $debug->switchTimer( "Half the way", "Start" );
  23. // Measure the time of writing "cruel world".
  24. $debug->startTimer( "Goodbye cruel world", "output" );
  25. echo "Goodbye cruel world<br/>";
  26. $debug->stopTimer( "Goodbye cruel world" );
  28. // Stop the last timer.
  29. $debug->switchTimer( "Stop", "Half the way" );
  30. $debug->stopTimer( "Stop" );
  32. // Get HTML output.
  33. $output = $debug->generateOutput();
  35. echo "<br/><br/>";
  36. echo $output;
  37. ?>

The output is as follows (if the CSS stylesheet is used that is available through "Example Stylesheet" in the menu):

img/debug_tutorial_timers.png

The output has two groups: output and accumulators. There are two timers in the "output" group: "Hello world" and "Goodbye cruel world".

The "accumulators" group has one timer called "Program runtime". This timer took a total of 0.00034 seconds. In this timer are several "switch timers". These show the time since the "Program runtime" was started.

Recursive timers

You can also time repeating code blocks. For example, you can measure the time a PHP statement takes in a loop. The Debug timer will calculate the average time of the repeating statement and display it in the debug summary. See the next example:

  1. <style type="text/css">@import url("example_stylesheet.txt");</style>
  2. <?php
  4. require_once 'tutorial_autoload.php';
  5. date_default_timezone_set( "UTC" );
  7. // Get the one and only instance of the ezcDebug.
  8. $debug = ezcDebug::getInstance();
  10. // Start the accumulator.
  11. $debug->startTimer( "Script runtime", "Accumulators" );
  13. // Store the name of the accumulator.
  14. $accumulatorName = "start";
  15. $debug->switchTimer( $accumulatorName, "Script runtime" );
  17. // Time the loop.
  18. $debug->startTimer ( "Five times Hello world", "output" );
  19. for( $i = 0; $i < 5; $i++ )
  20. {
  21. // Time the "Hello world" only.
  22. $debug->startTimer ( "Hello world", "output" );
  23. echo "Hello world<br/>";
  24. $debug->stopTimer( "Hello world" );
  26. // Store the accumulator.
  27. $debug->switchTimer( "After: hello world", $accumulatorName );
  28. $accumulatorName = "After: hello world";
  29. }
  30. $debug->stopTimer( "Five times Hello world" );
  32. // Stop the accumulator
  33. $debug->switchTimer( "stop", $accumulatorName );
  34. $debug->stopTimer( "stop" );
  36. // Get HTML output.
  37. $output = $debug->generateOutput();
  39. echo "<br/><br/>";
  40. echo $output;
  42. ?>

The resulting output is as follows (if the CSS stylesheet is used that is available through "Example Stylesheet" in the menu):

img/debug_tutorial_recursive_timers.png

Stack traces

Sometimes it is useful to get a stack trace for log messages. To achieve this, there are 2 possibilities offered by the Debug component:

1) Global stack trace switch

  1. <?php
  3. require_once 'tutorial_autoload.php';
  5. $debug = ezcDebug::getInstance();
  7. // Switch on global stack traces.
  8. $debug->options->stackTrace = true;
  10. // Configure stack trace appearance.
  11. $debug->options->stackTraceDepth = 3;
  12. $debug->options->stackTraceMaxData = 32;
  13. $debug->options->stackTraceMaxChildren = 3;
  14. $debug->options->stackTraceMaxDepth = 2;
  16. // ... somewhere else ...
  18. // Log with no explicit stacktrace indication
  19. ezcDebug::getInstance()->log(
  20. 'Function testThis() has been called.',
  21. ezcLog::NOTICE,
  22. array( 'additional' => 'info' )
  23. );
  25. // ... somewhere else ...
  27. // Print out log with stacktraces.
  28. $debug = ezcDebug::getInstance();
  29. echo $debug->generateOutput();
  31. ?>

In this example, the debug options (see: ezcDebugOptions) are used to switch on stack traces globally. The effect is, that whenever a debug message is logged, a stack trace is logged in addition. When printing the debug information, stack traces in the manor of Xdebug are included in the output.

Beside the $stackTrace option itself, the appearance of the stack traces is configured. This configuration only takes effect, if Xdebug is not installed. In this case, an own implementation is used to retrieve stack traces that look almost exactly like the Xdebug version. If Xdebug is installed, its internal settings will be used.

The possible options for stack traces are:

$stackTraceDepth
Defines the number of nested function calls included in the trace (starting at the most recent one). This option also affects Xdebug generated stack traces. The default is 5.
$stackTraceMaxData
Maximum bytes of data to be dumped for variable values. The default is 512.
$stackTraceMaxChildren
Defines the maximum number of child elements that will be dumped for array and object structures. The default value is 128.
$stackTraceMaxDepth
Maximum level of iteration that is performed when dumping nested array or object structures.

2) Local stack trace switch

If stack traces are not desired with every lock message, it is also possible to activate them when the log message is issued:

  1. <?php
  3. require_once 'tutorial_autoload.php';
  5. // ... inside some function...
  7. // Log with no explicit stacktrace indication
  8. ezcDebug::getInstance()->log(
  9. 'Function testThis() has been called.',
  10. ezcLog::NOTICE,
  11. array( 'additional' => 'info' ),
  12. // Enable stack trace
  13. true
  14. );
  16. // ... somewhere else ...
  18. // Print out log with stacktraces.
  19. $debug = ezcDebug::getInstance();
  20. echo $debug->generateOutput();
  22. ?>
Last updated: Mon, 05 Jan 2009