Tracing PHP Applications with xdebug

      3 Comments on Tracing PHP Applications with xdebug

Tracing PHP Applications with xdebug

By: Stefan Priebsch

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

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.

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:

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:

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:

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.

About the author:

Stefan Priebsch has been solving IT problems for over 25 years.
He is founder and CEO of e-novative GmbH, one of the first German IT
consultancies offering PHP-based solutions.
Stefan holds a university degree in computer science, and
is an internationally recognized PHP expert, book author, trainer and consultant.
You can reach him at stefan.priebsch@e-novative.de.

About Cal Evans

Many moons ago, at the tender age of 14, Cal touched his first computer. (We're using the term "computer" loosely here, it was a TRS-80 Model 1) Since then his life has never been the same. He graduated from TRS-80s to Commodores and eventually to IBM PCs.   For the past 10 years, Cal has worked with PHP and MySQL on Linux OSX, and when necessary, Windows. He has built on a variety of projects ranging in size from simple web pages to multi-million dollar web applications. When not banging his head on his monitor, attempting a blood sacrifice to get a particular piece of code working, he enjoys building and managing development teams using his widely imitated but never patented management style of "management by wandering around". Cal is happily married to wife 1.33, the lovely and talented Kathy. Together they have 2 kids who were both bright enough not to pursue a career in IT. Cal blogs at http://blog.calevans.com and is the founder and host of Nomad PHP