Identifying Bottlenecks with XHProf

  • henok_mikre

    Henok Mikre

A few days ago we noticed one of our Drupal 7 sites taking an unusually long time to save a node. We did not find anything in the logs. Fortunately, the issue was only evident in the dev tier and refreshing the database resolved the issue. We were still interested to know the root cause, however, so that we are better prepared should it ever happen in production.

There are plenty of articles on the web that show how to setup XHprof. You will find some of them below under "resources." This article is really a cheatsheet for ourselves.

Install XHProf PHP Extension and Graphviz

# Install XHProf PHP extension.
sudo pecl install xhprof-0.9.4
sudo sh -c 'echo "extension=xhprof.so" >> /etc/php.d/xhprof.ini'
sudo systemctl restart httpd.service

# Verify extension.
php -m | grep xhprof

# Install graphviz so PHP can create the callgraph.
sudo yum install -y graphviz

Create a Dedicated Vhost

We prefer to create a dedicated vhost so we can easily see the results even if the requests are coming from drush.

# Create xhprof docroot
sudo mkdir -p /var/www/vhosts/xhprof.dev/{html,log}

# Create a vhost configuration file.
# Insert the usual vhost configuration.
sudo vim /etc/httpd/conf.d/xhprof.dev.conf

# Restart apache
sudo systemctl restart httpd.service

# Create symlinks to xhprof in new docroot.
ln -s /usr/share/pear/xhprof_html/index.php /var/www/vhosts/xhprof.dev/html/index.php
ln -s /usr/share/pear/xhprof_html/callgraph.php /var/www/vhosts/xhprof.dev/html/callgraph.php

Don't forget to add an entry for the new vhost to your hosts file.

<ip-address>    xhprof.dev

Configure XHProf in Drupal

# Enable devel module
drush en -y devel

# Set xhprof URL.
drush vset --exact devel_xhprof_url 'http://xhprof.dev'

# Set xhprof directory
drush vset --exact devel_xhprof_directory '/usr/share/pear/'

# Enable profiling of all requests with XHProf devel
drush vset --exact devel_xhprof_enabled 1

That last command might throw the following error:

PHP Fatal error:  Class 'XHProfRuns_Default' not found in devel.module on line 1197

You can run the last command again to verify. It appears to be a false alarm caused by xhprof library path availability. If you enable this from the UI, you would not see the error so long as dependencies are met.

The Callgraph

The callgraph for a typical page request on this site looks like this:

XHProf callgraph

The callgraph for the request to save a node looked like this:

XHProf callgraph

Here is a higher resolution version of the tail end of that callgraph:

XHProf callgraph

It turned out that the purge module had a bad URL to expire and was causing the node saving process to take a very long time.

Resources