Ideas

Using Xdebug to find slow code in Drupal

We were recently contracted to improve performance on a large Drupal install. This is a Pressflow site that's been touched by many different hands over the years, a heavily modified theme (~30 custom templates), and over 200 modules. While the site felt snappy, there were some pages that took a long time to load (5-9 seconds). In evaluating and diagnosing slow performance, we first establish some benchmarks by timing page loads from different areas of the site:

Homepage:
Executed 723 queries in 104.98 ms.
Page execution time was 3821.49 ms.

Views generated content:
Executed 905 queries in 221.75 ms.
Page execution time was 4361.21 ms.

Executed 2089 queries in 366.94 ms.
Page execution time was 9361.21 ms.

Static Drupal content:
Executed 729 queries in 114.54 ms.
Page execution time was 4341.03 ms.

The average page execution time for all of the pages we benchmarked was 5372.17 ms. Unacceptable.

What immediately jumps out at us is the page execution time compared to query time. Obviously the bottleneck is not MySQL. For some reason, Drupal is taking a long time to present the content to the user. We know from experience that a large number of installed modules can bring Drupal to a screeching halt. 2bits wrote a great article a few years ago on what Khalid calls "Open Buffet Syndrome." In fact, 2bits has amassed an immense knowledge base of articles on performance tuning and optimization with Drupal.

Using the devel module, we captured:

• # of queries
• API calls
• database queries
• overall page execution time

While some performance improvements could be made to offset the large page sizes (~300KB) and high number of HTTP requests (50-75 on average), the "low hanging fruit" is in page execution time.

On our test server, we configured APC, which is part of our standard configuration and observed immediate improvements. The average query execution times dropped to 84 ms and average page execution to 3100 ms. The apc.shm_size needs to be adjusted depending on available memory on the system, how much memory Drupal requires (largely affected by the number of modules if using mod_php). When making these changes to the production host, we had to increase the apc.shm_size and kernel.shmmax to 256MB before we found a happy APC. Values outside of that range quickly fragmented which negates any improvements an opcode cache provides.

Page execution times, while better, could still be improved. The opcode cache helps reduce the amount of work PHP needs to do, but Drupal is still spending way too much time building pages. Drupal calls drupal_load() for every module, on every page load... the more modules installed, the longer page execution times.

As an experiment, we switched the theme to Garland and noticed another ~80% improvement (after installing APC) in page execution time. Looking closer at the theme, we saw many custom PHP templates and over 30 views templates. We could have just looked at the code by hand and tried to pick out any obviously slow code. The more logical approach is to use Xdebug and enable profiling. Profiling allows you to record the path PHP takes while loading a page and reports time spent, memory usage and callbacks. Invaluable. In addition, Webgrind will give you a nice web interface to do the analysis.

Profiling found a slow chunk of custom PHP code that was used to render drop-down primary links. After reading through the code, we quickly realized why. It was calling node_load for every link to find out the node type. Completely unnecessary. Perhaps it was incomplete, perhaps leftover logic, or maybe it was just dropped it in because "it worked on a previous theme." Whatever the case, rewriting that piece of code to something a bit more sane helped shave another 1500 ms off the page execution time. We could have (and normally would) use the Nice Menus module but it required some CSS tweaks and adding another module was not really desirable.

To further improve performance, we installed Varnish as a front-end caching server. Since this site was already running Pressflow, it was a no-brainer. Varnish works great but does require some configuration tweaks to make it work well with Drupal. For a good starting point, check out Four Kitchens Varnish/Pressflow Wiki. Don't just trust any .vcl as gold. Read the documentation to become familiar with how Varnish works and do some tests to make sure content is actually being served by Varnish.

After all of the optimizations and caching implementation, we brought the average page execution time down from ~5300 ms to ~1400 ms for authenticated users. A very fast site indeed. Xdebug is the cat's pajamas and a great tool for learning how Drupal works. Profiling is an important feature but it can also be used with a debugger to set breakpoints, watch variables, etc. If you're on a Mac, we recommend MacGDBp.