Function Tracing with XDebug

Integrating XDebug into your IDE opens up a world of powerful debugging fu, but there's more to XDebug than that. There is an API you can leverage for alternate ways of peering into what's going on during that page load.

In this post I'll demonstrate some basic function tracing and related configurations.

xdebug_start_trace() and xdebug_stop_trace(), starts and stops logging of function related data. This data includes time, memory, file, function, line number, and nesting level information for each function that gets called. You can wrap your entire app between those functions, or you can wrap a small section of code.

It may or may not seem practical, but I'll wrap an entire Drupal app for this example.


require_once DRUPAL_ROOT . '/includes/';

By default, XDebug will log the results of the trace to a file in /var/tmp. The file name will begin with the word trace. You will need to run a page with the trace code on once to find it. The default configuration is set to append the file with each run, but you can change that setting, and where the files are written to in your php.ini file. Take a look at phpinfo() for your current xdebug configurations and reference the docs linked above for their meaning.

On my system, the file ended up being: /var/log/trace.665686041.xt

The format of the file looks something like this:

    0.4394   81359120       -> drupal_alter() /Users/mike/projects/unicorns/includes/
    0.4394   81359264         -> is_array() /Users/mike/projects/unicorns/includes/
    0.4394   81359624         -> module_implements() /Users/mike/projects/unicorns/includes/

This is the default format, but you can choose other formats by defining xdebug.trace_format (default is 0), including a "computer format" (1) which has rows for the entry and exit of each function, and HTML (2).

I wanted to see memory usage in this log as well, so I set xdebug.show_mem_delta=1 in my php.ini file. With this enabled, memory usage in bytes is added as the 3rd column.

    1.4390  135115016      +32             -> variable_get() /Users/mike/projects/unicorns/includes/
    1.4390  135115080     +192                 -> drupal_static() /Users/mike/projects/unicorns/includes/
    1.4391  135172280   +57296             -> _registry_check_code() /Users/mike/projects/unicorns/includes/

- First column: seconds since the PHP script started
- Second column: total memory being used
- Third column: memory difference from start to end of the function

From here you can view the logs to see what's going on with whatever you have wrapped in the trace functions.

Another way to consume the data would be to use tail -f to monitor the log.

$ tail -f /var/log/trace.665686041.xt

That's just a blast of information though. It might expose something that hangs, but there's too much information scrolling by to be useful.

You could however pipe the output into something like awk to filter out functions that use more than 1 Mb.

$ tail -f /var/tmp/trace.665686041.xt |awk '($3 > 1024000) { print }'

You could use something like this to monitor for high memory usage as you click through various sections of a site. Keep in mind, in the awk statement, $2 is total memory usage, so you could set a threshold to find out where memory might be spiking.

You can use awk to do this without tailing the log as well. In this command, cat will print the entire file to the screen. The output is piped through awk to only display rows where the memory usage is greater than 1024000.

$ cat /var/tmp/trace.665686041.xt |awk '($3 > 1024000) { print }'

There are tools available to visualize XDebug logs, but the point here is that we can leverage XDebug API very easily without any other tools.

Take a look at the function trace and other XDebug documentation for more ways to level up your debugging fu.

Be sure to remove the trace code and clear your logs when you're done. These files can get big!