Bullet

This plugin is aimed to give you some performance hints about ActiveRecord usage, what should use but not use, such as eager loading, counter cache and so on.

Now it provides you the hint of eager loading.

The others are todo, next may be couter cache.

script/plugin install git://github.com/flyerhzm/bullet.git

• Eager Loading, protect N+1 query

• Eager Loading, protect N+1 query

important: It is strongly recommended to disable cache in browser.

• add configuration to environment
  

  
  Bullet.enable = true
  Bullet::Association.logger = true 
  Bullet::Association.alert = true 
  

  • Bullet.enable (required), if enable is true (default is false), Bullet plugin is enabled. Otherwise, Bullet plugin is disabled.
  • Bullet::Association.logger (optional), if logger is true (default is true), the N+1 query hints will be appended to log/bullet.log with N+1 query method call stack. Otherwise, no hint to log/bullet.log.
  • Bullet::Association.alert (optional), if alert is true (default value), alert box will popup if there is N+1 query when browsing web page. Otherwise, no alert box.

• browse the webpage, if there are N+1 queries, alert box and bullet log will generate according to configurations. Alert box will only popup when the request’s Content-Type is text/html, and log/bullet.log will produce whatever the request is.

• example of log/bullet.log
  

  2009-08-16 13:18:53[INFO] PATH_INFO: /posts    model: Post => assocations: comments

  
  It represents that in page ‘/posts’, there is a N+1 query from Post to comments. It means you may have a logic code in controller @posts = Post.find(:all) should be changed to @posts = Post.find(:all, :include => :comments)

• To see what causes N+1 queries, check the spec/bullet_association_spec.rb

1. setup test environment

$ rails test
$ cd test
$ script/generate scaffold post name:string 
$ script/generate scaffold comment name:string post_id:integer
$ rake db:migrate

2. change app/model/post.rb and app/model/comment.rb

class Post < ActiveRecord::Base
  has_many :comments
end

class Comment < ActiveRecord::Base
  belongs_to :post
end

3. go to script/console and execute

post1 = Post.create(:name => 'first')
post2 = Post.create(:name => 'second')
post1.comments.create(:name => 'first')
post1.comments.create(:name => 'second')
post2.comments.create(:name => 'third')
post2.comments.create(:name => 'fourth')

4. change the app/views/posts/index.html.erb to produce a N+1 query

<h1>Listing posts</h1>

<table>
  <tr>
    <th>Name</th>
  </tr>

<% @posts.each do |post| %>
  <tr>
    <td><%=h post.name %></td>
    <td><%= post.comments.collect(&:name) %></td>
    <td><%= link_to 'Show', post %></td>
    <td><%= link_to 'Edit', edit_post_path(post) %></td>
    <td><%= link_to 'Destroy', post, :confirm => 'Are you sure?', :method => :delete %></td>
  </tr>
<% end %>
</table>

<br />

<%= link_to 'New post', new_post_path %>

5. add bullet plugin

$ script/plugin install git://github.com/flyerhzm/bullet.git

6. enable the bullet plugin in development, add a line to config/environments/development.rb

Bullet.enable = true

7. start server

$ script/server

8. input http://localhost:3000/posts in browser, then you will see a popup alert box says

The request has N+1 queries as follows:
model: Post => associations: [comment]

which means there is a N+1 query from post object to comments associations.

In the meanwhile, there’s a log appended into log/bullet.log file

2009-08-20 09:12:19[INFO] N+1 Query: PATH_INFO: /posts;    model: Post => assocations: [comments]
2009-08-20 09:12:19[INFO] N+1 Query: method call stack:
/Users/richard/Downloads/test/app/views/posts/index.html.erb:11:in `_run_erb_app47views47posts47index46html46erb'
/Users/richard/Downloads/test/app/views/posts/index.html.erb:8:in `each'
/Users/richard/Downloads/test/app/views/posts/index.html.erb:8:in `_run_erb_app47views47posts47index46html46erb'
/Users/richard/Downloads/test/app/controllers/posts_controller.rb:7:in `index'

The generated SQLs are

  Post Load (1.0ms)   SELECT * FROM "posts" 
  Comment Load (0.4ms)   SELECT * FROM "comments" WHERE ("comments".post_id = 1) 
  Comment Load (0.3ms)   SELECT * FROM "comments" WHERE ("comments".post_id = 2) 

9. fix the N+1 query, change app/controllers/posts_controller.rb file

  def index
    @posts = Post.find(:all, :include => :comments)

    respond_to do |format|
      format.html # index.html.erb
      format.xml  { render :xml => @posts }
    end 
  end 

10. refresh http://localhost:3000/posts page, no alert box and no log appended.

The generated SQLs are

  Post Load (0.5ms)   SELECT * FROM "posts" 
  Comment Load (0.5ms)   SELECT "comments".* FROM "comments" WHERE ("comments".post_id IN (1,2)) 

a N+1 query fixed. Cool!

Copyright © 2009 Richard Huang (flyerhzm@gmail.com), released under the MIT license