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!

Tags
Drupal

Up Next

Creating Reusable Dynamic Content Components

A screenshot showing the "up next" reusable tagged content block
This is part 2 in this series that explores how to use paragraph bundles to store configuration for dynamic content. The example I built in part 1 was a "read next" section, which could then be added as a component within the flow of the page. The strategy makes sense for component-based sites and landing pages, but probably less so for blogs or content heavy sites, since what we really want is for each article to include the read next section at the end of the page. For that, a view that displays as a block would perfectly suffice. In practice, however, it can be really useful to have a single custom block type, which I often call a "component block", that has an entity reference revisions field that we can leverage to create reusable components.
Tags
Drupal

Drupal Pullquotes

Several powerful quotes with a pullquote sprinkled off to the side to draw a reader's attention
"Pullquotes", as described here, differ from blockquotes because they duplicate a section of text within the page, and get styled in a way that draws the reader's attention to the quote. As such, one simple solution that I've been using is to allow content editors to select a section of text while editing and click a button in the interface to designate it as a pullquote.
Tags
Drupal

Creating Paragraphs Entities for Dynamic Content

Logos with Paragraphs, Drupal and Atomic Design
The paragraphs module has become a central ingredient for many component-based sites in recent years. However, our content strategy also often requires components that display dynamic content (think "Read Next", or "Also of Interest"). In this tutorial, I'll demonstrate how we've been solving this problem, by building paragraph bundles that serve as configuration entities that we can then use as arguments that we pass to a view via the Twig Tweak module. You can see a working version of the dynamic content component we'll be building in the "Up Next" card grid at the bottom of this tutorial.
Tags
Drupal