The maze book for programmers!
mazesforprogrammers.com

Algorithms, circle mazes, hex grids, masking, weaving, braiding, 3D and 4D grids, spheres, and more!

DRM-Free Ebook

The Buckblog

assorted ramblings by Jamis Buck

Watching ActiveRecord Do Its Thing

8 January 2007 — 2-minute read

ActiveRecord is cool and all, and it goes without saying that we all trust its judgment, but sometimes you just want to watch while it does its thing. For instance, just today, I wanted to verify that, in edge Rails, ActiveRecord no longer loads the entire collection when doing a scoped “create”.

In other words, consider the following snippet:

1
2
3
4
5
6
class Account < ActiveRecord::Base
  has_many :people
end

account = Account.find(:first)
person = account.people.create :name => "Jamis Buck"

Before Rails 1.2, that last line would actually load all of the people in that collection, before creating the new person. This was problematic if the collection had thousands of rows, because a simple insert suddenly became a monstrous resource sink.

So, how to verify that the collection is no longer being loaded?

Did you know you can install your own logger instances in Rails? Yah, you can. And yah, it’s pretty cool:

1
2
3
4
5
6
7
8
9
10
11
12
13
$ script/console
>> ActiveRecord::Base.logger = Logger.new(STDOUT)
=> #<Logger:0x2814134 ...>
>> account = Account.find(:first)
  Account Load (0.000346)   SELECT * FROM accounts LIMIT 1
=> #<Account:0x2665478 ...>
>> account.people.create :name => "Jamis Buck"
  Account Columns (0.000271)   SHOW FIELDS FROM accounts
  Person Columns (0.000246)   SHOW FIELDS FROM people
  SQL (0.000093)   BEGIN
  SQL (0.000351)   INSERT INTO people (`account_id`, `name`) VALUES (1, 'Jamis Buck')
  SQL (0.253635)   COMMIT
=> #<Person:0x27cb628 ...>

There you have it. Each call to ActiveRecord now logs all of its activity to STDOUT (e.g., the console), via your custom logger instance. The tale it tells is revealing, and reassuring: scoped creates do not, in fact, load the entire collection anymore.

Yay!

(One caveat: be sure to set up your logger first, before doing anything else, otherwise the default logger will get cached with no simple way to uncache it.)

Reader Comments

I hate to have no comment other than grammar nazism, but it should be “Watching ActiveRecord do Its Thing.”

Before Rails 1.2, that last line would actually load all of the people in that collection, before creating the new person. Why on earth does it do that?

Evan, thanks. I fixed two of those before I hit publish, but missed the most prominent one of all. :( sigh

Joachim, why does any bug do what it does? It was a side-effect of the implementation, and Rails 1.2 fixes it.

That’s really cool actually. Saves me having to keep a spare window open for the log.

That’s a fantastic and useful tip, thanks so much!

Thanks for the awesome tip. Is there a way to do this every time you run console? I put it at the end of script/console but it didn’t seem to work.

Luke, you can put something like this at the end of your config/environment.rb file:

if "irb" == $0
  ActiveRecord::Base.logger = Logger.new(STDOUT)
end

Thank you!

Building on this and another snippet you can have your ActiveRecords logging through STDOUT system-wide via your .irbrc. Noice!