Ruby on Rails is all about ActiveRecord, and ActiveRecord is all about making your database look like Ruby objects. Sometimes, that’s great. The barrier to entry is low; it’s a lot easier to read than a convoluted SQL query; it’s easier to test. But it also makes it very easy to write horrifically inefficient code. I don’t just mean N+1: I’m talking about NM+1 or worse!

The general solution—although it’s not always the right answer—is to use eager loading, which is reasonably well supported in ActiveRecord, but even that is more complicated that you might initially think. Which tables need to be eagerly loaded at which point depends in large part on what your controllers are doing with them. There’s no point loading your entire database in one nightmarishly over-eager Cartesian product, because that really won’t help performance. Trust me.

At the risk of stating the obvious, the most important thing about optimisation is finding out what’s causing the problem. To help with this, I’ve put together a very simple Rails plugin, QTrace, that helps track down

  1. which queries are happening a lot, and
  2. where they are being called from.

To achieve this, it provides two helpful features:

  1. A log of the stack trace that led to a particular query being called;
  2. A summary of database queries issued.

You can browse the code online or check it out via subversion:

svn co http://paulbattley.googlecode.com/svn/qtrace/trunk qtrace

Stick it in your application’s vendor/plugins directory, and you’ll get a report printed to the console at the end of every development session, something like this:

| Request         | No. calls | Time   |
| select products |        10 | 0.0113 |
| select images   |         1 | 0.0017 |
| select sessions |         1 | 0.0086 |
| insert sessions |         1 | 0.0013 |
| Total           |        13 | 0.0229 |

If any of the SELECTs happens more than once for a single page, it’s a good candidate for improvement. In this case, you can look in more detail by tracing the specific query. Put something like this in your environment.rb file:

QTrace.watch 'products'

Where the parameter is either a string or a regular expression. (It won’t actually do anything unless you are in development mode, so it’s safe if you forget and leave it in when you deploy.) You’ll get a stack trace on stdout every time a query matching that parameter is issued:

* SELECT * FROM products WHERE (products.`id` = 666)
* ./script/../config/../app/models/some_presenter.rb:15:in `product'
* script/../config/../app/views/default/some_partial.rhtml:4:in `...'
* script/../config/../app/views/default/index.rhtml:21:in `...'
* script/server:3

That should help you track down where it’s getting called, so that you can load the right associations where they’re needed.

It’s a very simplistic plugin, but I’ve found it invaluable in carrying out performance improvement work. I must thank Alex for nagging me to get around to writing this up!