Speed Up Cache Clearing on Drupal 7

Cache clearing nirvana may be two vsets away

tl;dr If your D7 site uses features or has many entity types, some recent patches to the features module and the entity api module may deliver dramatic performance increases when you clear Drupal's cache. The magic:

    $ drush vset features_rebuild_on_flush FALSE
    $ drush vset entity_rebuild_on_flush FALSE

The Backstory

Given that tedbow is a good friend in our little slice of paradise, aka Ithaca, NY, we decided that we were going to embrace the entityform module on the large Drupal migration I was hired to lead. Fifty-eight entityforms and 420 fields later (even with diligent field re-use), we now see how, in some cases, a pseudo-field system has real benefits, even if it's not the most future-proof solution. As our cache clears became slower and slower (at times taking nearly 10 minutes for a teammate with an older computer), I began to suspect that entityform and/or our extensive reliance on the Drupal field system might be a culprit. Two other corroborating data points were the length of time that feature reverts took when they involved entityforms. Even deployments became a hassle because we had to carefully time them if they required the cache to be cleared, which would make the site unresponsive for logged-in users and cache-cold pages for 5 minutes or more. Clearly, something needed to be done.

Diagnosing

I'm sure there are better ways to handle performance diagnostics (using xDebug, for example), but given the procedural nature of drupal_flush_all_caches it seemed like the devel module would work just fine. I modified the code in Drupal's common.inc file to include the following:

function time_elapsed($comment,$force=FALSE) {
  static $time_elapsed_last = null;
  static $time_elapsed_start = null;

  $unit="s"; $scale=1000000; // output in seconds
  $now = microtime(true);
  if ($time_elapsed_last != null) {
    $elapsed = round(($now - $time_elapsed_last)*1000000)/$scale;
    $total_time = round(($now - $time_elapsed_start)*1000000)/$scale;
    $msg = "$comment: Time elapsed: $elapsed $unit,";
    $msg .= " total time: $total_time $unit";
    dpm($msg);
  }
  else {
      $time_elapsed_start=$now;
  }
  $time_elapsed_last = $now;
}
/**
 * Flushes all cached data on the site.
 *
 * Empties cache tables, rebuilds the menu cache and theme registries, and
 * invokes a hook so that other modules' cache data can be cleared as well.
 */
function drupal_flush_all_caches(){
  // Change query-strings on css/js files to enforce reload for all users.
  time_elapsed('_drupal_flush_css_js');
  _drupal_flush_css_js();
  time_elapsed('registry_rebuild');
  registry_rebuild();
  time_elapsed('drupal_clear_css_cache');
  drupal_clear_css_cache();
  time_elapsed('drupal_clear_js_cache');
  drupal_clear_js_cache();

  // Rebuild the theme data. Note that the module data is rebuilt above, as
  // part of registry_rebuild().
  time_elapsed('system_rebuild_theme_data');
  system_rebuild_theme_data();
  time_elapsed('drupal_theme_rebuild');
  drupal_theme_rebuild();
  time_elapsed('entity_info_cache_clear');
  entity_info_cache_clear();
  time_elapsed('node_types_rebuild');
  node_types_rebuild();
  // node_menu() defines menu items based on node types so it needs to come
  // after node types are rebuilt.
  time_elapsed('menu_rebuild');
  menu_rebuild();

  time_elapsed('actions_synchronize');
  // Synchronize to catch any actions that were added or removed.
  actions_synchronize();

  // Don't clear cache_form - in-progress form submissions may break.
  // Ordered so clearing the page cache will always be the last action.
  $core = array('cache', 'cache_path', 'cache_filter', 'cache_bootstrap', 'cache_page');
  $cache_tables = array_merge(module_invoke_all('flush_caches'), $core);
  foreach ($cache_tables as $table) {
    time_elapsed("clearing $table");
    cache_clear_all('*', $table, TRUE);
  }

  // Rebuild the bootstrap module list. We do this here so that developers
  // can get new hook_boot() implementations registered without having to
  // write a hook_update_N() function.
  _system_update_bootstrap_status();
}

The next time I cleared cache (using admin_menu, since I wanted the dpm messages available), I saw the following:

registry_rebuild: Time elapsed: 0.003464 s, total time: 0.003464 s

drupal_clear_css_cache: Time elapsed: 3.556191 s, total time: 3.559655 s

drupal_clear_js_cache: Time elapsed: 0.001589 s, total time: 3.561244 s

system_rebuild_theme_data: Time elapsed: 0.003462 s, total time: 3.564706 s

