Drupal 6 Performance Testing

A scenario where memcache can actually impair performance

We were recently asked to investigate poor performance on a Drupal 6 site. Memcache was enabled, but a siege test was still showing poor results.

Transactions:		         145 hits
Availability:		      100.00 %
Elapsed time:		      525.34 secs
Data transferred:	        1.89 MB
Response time:		       17.08 secs
Transaction rate:	        0.28 trans/sec
Throughput:		        0.00 MB/sec
Concurrency:		        4.71
Successful transactions:         145
Failed transactions:	           0
Longest transaction:	       28.38
Shortest transaction:	       13.03

We run New Relic for performance testing and the siege traffic gives it plenty to analyse.

The first thing we noticed in New Relic was that there were some slow hook_init functions being called. The worst performing of these was in the Password Policy module, covered at http://drupal.org/node/2008282. Fixing this didn't make a huge change to the performance though.

The site also runs CiviCRM and in the New Relic transactions, it showed that civicrm_invoke was taking a long time to process. Digging into the transaction details, we came across this:

The theme registry was being rebuilt on every page load. We checked to see if there were any theme settings that had been left enabled from development that were causing the theme rebuild, but found none.

Checking through the functions that appeared in the transaction log, the only reason for the theme registry to be rebuilt each time that we could come up with was that it was failing to be saved in the cache. The log shows that _theme_load_registry() is called, it checks memcache for the cached theme registry, but then rebuilds it.

function _theme_load_registry($theme, $base_theme = NULL, $theme_engine = NULL) {
  // Check the theme registry cache; if it exists, use it.
  $cache = cache_get("theme_registry:$theme->name", 'cache');
  if (isset($cache->data)) {
    $registry = $cache->data;
  }
  else {
    // If not, build one and cache it.
    $registry = _theme_build_registry($theme, $base_theme, $theme_engine);
    _theme_save_registry($theme, $registry);
  }
  _theme_set_registry($registry);
}

Checking all the logs failed to show any errors relating to memcache. For a quick check, we decided to try moving the cache table (where the theme registry is cached) out of memcache, back into the Drupal database. In settings.php, this was done by changing

$conf['memcache_bins'] = array(
    'cache' => 'default',
    ...

to

$conf['memcache_bins'] = array(
    'cache' => 'database',
    ...

Running the siege test again showed a marked improvement.

Transactions:		         112 hits
Availability:		      100.00 %
Elapsed time:		       97.70 secs
Data transferred:	        1.46 MB
Response time:		        3.83 secs
Transaction rate:	        1.15 trans/sec
Throughput:		        0.01 MB/sec
Concurrency:		        4.39
Successful transactions:         112
Failed transactions:	           0
Longest transaction:	        5.92
Shortest transaction:	        2.80

That seemed conclusive, but didn't help to understand why memcache was failing to store the theme registry. Further investigation led us to http://drupal.org/node/435694. Memcache will only store data up to 1M in size - not only that, but it fails silently, so nothing appears in the logs.

There are patches in http://drupal.org/node/435694 to add logging to capture these memcache failed saves and there's also a php snippet at http://gist.github.com/typhonius/8798894 to scan all the Drupal cache tables and highlight any objects over 1M in size.

If you're using memcache 1.4.2 or later, you can increase the 1M maximum object size, see https://code.google.com/p/memcached/wiki/ReleaseNotes142 for example, but increasing this too much may impact memcache's efficiency.

New Relic certainly made it much quicker for us to diagnose the underlying issue though and having the near instant feedback is great.