Enhanced PHP performance profiling with Xhprof

XHProf is a function-level hierarchical profiler for PHP and has a simple HTML based navigational interface. The raw data collection component is implemented in C (as a PHP extension). The reporting/UI layer is all in PHP. It is capable of reporting function-level inclusive and exclusive wall times, memory usage, CPU times and number of calls for each function. Additionally, it supports ability to compare two runs (hierarchical DIFF reports), or aggregate results from multiple runs. This extension is available through pecl [ http://pecl.php.net/package/xhprof ].

UPDATE May 13, 2013: To get this working in PHP 5.4 follow the instructions listed here.

Xhprof is similiar to the Xdebug profiler and Kcachegrind. I used this xhprof tutorial by Lorenzo Alberton to get started, but I quickly noticed that this was rather inadequate for modern applications using heavy doses of AJAX. In fact using this method breaks requests involving JSON since text/html is appended to each request. This solution also lacked a way of easily accessing previous profiles since it only gives you a link to the profile of the page you are viewing. So what I wanted to do was make a solution that is:

  1. Compatible with JSON requests
  2. Allows me to see all requests I’ve made in chronological order.
  3. Provide a pretty interface.
  4. Uses javascript that is library independent (so I can use it with my mootools and jquery projects).

Here is what I came up with:

Installing Xhprof

You’ll need php5-dev installed on your system. Install Xhprof via pecl and graphviz (for call call grapgs) via apt:

Then create an xhprof.ini file in /etc/php5/conf.d/xhprof.ini and put the following text in it:

In your php.ini file find the auto_append directives and make them look like this:

Make sure you’ve created the /var/tmp/xhprof directory and a /var/www/xhprof directory. Inside /var/www/xhprof directory create a symbolic link to where the xhprof files are actually installed:

Now we just need to create the header and footer files inside /var/www/xhprof and restart apache2. I’ve put those files in pastebin:

In my /var/www/xhprof directory I added a little PHP icon (you can see this in the example bottom-right of page). When I click on that an overlay is created with all profiling data – you can change the code in footer.php for your own needs. You will only see the data for a given HTTP_HOST. Just click on the resource link and xhprof opens in a new window.

Explanation of XHPROF Report

If you are like me you have no idea what a lot of the columns in the report mean so I decided to add an explanation of the fields you see in the xhprof report.

  • Calls: How many times was this function called
  • Call%: Not sure on this one…
  • Inclusive Wall Time: Wall time is the human perception of the passage of time. So when the report says 17,331 microseconds was spent on an operation – that means this operation (and all of its child operations) took 17.3 milliseconds or 0.0173 seconds. Inclusive means it includes its child operations.
  •  Exclusive Wall Time: Same as inclusive wall time except exclusive means the report is not counting the sum of the operations child processes, no children.
  • Inclusive/Exclusive Memory Usage: How much memory was consumed by this process – similar to memory_get_usage(). Since this is measured in bytes basically each million is worth roughly 1 Megabyte. For instance 2,433,256 means 2.32 MB.
  • Inclusive/Exclusive Peak Memory Usage: How much memory was consumed by this process at its peak – similar to memory_get_peak_usage().
  • Inclusive/Exclusive CPU Microseconds: I am not sure on this one, I think this literally means CPU time. Would love someone to school me up on that one.
Understanding the Percentage Columns
It’s important to note that the percentage columns refer to the percentage of the total. If you run down the column and start adding up all the percents you’ll notice it exceeds 100%. Most people probably already understand this but I was a bit confused at first. In our example above you’ll notice it says call_user_func_array() consumed 19.8% of inclusive memory or 481,760 bytes. If you divide that by the total consumed by main() you’ll see where it got the 19.8%. Remember the difference between inclusive and exclusive – that’s important when reading this report.

*EDIT: Due to an open_basedir restriction in PHP this implementation breaks phpmyadmin. To resolve this you’ll need to find your phpmyadmin apache.conf file and make sure the open_basedir value is set to:

7 Comments