drupal_theme_rebuild: Time elapsed: 0.122944 s, total time: 3.68765 s

entity_info_cache_clear: Time elapsed: 0.001606 s, total time: 3.689256 s

node_types_rebuild: Time elapsed: 0.003054 s, total time: 3.69231 s

menu_rebuild: Time elapsed: 0.052984 s, total time: 3.745294 s

actions_synchronize: Time elapsed: 3.334542 s, total time: 7.079836 s

clearing cache_block: Time elapsed: 31.149723 s, total time: 38.229559 s

clearing cache_ctools_css: Time elapsed: 0.00618 s, total time: 38.235739 s

clearing cache_feeds_http: Time elapsed: 0.003292 s, total time: 38.239031 s

clearing cache_field: Time elapsed: 0.006714 s, total time: 38.245745 s

clearing cache_image: Time elapsed: 0.013317 s, total time: 38.259062 s

clearing cache_libraries: Time elapsed: 0.007708 s, total time: 38.26677 s

clearing cache_token: Time elapsed: 0.007837 s, total time: 38.274607 s

clearing cache_views: Time elapsed: 0.006798 s, total time: 38.281405 s

clearing cache_views_data: Time elapsed: 0.008569 s, total time: 38.289974 s

clearing cache: Time elapsed: 0.006926 s, total time: 38.2969 s

clearing cache_path: Time elapsed: 0.009662 s, total time: 38.306562 s

clearing cache_filter: Time elapsed: 0.007552 s, total time: 38.314114 s

clearing cache_bootstrap: Time elapsed: 0.005526 s, total time: 38.31964 s

clearing cache_page: Time elapsed: 0.009511 s, total time: 38.329151 s

hook_flush_caches: total time: 38.348554 s

Every cache cleared.

My initial response was to wonder how and why the cache_block would take so long. Then, however, I noticed line 59 above, which calls module_invoke_all('flush_caches'), which should have been obvious. Also, given that I was just looking for bottlenecks, I modified both module_invoke($module, $hook) in module.inc, as well as the time_elapsed to get the following:

function time_elapsed($comment,$force=FALSE) {
  static $time_elapsed_last = null;
  static $time_elapsed_start = null;
  static $last_action = null; // Stores the last action for the elapsed time message

  $unit="s"; $scale=1000000; // output in seconds
  $now = microtime(true);

  if ($time_elapsed_last != null) {
    $elapsed = round(($now - $time_elapsed_last)*1000000)/$scale;
    if ($elapsed > 1 || $force) {
      $total_time = round(($now - $time_elapsed_start)*1000000)/$scale;
      $msg = ($force)
        ? "$comment: "
        : "$last_action: Time elapsed: $elapsed $unit,";
      $msg .= " total time: $total_time $unit";
      dpm($msg);
    }
  } else {
      $time_elapsed_start=$now;
  }
  $time_elapsed_last = $now;
  $last_action = $comment;
}


/** From module.inc */
function module_invoke_all($hook) {
  $args = func_get_args();
  // Remove $hook from the arguments.
  unset($args[0]);
  $return = array();
  foreach (module_implements($hook) as $module) {
    $function = $module . '_' . $hook;
    if (function_exists($function)) {
      if ($hook == 'flush_caches') {
        time_elapsed($function);
      }
      $result = call_user_func_array($function, $args);
      if (isset($result) && is_array($result)) {
        $return = array_merge_recursive($return, $result);
      }
      elseif (isset($result)) {
        $return[] = $result;
      }
    }
  }

  return $return;
}

The results pointed to the expected culprits:

registry_rebuild: Time elapsed: 4.176781 s, total time: 4.182339 s

menu_rebuild: Time elapsed: 3.367128 s, total time: 7.691533 s

entity_flush_caches: Time elapsed: 22.899951 s, total time: 31.068898 s

features_flush_caches: Time elapsed: 7.656231 s, total time: 39.112933 s

hook_flush_caches: total time: 39.248036 s

Every cache cleared.

After a little digging into the features issue queue, I was delighted to find out that patches had already been committed to both modules (though entity api does not have it in the release yet, so you have to use the dev branch). Two module updates and two vsets later, I got the following results:

registry_rebuild: Time elapsed: 3.645328 s, total time: 3.649398 s

menu_rebuild: Time elapsed: 3.543039 s, total time: 7.378718 s

hook_flush_caches: total time: 8.266036 s

Every cache cleared.

Cache clearing nirvana reached!