Case study: Views, Quicktabs and template.php

Performance troubleshooting and tuning of web sites is often, to paraphrase Winston Churchill, "a puzzle inside a riddle, wrapped in an enigma".

One of those puzzles is how sites are put together: in this case: multiple layers of modules that obscure the real cause of where the slowness of a site is, and a theme for the topping.

Problem and symptoms

We were conducting a benchmark for a client who is about to launch a site that is expected to be advertised on TV, and hence receive a lot of traffic. They noticed that the site is sluggish and sought assistance from 2bits.com for troubleshooting the issues.

The complaint was sluggish page load times, and more time in PHP than in query execution, ruling out -- at first glance -- database queries as the cause.

Investigation

As usual, we got a copy of the site in our labs, and proceeded with recreating the site there, and putting it under load. We simulated a lot of 150 concurrent users, and found that the response time was 4.13 seconds averaged across all the URLs tested. Specific URLs were as high as 7.91 seconds, and the front page at 7.48 seconds. Not good at all!

Moreover the CPU utilization on the web server was excessively high (100%), and the load average was between 20 and 40.

No way to launch a site with these issues.

Looking closer, we found devel saying this for the front page:

Executed 1289 queries in 1643.2 milliseconds. Page execution time was 3206.81 ms.

While the number of queries is high, and the time to execute them as well, the overall page execution time should be some 2000 or so milliseconds and not 3200 like above.

We started investigating one view from the front page, and went to admin/build/views, then selected "Edit" for the specific view, and then clicked on "Preview" button. We saw this:

Query build time	7.25 ms
Query execute time	237.73 ms
View render time	147.08 ms

That is some 390 ms, with the rendering time a bit high, but does not account for all the time.

We then realized that the admin theme was Root Candy, and not the system default theme.

We switched the admin theme to the system default theme, and found things are different:

Query build time	6.29 ms
Query execute time	245.87 ms
View render time	385.03 ms

We are on to something here: 238 ms more of rendering time! Even more time than the query execution itself.

Lesson 1: Make sure you test and debug with the same theme that the users will be using ... you get to keep your hair ...

Diagnosis

They have a custom views-view-viewname.tpl.php file in the system default theme directory, and in template.php there was a phptemplate_preprocess_views_view() with lots of processing in it. For each row, it did a node_load() and a user_load() as well. With 116 modules enabled, there was a lot of code to call and a lot of database activity to do for each row in the view result. Since the admin theme was different, they never saw this problem!

As usual, it was several views with lots of joins, in some cases a 7 table join.

SELECT DISTINCT(node.nid) AS nid,
   node.title,
   node.type,
   node.vid,
   votingapi_cache_node_percent_vote_average.value,
   node_comment_statistics.comment_count,
   users.picture,
   users.uid,
   users.name,
   node.created,
   node.changed,
   node_data_field_foo.field_foo_value,
   node_data_field_bar.bar_value,
 FROM {node} node 
 LEFT JOIN {votingapi_cache} ON node.nid = content_id 
  AND (content_type = 'node' 
  AND value_type = 'percent' 
  AND tag = 'vote' 
  AND function = 'average')
 LEFT JOIN {term_node} ON ...
 LEFT JOIN {term_data} ON ...
 LEFT JOIN {content_type_foo} node_data_field_foo ON ...
 INNER JOIN {node_comment_statistics} ON ...
 INNER JOIN {users} ON ...
 LEFT JOIN {content_type_foo} node_data_field_bar ON ...
 WHERE (node.type in ('%s')) 
   AND (node.status <> 0) 
   AND (term_data.vid in ('%s'))
 ORDER BY ... DESC, 
   ... DESC, 
   ... DESC, 
   ... DESC

Lesson 2: Reduce those tables in views ... It will save you a lot of headaches ...

But all that accounted for a portion of the time, and not all of it.

These views were abstracted on another layer: the quicktabs module. And the blocks from that module were inserted in regions in the theme.

In quicktabs, a block is composed of several views, in this each of the quicktabs provided 3 tabs (most recent, top viewed, top rated) each with an underlying display on the above view.

There is an important setting for each block:

Ajax:
Yes: Tab content will be loaded at tab click.
No: All tabs will be loaded at page load.

These blocks were set to "No", meaning that for each page load, 3 views were executed and rendered, tripling the amount of time for the page.

Lesson 3: Do not go for "pretty" at the expense of "slow" ...

Solutions

One of the recommendations was to set the Ajax settings to "Yes", so only one view is executed and rendered.

Making things more complex was the fact that quicktabs blocks are not cached, and you have the above horrendous performance.

