Solving High CPU usage and reducing page generation times due to Skinr module

While doing a Drupal Performance Assessment for a clients Drupal 6.x site recently, we found an odd problem.

Among other things, page generation times was high, and this was due to the function skinr.module::skinr_preprocess() was being called 190 times for each page load.

Each of these calls was calling theme_get_registry(), which is supposed to statically cache its results. However, these were still consuming too much time, even with static caching. Perhaps this was due to the large amount of memory the data for the theme registry consumes.

Each invocation took up to 11 milliseconds, and those added up significantly.

We measured this by adding the following debugging code in includes/theme.inc::theme_get_registry()

function theme_get_registry($registry = NULL) {
  timer_start(__FUNCTION__);
  static $theme_registry = NULL;
  if (isset($registry)) {
    $theme_registry = $registry;
  }

  $time = timer_stop(__FUNCTION__);
  error_log(__FUNCTION__ . ':' . $time['time']);
  return $theme_registry;
}

We then checked how much time the skinr_preprocess() function takes, by adding a static flag to prevent it from being executed more than once. This of course would impact the site's functionality, but we wanted to measure the impact of all these calls:

function skinr_preprocess(&$vars, $hook) {
  static $already_called = FALSE;
  if ($already_called) {
    return;
  }

  ...
  
  $already_called = TRUE;
}

We found that this made a significant difference in performance, when measured via a code profiler, such as xhprof:

theme_get_registry() 194 calls total of 327,560 usecs 15.8% of total page load time
skinr_preprocess() 190 calls total of 264,246 usecs 12.8% of total page load time

By eliminating these, we take off more than half a second of page execution time!

Instead of a total 2,068 ms before, it is down to 1,220 ms with the change.

Since this does impacts the site's functionality, we modified this to a less performant but still functional variant like so (for Skinr 6.x-1.x):

function skinr_preprocess(&$vars, $hook) {
  static $already_called = FALSE;
  static $skinr_data;
  static $info;
  static $current_theme;
  static $theme_registry;

  if (!$already_called) {
    $already_called = TRUE;

    // Let's make sure this has been run. There have been
    // problems where other modules implement a theme 
    // function in their hook_init(), so we make doubly
    // sure that the includes are included.
    skinr_init();
  
    $skinr_data = skinr_fetch_data();
    $info = skinr_process_info_files();
    $current_theme = skinr_current_theme();
    $theme_registry = theme_get_registry();
  }

  ...
}

Before:

Total page generation time 2,055,029 usecs

theme_get_registry 194 calls totalling 328,355 usecs and 16.0% of total page generation time
skinr_preprocess 190 calls totalling 266,195 usecs and 13.0% of total page generation time

After:

Total page generation time 1,402,446 usecs

Over 650 milliseconds saved!

We also noticed a corresponding decrease in CPU utilization, which means the servers can scale better.

We have created patches that fix the above. You can grab them for Skinr 6.x-1.x, 6.x-2.x and 7.x-2.x from issue #1916534.