Upgrade Your Drupal Skills
We trained 1,000+ Drupal Developers over the last decade.
See Advanced Courses NAH, I know EnoughSolving 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.
About Drupal Sun
Drupal Sun is an Evolving Web project. It allows you to:
- Do full-text search on all the articles in Drupal Planet (thanks to Apache Solr)
- Facet based on tags, author, or feed
- Flip through articles quickly (with j/k or arrow keys) to find what you're interested in
- View the entire article text inline, or in the context of the site where it was created
See the blog post at Evolving Web