Watching ActiveRecord Do Its Thing

Posted by Jamis on January 08, 2007 @ 11:45 AM

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.)

Posted in Tips & Tricks

Comments

Have something to add? Click here to leave a comment.

08 Jan 2007

1. Evan said...

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

2. Joachim Bengtsson said...

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?

3. Jamis said...

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.

4. Adam Sanderson said...

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

5. Don said...

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

09 Jan 2007

6. Luke said...

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.

7. Jamis said...

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

8. Luke said...

Thank you!

05 Feb 2007

9. Tim Lucas said...

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