Tracing PHP Applications with xdebug

Other Articles in the Series

Part One: Introducing xdebug
Part Two: Tracing PHP Applications with xdebug
Part Three: Profiling PHP Applications With xdebug
Part Four: Debugging PHP applications with xdebug
Part Five: Creating Code Coverage Statistics with xdebug

Welcome to the second installment of our five-part series of articles on xdebug, the PHP developer‘s swiss army knife extension. The installation of xdebug and its basic features were covered last week. This week, we will explore the tracing feature of xdebug.

As programs, especially object-oriented ones, become more and more complex, the individual code blocks become smaller and smaller. Small code blocks make a program easier to maintain, since changes and additions can be introduced without changing existing code. If you look at an object-oriented PHP program for the first time, however, it seems that the program never does any actual work, but just comprises of a seemingly endless series of delegations.

Though it may sound awkward, this is a sign of quality of object-oriented code. Each piece of code should do exactly one thing and different concerns should be separated. As a rule of thumb, the source code of one method should fit on the screen without scrolling.

These small code bits make software maintainable, but on the other hand it becomes very difficult to understand the actual control flow of a program. While it is rather easy to understand a single class or method, one can have a really hard time trying to figure out the control flow of a complex object-oriented application just by looking at the code.

We could put numerous var_dump() statements into the code to get a feeling for what is going on. As we have learned last week, xdebug beautifies the var_dump() output to make it even more readable. Another option is to add logging to the application. Both techniques, however, require a modification of the source code and come at a performance penalty, since even when the logging is turned off, or commented out, these lines must be parsed. If PHP was a compiled language, we could wrap the var_dump() or logging code into a preprocessor macro, and thus ignore it in a production build. As soon as a problem turns up in a production build, we‘d have to switch back to a debug build, which is not always easy.

Creating a trace log

Instead of manually adding logging code to the program code, we can have xdebug create a trace log while the program executes. A trace log is a list of every function and method call a PHP script has performed. The advantage is that every call appears in the trace log, not just the information we chose to log explicitly. On the other hand, the longer a trace logs get, the harder to read it becomes.

A trace log will usually differ with each program run, because the program‘s execution path depends on the input data, and the input data fed to the program will probably vary from request to request. Imagine a web application that executes a command issued by a GET parameter. Depending on the command, different code is being executed, resulting in completely different trace logs for each run.

While looking at a trace log helps us understand the control flow of a program by showing one execution path, is is virtually impossible to visualize all execution paths of that same program, unless the program is really simple. One if statement introduces two possible execution paths to a program. With every further if statement, the number of (theoretically) possible execution paths multiplies by two. This is what makes testing software so difficult: in a large program, there are just too many possible execution paths to even think about them all.

But let us now get into creating a trace log. xdebug supports two different trace log formats. By default, trace logs are created in nicely formatted way so that the human user can easily read them. If you want to process the trace logs with another computer program, you should configure xdebug to log in the computer-readable format. The computer-readable format is easier to parse, because in contains no fixed size columns.

If you are using auto prepend scripts that you want to show up in the trace log, or want to create a full trace log of every script that is run, you can put

xdebug.auto_trace=On
xdebug.trace_output_dir=c:\data

into php.ini. As always, remember to restart your web server after changing php.ini.

The second setting defines the path where xdebug will store the trace logs. This path defaults to /tmp which is a good choice on Unix, but calls for trouble on Windows, since the directory c:\tmp (provided that the c: is the current drive) usually does not exist. So you either need to create this directory or specify another existing directory, otherwise xdebug will not be able to create trace logs since has nowhere to store them.

Because trace logs get large, the are not kept in memory, but are written to the disk. As you can imagine, the application will run a multitude slower with tracing enabled since every function and method call at PHP level results in a line written to the log.

Please note that it is not possible to start tracing at script runtime with

ini_set(‘xdebug.auto_trace‘, ‘On‘);