Another recommendation was to use Views as a Rapid Application Development (RAD) tool, to develop and test the queries, then create a module with those queries in them, and cache the result:

function foo_bar($no_results = 5) {
  if (user_access('access content')) {
    $cid = __FUNCTION__;
    // Check if it is in the cache
    if ($cache = cache_get($cid)) {
      return $cache->data;
    }
    // Query from views here
    $query = "SELECT ... FROM ... WHERE ... GROUP BY ... ORDER BY ...";
    $result = db_query($query, FOO_TYPE, 0, $no_results);
    $items = array();
    while ($row = db_fetch_object($result)) {
      $item = array(
        'something' => $row->something,
        'something2' => check_plain($row->something2),
        ...
      );
      $items[] = $item;
    }
    $data = theme('foo_display', $items);
    // Cache it for 15 minutes
    cache_set(__FUNCTION__, $data, time() + 60*15);
    return $data;
  }
}

Results

There were many other things that we did to tune the site. Our report was 34 pages long with findings, analysis and recommendations in details.

The end result was reducing the front page from 7.48 seconds to 0.94 seconds under a load of 150 users (only 0.44 seconds in single user mode), without using memcache or boost for page caching.

The CPU was only 75% utilized on the web server, and the load average was between 5 and 9.

Block timing patch

It took us a lot of digging to find out where the main problem area described above is (quicktabs, with multiple views executed and high rendering time). During the course of investigating and tuning, we developed a patch that was able to give us insight on which components were slow.

The patch helped us pinpoint which region and block were the culprits in all this, so we are including it here since it may prove useful to someone.

The output is a plain old drupal_set_message(), and will be similar to this (with some blocks removed for brevity):

  52.40 - header/logintoboggan:0
   3.37 - search/block:10
1956.96 - content/quicktabs:2
  12.09 - right/block:13
  10.02 - right/block:14
 342.71 - right/views:foo-block_1
  71.36 - right/user:1
  19.15 - footer/menu:menu-footer

As you can see, it is all there at a glance: the content region quicktabs block is to blame (1956 milliseconds). As well, the view in the right region is on the high side as well (342 milliseconds).

Note that the figures are much lower than the 7.91 seconds, because this is a single user test, while the figures mentioned before are for multi-user tests with 150 users concurrently.

To verify that the view in question was the culprit, we ran the 150 users test above with the quicktabs blocks disabled, and saw the home page goes down to only 0.35 seconds, and the CPU was only at 50% utilization for the web server!

Installing and configuring the patch

To install the patch, use your favorite IDE, or the patch command like so:

  cd /your/drupal/directory
  patch -p0 < filename.patch

Then add this to your settings.php:

  $conf['block_timing'] = 1;

When you do not need the output, just set the above to 0 and the patch will print nothing.

The patch is attached below for Drupal 6.x. Please comment below if it helped you.

What about Devel?

Normally, slow queries are easily caught if you install and enabled the indispensible devel module.

But in this case, devel does not show any query that is generated by views to be long running and flag it by being more than the set threshold.

What about Views?

Views 2.x does some weird stuff to query logging for reasons that are not fully clear to us. I am not sure exactly how that impacts devel's ability to log and time queries, but it looks suspicious (and evil!)

This is a snippet from views.inc for Drupal 6.x:

  /**
   * Set up query capturing.
   *
   * db_query() stores the queries that it runs in global $queries,
   * bit only if dev_query is set to true. In this case, we want
   * to temporarily override that setting if it's not and we
   * can do that without forcing a db rewrite by just manipulating
   * $conf. This is kind of evil but it works.
   */
  function start_query_capture() {
    global $conf, $queries;
    if (empty($conf['dev_query'])) {
      $this->fix_dev_query = TRUE;
      $conf['dev_query'] = TRUE;
    }
   ...
  /**
   * Add the list of queries run during render to buildinfo.
   *
   * @see view::start_query_capture()
   */
  function end_query_capture() {
    global $conf, $queries;
    if (!empty($this->fix_dev_query)) {
      $conf['dev_query'] = FALSE;
    }

However, Views does provide a devel settings in admin/build/views/tools, but the display is not as easy to understand as devel's display, nor is it integrated in it. We noticed that it listed the block name and timing for regular view blocks, like so:

Block block_name execute time: 346.459150314ms

But it does not provide that info for the views that are in quick tabs.

The "Preview" button is clearer, as long as you are using the same theme that regular users will be using.

Our patch will also catch slowness due to reasons other than views or the database, such as a block containing a widget that contacts another server for example.

Because Drupal is very powerful and flexible, there are no two sites that are exactly alike ...

Every site is a riddle inside a puzzle wrapped in an enigma, and at 2bits.com, we enjoy unraveling them ...