Profiling PHP with Xdebug

Posted on: Friday March 22, 2013

My last post was about using ab and jmeter to get some performance benchmarks on a website. Now, I figure I should probably mention how to profile your application to look for memory leaks, bad calls, and what portion of the code is taking the most amount of time.

First thing to do is get xdebug installed. There are several ways to go about this, the easiest being using a package manager to do the hard work for you. For example, if you're running Ubuntu with the default php from apt-get, you would do:

sudo apt-get install php5-xdebug

Failing that, the xdebug site has a full set of instructions on how to install and configure it: http://xdebug.org/docs/install

Okay! Now that it's installed (and presumably working), jump into php.ini (usually going to be in /etc/php.ini on linux systems, I hear it's in /usr/local/etc on freeBSD for example).

There are a couple of configuration settings you can set in order to turn on profiling. Here are how they work (and they're all listed here as well: http://xdebug.org/docs/profiler):

xdebug.profiler_enable=1 - This will turn on profiling for all requests, which is not a great idea as it will generate a lot of cachegrind files quickly.

xdebug.profiler_enable_trigger=1 - This turns on profiling if XDEBUG_PROFILE=1 is present in the GET/POST, or if you have a cookie set with that name (content doesn't matter)

xdebug.profiler_output_dir=/tmp - Sets the profiler's output directory!

xdebug.profile_output_name=cachegrind.out.%t - This will name the file "cachegrind.out.{timestamp}". There are lots of options and you can see them here http://xdebug.org/docs/all_settings#trace_output_name

So, you usually want to turn on profiler_enable_trigger, and then pick out a page you want to profile (maybe one that is fairly slow) and then add ?XDEBUG_PROFILE=1 to the end of the url. Go check the directory you set in profiler_output_dir, and check out the cachegrind files it generated.

What the heck do you do with cachegrind files?

If you're on Windows, you'll want to dig out wincachegrind. On Linux, kcachegrind. On Mac, I've tried out MacCallGrind, it's a paid app, but the trial allows you to open files up to 3MB in size (which will generally be enough on smaller page loads, but if you have a serious call stack problem it won't cut it).

So, fire up the cachegrind parser of choice and load up a cachegrind.out file of your choosing. You will be presented with a window that looks like this (WinCacheGrind).

Learning to read the output isn't too difficult, the left side of the window is the entire call stack, starting at the outermost call and allowing you to drill down into all of the subsequent calls. You can also do that on the main panel. The different columns of the main window are the amounts of time each call took to execute. Self is the total amount of time that particular invocation took. In the sceenshot my main file (but nothing it included) took 1ms. The Cum. column is the cumulative amount of time that all of the child calls inside of the main method took (aka 22 seconds).

Just stepping through the entire application can be useful, but more useful is being able to sort through the most expensive calls that are happening in your application. Simply click on the Overall tab, and you will be presented with a screen like the following.

As you can see, there are several more columns which provide you with more information. Avg. Self is the average amount of time that individual call took across all of the invocations. Avg. Cum. is the average amount of time that the call took including all of the child calls that method invoked. Total Self is the total amount of time the individual call took across all invocations. Total Cum. not surprisingly is the total amount of time the call including child calls took. Calls is the total number of times that method was called during script execution.

That Total Cum. column is the one you will want to look at in order to determine where large spikes of time are being used up. As you can see, I've sorted on that field, and php's call_user_func_array is taking the largest amount of time. That's not particularly useful, though you can then drill down into the call stack and get to the meat of the problem by doubleclicking (from the line-by-line section) until you find a more concrete problem. How do I know it's not actually call_user_func_array's fault? For one, Total Self is 18ms, which is almost nothing. For two, it doesn't do anything except make another call.

Drilling down, I find that ultimately the longest call is split between view->build and view-render, indicating I have a problem with a drupal view I'm inculding on a bunch of pages. Going even deeper, the majority of the time in those calls are also because of a mysql call, indicating a query problem being the bottleneck.

Optimizing Mysql is beyond the scope of this article, but it is next in my series of site optimization articles so stay tuned!