because auto prepend scripts are executed before your the main script is even started, which would prevent the prepend script to be traced.

Tracing a part of an application

As trace logs grow to a considerable size quickly, it is a good idea to only create a trace log for the "interesting" part of your application instead of - for example - creating a trace log of the application‘s initialization process over and over again.

Let us have a look at how to create a trace log of a simple recursive function, the factorial function, that starts and stops trace logging at runtime. If you have already activated tracing in php.ini, you will see a warning telling you that tracing is already active for the script.

<?php
xdebug_start_trace(‘c:/data/fac.xt‘);
print fac(7);
function fac($x)
{
if (0 == $x) return 1;
return $x * fac($x - 1);
}
xdebug_stop_trace();
?>

As you can tell from the path and filename of the trace log, I have run this example on Windows. If you work on Unix, you must use a different file name, of course. The function xdebug_start_trace starts the trace logging, and xdebug_stop_trace stops trace logging. When this program is run with the xdebug extension enabled, the following trace file is created:

TRACE START [2007-10-26 12:18:48]
0.0068      53384     -> fac() C:\www\fac.php:5
0.0069      53584       -> fac() C:\www\fac.php:10
0.0069      53840         -> fac() C:\www\fac.php:10
0.0070      54096           -> fac() C:\www\fac.php:10
0.0070      54376             -> fac() C:\www\fac.php:10
0.0071      54656               -> fac() C:\www\fac.php:10
0.0072      54936                 -> fac() C:\www\fac.php:10
0.0072      55216                   -> fac() C:\www\fac.php:10
0.0073      55392     -> xdebug_stop_trace() C:\www\fac.php:13
0.0237      55392
TRACE END   [2007-10-26 12:18:48]

On each line, the first column shows the total execution time. The second column is the amount of memory the script was consuming at the time. The last column shows the file, line and function name. xdebug indents each function call according to the call stack level for better readability.

If you want xdebug to show an additional memory delta column in the trace log, add

xdebug.show_mem_delta=On

to php.ini. The memory delta is the difference between the memory size in the current line and the previous line. You can configure this setting at runtime with ini_set, but only before tracing has been started.

The function xdebug_start_trace has an optional second parameter. You can use one or more of the following three options: XDEBUG_TRACE_APPEND appends to an existing trace file, rather than overwriting the file. When XDEBUG_TRACE_COMPUTERIZED is set, xdebug creates a computer-readable trace log rather than human readable log. Using this parameter has the same effect as setting xdebug.trace_format to 1. The parameter XDEBUG_TRACE_HTML makes xdebug format the trace log as HTML.

The following screen shot shows an HTML-formatted xdebug trace log:

Adding more information to the trace log

We can also configure xdebug to log the parameters that were passed to a function. This is very helpful to better understand the program‘s control flow, since you can see the values the program deals with.

 

Logging parameters in a trace log is controlled by the configuration setting xdebug.collect_params, which was already introduced in last week‘s article. xdebug.collect_params takes a numeric parameter, with 0 meaning no additional information, and 4 meaning to display the variable name and always the full contents of each function parameter. A value of 3 will display name and parameter, truncating long variable content according to the formatting rules defined by xdebug.var_display_max_data, debug.var_display_max_children, and xdebug.var_display_max_depth that we also already covered last week.

Here is an excerpt of our trace log with the logging of function parameters activated:

    0.0033      54320     -> fac($x = 7) C:\www\fac.php:6
0.0034      54432       -> fac($x = 6) C:\www\fac.php:11

Let us add even more information. Using

xdebug.collect_return=On

we can configure xdebug to also log the return values of each function. This makes the trace a little more difficult to read, but looking at the log of our factorial function, you can see how each recursively calculated factorial is being returned:

