Rails3 - why my view loading times are so long?

Question

So one week ago I started to move my old app written in Rails 2.3.5 to new 3.0. Unfortunately, I found out that some of the views are loading surprisingly slow.

Example:

Rails 2.3.5 Ruby 1.8.7 -> WEBrick: Completed in 297ms (View: 143, DB: 40)
Rails 3.0.0 Ruby 1.8.7 -> WEBrick: Completed in 3081ms (View: 261, ActiveRecord: 108)
Rails 3.0.0 Ruby 1.8.7 -> WEBrick: Completed in 2495ms (View: 356, ActiveRecord: 76), slightly improved version -> less SQL queries, more counting in the view
Rails 3.0.0 Ruby 1.9.2 -> WEBrick: Completed in 2941ms (View: 423, ActiveRecord: 90), imp. version

Times differ with every reload of course, but still you can get the idea - in Rails 3 this view loads 10 times slower, no matter if I use Ruby 1.8.7 or 1.9.2. I checked that in development and production environments as well as on Heroku - everytime it looks the same. Other views' loading times are about 2 times slower in 3.0.

Here you can find all the logs:

http://img811.imageshack.us/img811/8514/1rails235ruby187oldver.jpg

http://img217.imageshack.us/img217/5521/2rails300ruby187oldver.jpg

http://img7.imageshack.us/img7/3089/3rails300ruby187diffver.jpg

http://img534.imageshack.us/img534/5138/4rails300ruby192diffver.jpg

What's wrong here? I was busy for 1 week to adapt all my controllers, views, gems, plugins and configs to Rails3 and now I'm stuck... I feel I really should learn some PHP, because it would give me more control on what actually is happening.

The view goes here:

    <%= render :partial => 'menu' %>

<div id="preload">
    <%= image_tag("/images/next_big.png") %>
