Using Xdebug to Trace Functions

I’ve been relying on Xdebug quite a lot in recent years to step through PHP code, analyze stacktraces, inspect variables, profile applications, and more. Recently I needed to find out why a function call was taking so long to execute. Using Xdebug’s trace functionality made this task pretty simple. Here’s how Xdebug describes function tracing:

Xdebug allows you to log all function calls, including parameters and return values to a file in different formats.


Those so-called “function traces” can be a help for when you are new to an application or when you are trying to figure out what exactly is going on when your application is running. The function traces can optionally also show the values of variables passed to the functions and methods, and also return values. In the default traces those two elements are not available.

Having Xdebug trace your function calls is simple enough, and well-documented across the web. You can see my recommended settings at the bottom of this page, and here’s a good resource on the subject: http://devzone.zend.com/1135/tracing-php-applications-with-xdebug/

In my particular case, I wanted to see why a specific function call (or really a few lines in a Drupal module file) was taking so long to execute. To achieve this, I wanted to use the xdebug_start_trace  and xdebug_stop_trace()  instead of just enabling auto trace in my php configuration. As an aside I have successfully parsed a file with 3,013,007 lines using the methods outlined here. It took 2.5 minutes to open the file, but it worked perfectly once it opened.

Here’s the code I executed (via the “execute php code” provided by the Drupal devel module):

After running that, I was happy to see a mysite_cache_clear.xt file in my home directory. I opened the file in Vim and wasn’t surprised to see more than 400,000 lines. The information was there, but how would I comb through it?

I found a few tools on github that aimed to make it easier to browse these files, but they weren’t really what I was looking for. I needed a way to quickly identify what function calls were “slowing things down.”

Here’s what the output looks like in plain text:

Screenshot_2015-10-08_09-08-11The first column is very important. It’s the time index and it is useful in determining how long a function took to execute. In the example above everything was called and executed very quickly. What if you have a thousand function calls that all take up a small chunk of time? Well, it adds up. So, how can you possibly tell what function calls really took “too much” time? In order to do that you need to be able to view function calls in terms of their hierarchy (so that you can see which parent’s children took too long to execute). Let me show you what I was after:

Screenshot_2015-10-08_09-17-03

What you’re looking at is the output when you collapse everything down to just the top-level function calls. If you look at the code that I executed you’ll see calls to module_invoke_all()  and cache_clear_all()  (which is in a loop). We can clearly tell, now that we’ve focussed on just the top-level calls, that module_invoke_all()  is taking a LONG time to execute (nearly 25 seconds).

Let me stop for a minute and explain how I achieved that collapsed output. I’m a die-hard Vim user. Vim handles folding really well. Xdebug provides a syntax file that gives the basic coloring (notice in the first screenshot that the -> gets colored, and the line number too). Unfortunately folding definitions aren’t provided for this xdebug trace output. I wrote a simple ftplugin to handle this, and I’ve included it in a small git repo that also contains the syntax declarations too.

Please check out xdebug-trace-for-vim now (and read the README).

Alright, back to business. Using the folding behavior in Vim we can now start drilling down ( zo  to open a fold, zc  to close one) to see what’s causing the delay. Here’s what opening module_invoke_all()  gives us:

Screenshot_2015-10-08_09-44-36You can see some time starting to build up between some of these calls. It’s up to you, as the developer, to determine what kind of bottlenecks you want to address. I ask myself, “Am I okay with those first view call_user_func_array()  calls taking a second to execute?” Well, it’s not ideal, but I’ll leave them collapsed because I’m really curious what’s taking us from 4 seconds to 21 seconds. Here’s what happens when I drill down into that 4.8547 call (and go a few levels deeper):

Screenshot_2015-10-08_09-48-02Here’s what the 5.7182 call looks like:

Screenshot_2015-10-08_09-49-23And so on and so forth…

Eventually you will be able to determine what’s taking so long. If there isn’t enough information to tell you exactly why a function is taking so long, you can enable parameter logging (commented out below) for the trace output. If you use my Vim folding plugin, please do read the README regarding this. Within it I give a perl command to cleanup newlines.

In case you’re curious, eventually I drilled down to a few function calls that were repeating tens of thousands of times (see the 5.8093 above? I drilled into that and found a call that repeats 50,000+ times), and there were a few calls that didn’t repeat as much but took far too long to execute.

Lastly, if you open a fold (zo) and nothing seems to happen, keep opening (zo zo zo zo) until it eventually opens. I’ll have to debug this someday.


Example xdebug Settings

 

Tagged with: , , ,
Posted in Development

Leave a Reply

Your email address will not be published. Required fields are marked *

*