TRACE START [2007-10-26 12:30:04]
0.0133      55704      +48     -> fac($x = 7) C:\www\fac.php:8
0.0133      55840     +136       -> fac($x = 6) C:\www\fac.php:13
0.0134      56096     +256         -> fac($x = 5) C:\www\fac.php:13
0.0134      56352     +256           -> fac($x = 4) C:\www\fac.php:13
0.0134      56632     +280             -> fac($x = 3) C:\www\fac.php:13
0.0135      56912     +280               -> fac($x = 2) C:\www\fac.php:13
0.0135      57192     +280                 -> fac($x = 1) C:\www\fac.php:13
0.0135      57472     +280                   -> fac($x = 0) C:\www\fac.php:13
>=> 1
>=> 1
>=> 2
>=> 6
>=> 24
>=> 120
>=> 720
>=> 5040
0.0140      57648     +176     -> xdebug_stop_trace() C:\www\fac.php:26
0.0140      57648
TRACE END   [2007-10-26 12:30:04]

As you can see, we have also turned on xdebug.show_mem_delta in this example.

Naming the trace log

Until now, we have explicitly defined the name of our trace log file. This does not always make sense, though. If you need separate trace logs depending on input data or the application state, for example, it is better to have xdebug automatically pick a name. xdebug can pick a name for your trace log, regardless of wether you use the xdebug.auto_trace setting or the xdebug_start_trace() function to activate tracing. In the latter case, just pass an empty argument list to the function, and xdebug will automatically choose a trace file name.

The file name of an xdebug trace always starts with trace. and has the extension .xt. The name part between the two dots defaults to the CRC checksum of the working directory. By the setting xdebug.trace_output_name, you can define another file name. xdebug.trace_output_name takes a string as argument that can contain various format specifiers. The most important format specifiers are:

 

• %c for the CRC checksum of the current working directory
• %p for the process id
• %r for a random number
• %u for a timstamp with microseconds
• %H the $_SERVER[‘HTTP_HOST‘]
• %R the $_SERVER[‘REQUEST_URI‘]

Using a clever combination of these format specifiers, you can have xdebug create a number of trace logs and still keep them separate even in complex scenarios like with virtual hosts or concurrent request.

In most cases, you will want to create a trace log for one single run of a script. Therefore, xdebug overwrites existing trace logs of the same name by default. You can configure xdebug to append to an existing file by setting

xdebug.trace_options=1

in php.ini. This might be useful when you tunnel all requests of your application through one index.php file or if you want to trace multiple programs runs into one file because you use different input data for each run. I would recommend keeping a separate trace log for each program run. It is easy to keep them separate by choosing a clever name using the xdebug.trace_output_name setting.

If you need to know at script runtime which trace log name xdebug has chosen, you can call the function xdebug_get_tracefile_name((). You might want to include this name in the script‘s output or save the generated HTML for later reference. Especially when errors occur, it can be very useful to have access the actual output the program has produced when analyzing the trace log.

Conclusion

The function tracing feature of xdebug is very useful. You can create logs in your application without adding a single call to a logger function. Since all function calls are logged, you will always have the relevant information in the log file, whereas with a explicit logger function, you might end up adding more and more logger calls until you finally have the relevant information in the log.

You can use tools like grep to find relevant entries or sections in the trace logs, or even write a small PHP program that parses the trace log for you. Tracing is no replacement for a debugger, though. We will look into the debugging features of xdebug in the fourth part of this series.

You should never activate trace logging on a production site, because that would absolutely kill your performance as one line has to be written to a file for every function call in your PHP script. That said, you should never install xdebug on a production server, not because it is not stable or insecure, but just because you don‘t want somebody to accidentally turn on trace logging, profiling, or even debugging.

This concludes this‘s weeks dose of xdebug, thanks for joining in on the second installment of this five-part article series on xdebug. Next week we will explore how to profile PHP applications with xdebug. Profiling an application is the first step in optimizing it, because you need to know where your application spends most time, before you can figure out how to make your application faster.

So, make sure you check back here next week for the third part in this series of xdebug articles. Until then: Happy tracing - with xdebug enabled, of course.