ActiveRecord's Dirty Little Secret

Are you ready to hear the dirty little secret that ActiveRecord is hiding from you? ActiveRecord isn’t telling you how long your queries actually take!

It may come as a surprise that when ActiveRecord says a query takes 10ms to run it’s not telling you the whole truth. That time doesn’t include how long it took to create your objects!

Let’s break this down into a super simple example to see this in action. Here’s a database with 500 User objects and we’re going to load them all up at once:

1
2
3

User.all.to_a
# => User Load (10.4ms)  SELECT "users".* FROM "users"
# => [#<User id: 263, ... >, #<User id: 264, ... >, #<User id: 265, ... >, ... ]

If you haven’t discovered this dirty secret yet, you’d think this query took 10.4ms to run. Let’s take a look using the Benchmark class to see what the true cost of running this query is:

1
2
3

puts Benchmark.measure { User.all.to_a }
    user    system     total        real
0.143333  0.000000  0.143333 (  0.163123)

As you can see from the benchmark (using total time) that the query really takes 143.3ms. That’s over a 10x difference! And the majority of that time is spent building ActiveRecord models.

Application

How can you use this knowledge to improve the performance of your Rails apps? One way is to start looking more closely at your ActiveRecord query times.

Here’s an example response that I recently pulled out of an app:

1

Completed 200 OK in 1308ms (Views: 278.5ms | ActiveRecord: 89.8ms)

Database queries totalling 89.8ms are high but most of use would look to optimize the views at 278.5ms first. However when I dug further into this response, it turned out that there were multiple queries creating 750+ objects, costing over 500ms. Ouch! By tuning the request using methods like pluck and select I was able to reduce this request time by 50%.

Another place where object creation cost can be hidden is inside ActiveRecord after_initialize hooks. For those of you that are unfamiliar with it after_initialize is a callback that runs (you guessed it!) after initialization of an ActiveRecord object. In the event that your code has an expensive operation in an after_initialize hook your object load times will increase!

If you’d like to try this in your own code, drop the following lines into any ActiveRecord model:

1
2
3
4
5
6
7
8
9

class ActiveRecordModel
  after_initialize :test

  def test
    puts "start hook"
    sleep 5
    puts "end hook"
  end
end

Then run a quick measurement using the first method:

1
2
3
4
5
6

Benchmark.measure { ActiveRecordModel.first }
# => start hook
# => ... (5 second delay)
# => end hook
    user     system      total        real
0.010000   0.000000   0.010000 (  5.002338)

As you can see you get an extra 5 seconds added onto your query (because it’s a sleep it shows up in real, not in user or system.) Hopefully this code wouldn’t make its way into production but you can see how damaging a poorly written after_intialize hook can be!