Ridiculously Slow View Rendering

rubyonrails-talk
1

Hi,

I've been experiencing some severe slowness in rendering the views in my users/index action. It's really not doing anything fancy at all, and has been driving me nuts the last few days. I'm running Rails 2.2... does anyone have any idea how to resolve this? Look at home much time is being consumed by the view. Obviously those response times are unacceptable, and this is with 3 instances of Thin running in production on a VPS...

#production.log Rendering users/index Completed in 11386ms (View: 8693, DB: 151)

Rendering users/index Completed in 5024ms (View: 3286, DB: 16)

Rendering users/index Completed in 11692ms (View: 8811, DB: 105

Rendering users/index Completed in 11184ms (View: 8116, DB: 364)

Rendering sessions/new Completed in 1696ms (View: 1012, DB: 0)

Rendering users/index Completed in 8361ms (View: 6898, DB: 107)

#users/index.html.erb <div>         <h2>Users</h2>          <%= render :partial => "users/user", :collection => @users %>         <%= will_paginate @users %>         <% if @users.empty? -%>                 <p class="infobox">Looks like we couldn't find anything matching your search. Maybe you should consider broadening it? </p>         <% end -%> </div>

#_user.html.erb <% div_for user do %>         <h2><%= link_to(image_tag(user.photo.url(:small), :alt => user.login, :height => 130, :width => 130, :class => "profile-photo"), user) %><%= link_to(user.login, user) %></h2>         <p class="user-location"><%= user.age %> / <%= user.sex %> / < %= user.city %>, <%= user.state %></p>         <p class="user-summary"><%= truncate_words(user.about_me || "", 80) -%></p> <% end %>

The template code is here too: http://gist.github.com/90786

Any ideas?

Thanks!

Avishai

2

I can't find anything fundamentally wrong on your views, but we haven't seen any controller and model code.

Try benchmarking/profiling your app to find out exactly what the bottleneck is. See http://guides.rubyonrails.org/performance_testing.html

A good start may be your DB. What RDMS are you using? Do you have proper indexes? Have you tried running the SQL directly (pick it up from the logs) and finding out if it's a problem with Rails at all? How big is the user.about_me column be? If it's huge you may be hitting a bandwidth bottleneck (DB => web server).

Not much more occurs to me at this point, but hope that points you on the right direction.

3

Hi,

I've been experiencing some severe slowness in rendering the views in my users/index action. It's really not doing anything fancy at all, and has been driving me nuts the last few days. I'm running Rails 2.2... does anyone have any idea how to resolve this? Look at home much time is being consumed by the view. Obviously those response times are unacceptable, and this is with 3 instances of Thin running in production on a VPS...

I'd turn up your log level. If for example each user partial was
loading its photo from the database 1 by 1 then you'd see a zillion
sql queries in your log.

Fred

4

Interesting. Maybe something is going on in the controller. I've tried running the resulting SQL queries directly, and they still seem to be fetching pretty quickly...

The controller contains a lot of conditionals, maybe that's the issue? I've used Newrelic RPM to analyze my SQL, and it looks like for everything there's no USING FILESYSTEM, so indexes are set up properly... The about_me column is a regular freetext column (TEXT i think), so the length varies anywhere from zero to a few paragraphs of text. The photos are handled with paperclip, but are just URLs, not the actual files in the DB. Could it still be a bandwidth still be an issue DB => webserver if they're on the same box?

Controller code is at the end here: http://gist.github.com/90786

Cheers,

Avishai

5

Fred, I took your suggestion to up the log level and this is what it reveals:

Processing UsersController#index [GET]   Parameters: {"action"=>"index", "controller"=>"users", "page"=>"11"}   User Load (26.0ms) SELECT * FROM `users` ORDER BY users.created_at DESC LIMIT 100, 10   SQL (0.2ms) SELECT count(*) AS count_all FROM `users` Rendering template within layouts/application Rendering users/index Rendered users/_user (3.7ms) Rendered users/_user (2.9ms) Rendered users/_user (3.1ms) Rendered users/_user (42.6ms) Rendered users/_user (39.6ms) Rendered users/_user (121.2ms) Rendered users/_user (32.9ms) Rendered users/_user (4.9ms) Rendered users/_user (14.7ms) Rendered users/_user (2.7ms)   User Load (0.2ms) SELECT * FROM `users` WHERE (`users`.`id` = 1) LIMIT 1 Rendered users/_search (3.0ms) Rendered users/_user_bar (2.1ms) Completed in 319ms (View: 288, DB: 27)

However, once I hit refresh a bunch of times, all those partials drop to only a few ms each. Including the ones that show as 40, 120, etc above. Those long ones all had text in the about_me....

-Avishai

6

This is good to know. “Completed in 319ms (View: 288, DB: 27)” 319ms is not hardly close to your original 11386ms.

I notice that your params below do not have any of the “search” criteria ([:user][:interests], etc). If you run the view using the criteria, does performance degrade?

7

I tried a bunch of different searches, and it's actually loading reasonably quickly still... < 500ms at least.

Also, in the process I upgraded from Rails 2.2.1 to 2.3.2, so maybe that helped somewhat too.

-Avishai

8

When I leave the params off and just go for a straight index, I'm still seeing this:

Processing UsersController#index [GET]   Parameters: {"action"=>"index", "controller"=>"users"}   User Load (5.6ms) SELECT * FROM `users` ORDER BY users.created_at DESC LIMIT 0, 10   SQL (0.4ms) SELECT count(*) AS count_all FROM `users` Rendering template within layouts/application Rendering users/index Rendered users/_user (432.4ms) Rendered users/_user (133.4ms) Rendered users/_user (96.1ms) Rendered users/_user (202.4ms) Rendered users/_user (26.1ms) Rendered users/_user (55.6ms) Rendered users/_user (51.3ms) Rendered users/_user (21.8ms) Rendered users/_user (38.3ms) Rendered users/_user (47.9ms) User Load (9.3ms) SELECT * FROM `users` WHERE (`users`.`id` = 1) LIMIT 1 Rendered users/_search (67.1ms)   SQL (3.8ms) SELECT count(*) AS count_all FROM `messages` WHERE (`messages`.receiver_id = 1 AND (`messages`.`read` = 0)) Rendered users/_user_bar (134.7ms) Completed in 1861ms (View: 1534, DB: 19)

I had thought that it had something had to do with the size of the about_me as mentioned before, but I checked again, and some of those long-rendering user partials had no content for the about_me field...

Any other ideas as to why this could be taking so long to render?

Thanks a lot

Avishai

9

To be honest, I really don’t know what’s going on, but I would try commenting out the image_tag. First of all, it is probably causing another trip to the DB per user. Second, I don’t know how heavy the images are, but using height and width may be hiding the fact that they’re big, and you’re just using html to scale them down on your view. Do you see similar results when completely removing the images on that _user partial?

10

Yep I agree there, you should create thumbs that are totally separate. Otherwise your sending megs instead of K. And you can create the thumbs on new user signup. I've done that, and it woks really well. Really need to check your image sizes.