</div>  

    <div class="clearer"><hr /></div>

    <div class="picture">
        <%= link_to image_tag(@picture.img.url(:page), :alt => @picture.title.gsub("; "," "), :border => 0), :action => "fullsize", :link => @picture.link %>
    </div>

    <div class="right">
        <div class="title"><%= raw @picture.title.gsub("; ","<br />") %></div>
        <div class="tags">
            <% taglist = @picture.cached_tag_list.split(", ") %>
            <% x = taglist.length %>
            <% y = 0 %>
            <% x.times do %>
                <a href = "/tag/<%= taglist[y].gsub(" ", "_") %>"><%= taglist[y] %></a><% y += 1 %><% if y != x %>,<% end %>
            <% end %>           
        </div>
        <div class="datetime">Posted <%= time_ago_in_words(@picture.created_at) %> ago</div>
        <% this_voting = "voting" %>
        <div id="<%= this_voting %>" class="voting">
            <%= link_to image_tag("/images/yes.png", :alt => "Vote up", :class => 'vote_button'), {:action => :yes_vote, :id => @picture.id}, :remote => true %> 
            <span id="<%= this_voting + '_result' %>"><%= @picture.voting %></span> 
            <%= link_to image_tag("/images/no.png", :alt => "Vote against", :class => 'vote_button'), {:action => :no_vote, :id => @picture.id}, :remote => true %> 
            Pageviews: <%= @picture.views %>    
        </div>
        <div class="link">Link:<br /><input type="text" value="http://bzzzzzzzzzzz.com/&lt;%= @picture.link %>" /></div>
        <div class="share">Share:<br />
            <a href="http://facebook.com/sharer.php?u=http://bzzzzzzzzzzz.com/&lt;%= @picture.link %>" target="_blank">
                <img src="/images/mfb.png" alt="Facebook" onmouseover="puttext(fb, 0)" onmouseout="cleartext(0)" border="0" /></a>
            <a href="http://twitter.com/home?status=http://bzzzzzzzzzzz.com/&lt;%= @picture.link %>" target="_blank">
                <img src="/images/mtwitter.png" alt="Twitter" onmouseover="puttext(twitter, 0)" onmouseout="cleartext(0)" border="0" /></a>
            <a href="http://digg.com/submit?url=http://bzzzzzzzzzzz.com/&lt;%= @picture.link %>&amp;title=<%= @picture.title.gsub("; "," ") %>&amp;media=image&amp;topic=comedy" target="_blank">
                <img src="/images/mdigg.png" alt="Digg" onmouseover="puttext(digg, 0)" onmouseout="cleartext(0)" border="0" /></a>
            <a href="http://reddit.com/submit?url=http://bzzzzzzzzzzz.com/&lt;%= @picture.link %>&amp;title=<%= @picture.title.gsub("; "," ") %>" target="_blank">
                <img src="/images/mreddit.png" alt="Reddit" onmouseover="puttext(reddit, 0)" onmouseout="cleartext(0)" border="0" /></a>
            <a href="http://stumbleupon.com/submit?url=http://bzzzzzzzzzzz.com/&lt;%= @picture.link %>" target="_blank">
                <img src="/images/msu.png" alt="StumbleUpon" onmouseover="puttext(su, 0)" onmouseout="cleartext(0)" border="0" /></a>
        </div>
            <div id="share_caption0" class="share_caption"></div>
            <div class="small_clearer"></div>
        <% if @picture.last_comment_body %>
        <div class="links_to_c">
            <a href="#comments"><%= @picture.comments_count %> comment<% if @picture.comments_count > 1 %>s<% end %></a> 
            | <%= link_to "Write a comment", :anchor => "add_comment" %>
        </div>
        <% else %>
        <div class="links_to_c">
            <%= link_to "No comments, write a comment", :anchor => "add_comment" %>
        </div>
        <% end %>
        <% if @picture.fullsize == true %>
            <div class="fullsize">
                <%= link_to "Fullsize", :action => "fullsize", :link => @picture.link %>
            </div>
        <% end %>       
    </div>
    <div class="next">
    <% if @picture.id != 1 %>
        <% next_pict_link = Picture.find(@picture.id.to_i - 1).link %>
        <%= link_to image_tag("/images/next.png", :alt => 'Next picture', :border=>0, :onmouseover => "this.src='/images/next_big.png'", :onmouseout => "this.src='/images/next.png'"), :action => 'show', :link => next_pict_link %>
    <% else %>
        <% last_pict_link = Picture.find(:last).link %>
        <%= link_to image_tag("/images/next.png", :alt => 'Latest picture', :border=>0, :onmouseover => "this.src='/images/next_big.png'", :onmouseout => "this.src='/images/next.png'"), :action => 'show', :link => last_pict_link %>
    <% end %>
    </div>

    <div class="clearer" style="padding-bottom: 0px"><hr /></div>
    <h1><%= @thumbnails_text %></h1>
    <% @pictures.each do |pict| %>
        <%= link_to image_tag(pict.img.url(:thumb), :alt => "", :border => 1, :class => 'thumbnail'), :action => "show", :link => pict.link %>
    <% end %>   
    <div class="clearer" style="padding-top: 6px; padding-bottom: 15px"><hr /></div>
        <% if @picture.last_comment_body != nil %>
            <a name="comments"><h1>Comments:</h1></a>
            <% @picture.comments.each do |comment| %>
            <div id="<%= comment.id %>" class="comment">
                <font class="c_author"><%= comment.author %></font>
                <font class="c_datetime"><%= time_ago_in_words(comment.created_at) %> ago</font>
                <font class="c_id">#<%= comment.id %></font><br />
                <div class="c_body"><%= comment.body.gsub(/\n/, '<br />') %></div>
             </div>
            <% end %>
        <% end %>       
    <div id="insert_here"></div>
    <a name="add_comment"></a>
    <%= form_for [@picture, Comment.new], :remote => true do |f| %>
    <div id="add_comment" <% if @picture.last_comment_body == nil %>style="margin-top: 15px"<% end %>>
        <div class="f_section">
            <div class="f_type" style="padding-right: 46px"><%= f.label :author, "Nick:" %></div>
            <div class="f_field"><%= f.text_field :author, :maxlength => 40 %></div>
        </div>
        <div class="f_section">
            <div class="f_type"><%= f.label :body, "Comment:" %></div>
            <div class="f_field"><%= f.text_area :body, :maxlength => 2000, :rows => 6 %></div>
        </div>
        <div class="f_section">
            <div class="f_type" style="padding-right: 20px"><%= f.label :captcha, "Captcha:" %></div>
            <div class="f_captcha"><%= raw recaptcha_tags %></div>
        </div>
        <div class="f_submit">
            <%= f.submit "Submit", :class => 'submit' %>
        </div>
    </div>
    <% end %>
<div class="clearer bottom_clearer fifty_from_top"><hr /></div>

Answer 1

There's a lot that can go wrong in any environment, especially PHP.

What could be the issue here is using WEBrick with Rails 3. Using an alternative like mongrel or Passenger could help narrow down this problem.

You could have a situation where something that should be working is timing out, for instance, Memcache is not configured correctly, or a CURL request is being made that eventually fails.

It's always handy to have a very basic view with nothing in it you can use to benchmark the baseline performance of your application. A simple controller with a single action and an empty view can do the trick here. Diagnosing the problem will be a case of adding some of your controller code to this empty action until you can trigger the problem, or stripping parts out of your views to see if that's what causes it.

I usually start commenting out partials to see if one of them is causing the drag, and from there move back to the controller to pay close attention to what's getting loaded.

Answer 2

So.. I think I have tracked down the problem. I saw that WEBrick is giving me back two deprecation warnings (related to RAILS_ROOT and RAILS_ENV). I didnt use any of these phrases by myself, so I started to look for them in my plugins and gems. I found out that they are being used by paperclip (2.3.4) and recaptcha gem (recaptcha by ambethia 0.2.3). Then I removed paperclip from my Gemfile and commented all paperclip related settings from my model. The loading times dropped to 400-500ms.

So I guess I need to wait until somebody will fix paperclip... Im a ruby-newbie, so I wont be able to do this by myself :/