codelevy

How Rails' Benchmarks Lie

Posted by Lance Ivy Wed, 28 Nov 2007 00:42:00 GMT

I’ve been on a benchmarking blogging spree lately. Creating BenchmarkForRails (B4R) with its non-invasive benchmarking technique has made it very easy to play around with timing of key Rails methods and develop a better picture of the true costs. The results have been amazing.

First of all, apologies to those of you still running Rails 1.2.x. B4R’s non-invasive technique only works well in Rails 2.0 due to some very nice refactoring, especially in Dispatcher and ActionController::Filters.

Blind Spots

Take a look at these benchmarks for the exact same request, as seen by Rails and B4R. This was done in development mode on an unoptimized page, so don’t worry too much about the times, ok? It’s the differences that are important.

Completed in 0.85246 (1 reqs/sec)
Rendering: 0.48872 (57%)
DB: 0.02561 (3%)

- [0.9532] GET /plans ----------------------------
   0.8528 processing action
   0.5015 rendering
   0.2533 activerecord find
   0.0461 development mode
   0.0073 before filters
   0.0046 session management
   0.0000 after filters
------------------------------ BenchmarkForRails -

The first line is from Rails’ built-in benchmarks. The following lines are from B4R. Please note that the benchmarks in B4R are not meant to add up, which is no different than Rails’ benchmarks.

Completion Time

Rails claims that the completion time was 0.85 seconds, and B4R claims that the completion time was 0.95. That’s a difference of 0.1 seconds. Big deal? It can be! But where’s the extra time coming from? Well, notice that B4R has an entry for “processing action”, and notice that this time (0.85) matches Rails’ declared completion time.

The problem is that there’s more machinery involved in handling a request then just processing the controller action. Here’s a quick list of some potentially significant things Rails is missing in its reported completion time:

• routing recognition
• before filters
• after filters
• session management

But these are all very real costs that you can (and should) strive to optimize. They’re costs you should know about. And they’re costs that definitely affect your requests-per-second.

DB Access

Rails’ idea of query costs is how much time was spent waiting for your database to answer, and so it comes back with an incredibly low 0.025 seconds. With numbers like that, why would anyone optimize queries! Why would anyone bother with eager-loading?

Pure database access time only matters for big queries. But if you make just ten small queries, the true costs are somewhere else: ActiveRecord’s query construction.

Now go back to the sample benchmarks above. Notice the “activerecord find” entry? That’s 0.25 seconds. No, it didn’t misplace the decimal – the real cost of executing queries on the page was 10x what Rails reported. Why? Because the database is faster than ActiveRecord, obviously.

So yeah, there’s some real motivation for eager loading, yeah?