The Need for Speed: Profiling PHP with XHProf and XHGui

While patience is a virtue, it’s generally not one inherent to today’s society when it comes to waiting for web pages to load. Studies conducted by big names in technology like Google, Microsoft, and Yahoo! have shown that even sub-second differences in page load time can have significant impact on conversions. If that’s not enough reason, Google incorporated page load time into their search rankings back in April 2010, so it also impacts SEO. A number of factors can affect page load time: network latency, web server configuration or load, use of persistent storage, caching or lack thereof, and application response time. In general, application response time should be suspected and dealt with last as it’s a less common culprit than database servers or handling of static assets and efforts to tune it usually have a lower ROI. However, knowing how to locate issues affecting application performance – often called bottlenecks – is a good skill to have should you ever be required to do so. Profiling is the process of measuring the execution time of each function or method call involved in servicing a single page request. The data collected from this process can reveal issues such as a particular method taking a long time to execute or being called a large number of times. Profiling a PHP script generally requires installing a PHP extension. The two more popular extensions for this purpose are Derick Rethans‘ Xdebug and Facebook’s XHProf. This article will focus on XHProf.

Installing XHProf

XHProf is available via PECL, so installing it is pretty easy. For example, it can be installed with the following on Debian-based systems:

sudo pecl install xhprof-beta
echo 'extension=xhprof.so' | sudo tee /etc/php5/conf.d/xhprof.ini >/dev/null
sudo apachectl restart

The raw profiling data generated by XHProf isn’t easily consumed at a glance. As such, an interface or visualization of some sort can be useful to view it. XHGui, a fork of XHProf, provides this. XHGui is hosted on GitHub, so you have two installation options. The first option involves using git to clone the repository, which provides an easy way to update it later.

git clone git://github.com/preinheimer/xhprof.git

If you prefer not to use git, the second option is to simply download and extract a tarball reflecting the repository’s current state like so:

wget -O xhgui.tar.gz https://github.com/preinheimer/xhprof/tarball/master && tar -zxf xhgui.tar.gz

At this point, you can use directions in the INSTALL file to guide you through the rest of the process for your particular server environment. The xhprof_html directory contains the index.php file to load the XHGui interface, so make sure your web server is configured to expose that path within your host’s document root using a symbolic link, an Alias directive, or something of that sort. SQL to create the database table used for storing profiling data is located in comment blocks at the top of the PHP files in the xhprof_lib/utils/Db directory. Use the file appropriate for your environment’s database server to create that database table, then add credentials to access it to the XHGui config.php file. If your web server is not running on your local host, don’t forget to add your local host’s IP address to the $controlIPs variable in the XHGui config.php file, else you’ll get an error message stating “You do not have permission to view this page.” Once all this is in place, XHGui should load successfully when you browse to it.

For more information on other configuration settings offered by XHGui, see the PHP Advent blog post linked at the bottom of the INSTALL file. If you’re running XHGui in a development environment, one place where you can vary slightly from the instructions is in the directives to configure the auto_prepend_file PHP configuration setting. According to the PHP manual, this setting is configurable per directory, meaning you can use a .htaccess file rather than having to modify your virtual host configuration and bounce your web server if your application has a central endpoint for servicing requests. An example of this is shown below.

php_value auto_prepend_file "../../xhprof/external/header.php"

This setting executes the specified PHP file before any PHP file is served. This particular file enables collection of profiling data before the code to be profiled is executed and sets up a shutdown function to store that data once the code has completed its execution.

Profiling your Application

