doquesnet

PHP owns special Xdebug extension that can be used for debugging and profiling PHP code. Profiling means determining bottlenecks in your scripts and visualize them in some external application (we'll use KCacheGrind through out the page).

In this article we'll give a real example how profiling can help to improve your PHP web-site's performance. We will profile Drupal 6 core.

Installing and configuring Xdebug

You should install php5-xdebug package through your package manager.

The following minimal configuration is required to make Xdebug log profiler results into /tmp/drupal-cachegrind.out file:

# Depending on Linux distribution this can be even more
# simpler, I think:
#   extension = xdebug.so
zend_extension = ${extension_dir}"/xdebug.so"
 
# Enables Xdebug's profiler which creates files in the profile
# output directory. Those files can be read by KCacheGrind to
# visualize your data.
xdebug.profiler_enable = 1
 
# The directory where the profiler output will be written to, make
# sure that the user who the PHP will be running as has write
# permissions to that directory.
xdebug.profiler_output_dir = /tmp
 
# This setting determines the name of the file that is used to dump
# traces into.
xdebug.profiler_output_name = "drupal-cachegrind.out"

Restart Apache service to enable new PHP module and settings:

/etc/rc.d/apache2 restart

Open PHP page in your web-browser and /tmp/drupal-cachegrind.out file will be created. Aware that after you open or reload page the profiler file will be overwritten with new data.

Profiling in KCachegrind

For demonstation I used some real Drupal web-site that works with about 250 various modules installed, has 50K nodes and 1K user accounts. Profiler file was generated for web-site's front page.

Run KCachegrind and open /tmp/drupal-cachegrind.out file. Application will give you a fancy presentation of all your Drupal functions executed during the request and many more information. The most interesting is "Flat Profile" pane showing all functions sorted by time spent in that function. Turn Show Absolute Costs button on if it's not clicked already.

Description of fields:

Clicking on Show Relative Cost button will show you relative times spent in each function in percents.

For example, module_implements() function implementation takes only 5.46% CPU (42ms) time of all the request. So there might be far better candidates for optimization. Anyway we will try to optimize this function.

I've totally changed some module_implements() implementation by adding some caching into it:

function module_implements($hook, $sort = FALSE, $refresh = FALSE) {
  static $implementations;
  static $cache_exists;
 
  if (!isset($cache_exists)) {
    $cache_exists = function_exists('cache_get');
  }
 
  // Load implementations from cache.
  if (!isset($implementations)) {
    if ($cache_exists) {
      $cache = cache_get('module_implements');
      if ($cache) {
        $implementations = $cache->data;
      }
      else {
        $implementations = array();
      }
    }
  }
 
  if ($refresh) {
    if ($cache_exists) {
      cache_clear_all('module_implements', 'cache');
    }
    $implementations = array();
    return;
  }
 
  if (!isset($implementations[$hook])) {
    $implementations[$hook] = array();
    $list = module_list(FALSE, TRUE, $sort);
    foreach ($list as $module) {
      if (module_hook($module, $hook)) {
        $implementations[$hook][] = $module;
      }
    }
 
    if ($cache_exists) {
      cache_set('module_implements', $implementations);
    }
  }
 
  // The explicit cast forces a copy to be made. This is needed because
  // $implementations[$hook] is only a reference to an element of
  // $implementations and if there are nested foreaches (due to nested node
  // API calls, for example), they would both manipulate the same array's
  // references, which causes some modules' hooks not to be called.
  // See also http://www.zend.com/zend/art/ref-count.php.
  return (array)$implementations[$hook];
}

Before doing all the stuff this code checks whether cache_get() function exists because it might be unavailable on update.php page, for example.

One silly problem I see with this implementation is that it calls cache_set() function too often when cache hit missed. But misses will be very rare so that might be not a big problem.

To apply change to module_implements() you may apply this patch.

Here are the benchmarks after patch has been applied. I've pressed Reload in browser two times to make sure I will profile module_implements() function that just gets data from cache and doesn't do any calls to cache_set():

Results:

Difference between these times will not be so big when we will turn off Xdebug, so you decide whether to apply this micro-optimization to your Drupal site.

These results are very approximate. Some real ab2 benchmarks should be processed to calculate the mean.

More information

More documentation about profiling code using KCachegrind can be found here.

Another nice article about benchmarking Drupal with Xdebug and KCachegrind.