For the purposes of this article, the skeleton example application provided for use with Zend Framework 2 is used as the subject of profiling. The .htaccess file above is placed in that application’s public directory, which is configured as the host document root. To enable profiling for a particular URL, append _profile=1 to its query string. For example, the environment used in this article uses a hostname of zf2.local, making the URL to access the application with profiling enabled http://zf2.local/?_profile=1. This will set a cookie and then redirect back to the application with that query string variable removed; with the cookie in place, you won’t need to modify the query string to enable profiling for subsequent requests. Once the application request has completed, the profiling data will be stored in the database you configured XHGui to use. Simply refresh the XHGui interface and its data grid will list the new profiling run near the top. The data grid also has links for easy filtering of runs by time period, memory usage, runtime, server, and domain. Click the timestamp listed for a run and XHGui will display a page detailing the data collected during that run. The table on the top left displays aggregated statistics such as total runtime, memory usage, and function call count. The top right shows tables of GET, POST, and cookie data as well as a pie chart detailing expensive function calls made during the request. Scroll down and you’ll find a data grid listing functions and their corresponding statistics. If you’re profiling for runtime, the two columns you’ll generally want to focus on are labeled “Exclusive Wall Time” and “Call Count.” For memory usage, look at the columns labeled “Exclusive Memory Usage” and “Exclusive Peak Memory” Usage. Click on any grid column to sort the grid’s data by that column. Click on an individual function name to view a detail page that includes that function’s statistics as well as those of its parent functions (i.e. functions that call it) and child functions (i.e. functions that it calls).

Comparing Profiling Runs

The common use case for profiling is to profile an application, make a change to that application’s source code, and then profile it again to see what performance impact the change made. XHProf and XHGui were designed to make doing this fairly easy. Within XHGui, in the data grid for profiling runs, each run has a hash value shown underneath its timestamp. Choose one of two runs you’d like to compare and copy its hash value. Click the timestamp of the other run to bring up its detail page. Finally, at the bottom of the data table on the top left, enter the hash value into the text box labeled “Perform Delta” and hit the “Delta” button next to it. This displays a page where the run for which you entered the hash value is labeled “Run Two” and the run for which you viewed the detail page is labeled “Run One.” Like the detail page, it displays both aggregate statistics and statistics per function call. These function call statistics are computed by subtracting those for Run One from those for Run Two. For example, the “Wall Time” column value for the main() function row in the function statistics table corresponds to the difference of the values of the “Incl. Wall Time” cell for Run Two and Run One in the aggregated statistics tables.

It’s possible that you may profile an application twice without making any changes and see a significant difference in the two profiles. One possible reason for this is that PHP maintains its own stat cache of filesystem lookups to improve performance. To mitigate this difference in xhprof profiling runs, add a call to the clearstatcache function at the top of external/header.php in your XHGui installation.

Viewing Callgraphs

Another feature offered by XHGui is generation of callgraphs, directed graphs that show calls between functions and visually highlight function calls that take up a large amount of runtime. XHGui shells out to the dot graphviz utility to do this. Below is the command to install the package for this on Debian-based systems:

sudo apt-get install graphviz

Note that you also need to uncomment the block that looks like the one below in the XHGui config.php file or else XHGui will return a rather unintuitive error message in place of the callgraph. Thanks to a blog post by Lorna Jane Mitchell for pointing this out.

<?php
//These are good for linux and its derivatives.
$_xhprof['dot_binary']  = '/usr/bin/dot';
$_xhprof['dot_tempdir'] = '/tmp';
$_xhprof['dot_errfile'] = '/tmp/xh_dot.err';

Near the top of the detail page for an individual run or a difference between two runs, you’ll find a “View Callgraph” link. Clicking it will generate a call graph resembling the one shown below. Note that this may take a while for profile runs with a lot of function calls. You can also click on an individual function name and click the “View Callgraph” link on its detail page to view a callgraph specific to that function.

In Closing

I hope you’ve enjoyed this overview of the functionality that XHProf and XHGui provide and that it’s provided insight into the value of an effective profiling toolset. While your application layer may prove an infrequent cause of performance bottlenecks, you should now have the knowledge necessary to isolate their causes and take further steps to eliminate them. Image via Fotolia

Frequently Asked Questions about Profiling with XHProf and XHGui