Rails template rendering slow?

Question

i'm currently using mongrel server running rails2.3.5 with ruby1.8, and got this odd behavior:

Rendered common/_header (3.1ms)
Rendered common/_categories (1.2ms)
Rendered common/_footer (1.2ms)
Completed in 6934ms (View: 5897, DB: 174)   ## 5897ms... to rendering a local page??

why?

updated

only one user there.. i'm working on my notebook, the problem lies in the rendering of view, i thought. but i just can't figure out why, since there's nothing fancy in the partials layouts, and templates.

the server log

Processing PostController#show (for 127.0.0.1 at 2009-12-29 22:09:35) [GET]
  Parameters: {"action"=>"show", "id"=>"1", "controller"=>"post"}
  Post Columns (4.0ms)   SHOW FIELDS FROM `posts`
  Post Load (3.0ms)   SELECT * FROM `posts` WHERE (`posts`.`id` = 1) 
  User Columns (4.5ms)   SHOW FIELDS FROM `users`
  User Load (3.1ms)   SELECT * FROM `users` WHERE (`users`.`persistence_token` = 'XXXXXXXXXX') LIMIT 1
  Answer Columns (3.5ms)   SHOW FIELDS FROM `answers`
  Reading Columns (2.5ms)   SHOW FIELDS FROM `readings`
  Reading Load (1.2ms)   SELECT * FROM `readings` WHERE (`readings`.`user_id` = 9) AND (`readings`.post_id = 1) LIMIT 1
Rendering template within layouts/base
Rendering post/show
  Vote Load (1.5ms)   SELECT * FROM `votes` WHERE (`votes`.post_id = 1) 
  Vote Columns (3.0ms)   SHOW FIELDS FROM `votes`
  SQL (1.0ms)   SELECT count(*) AS count_all FROM `readings` WHERE (`readings`.post_id = 1) 
  User Load (3.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  posts_tags Columns (3.3ms)   SHOW FIELDS FROM `posts_tags`
  Tag Load (1.8ms)   SELECT * FROM `tags` INNER JOIN `posts_tags` ON `tags`.id = `posts_tags`.tag_id WHERE (`posts_tags`.post_id = 1 ) 
  Tag Columns (5.4ms)   SHOW FIELDS FROM `tags`
  SQL (1.1ms)   SELECT count(*) AS count_all FROM `answers` WHERE (`answers`.post_id = 1) 
  Answer Load (23.4ms)   SELECT * FROM `answers` WHERE (`answers`.post_id = 1) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  Digg Load (2.2ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 9) 
  Digg Columns (3.3ms)   SHOW FIELDS FROM `diggs`
  Reply Load (2.8ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 9) 
  Reply Columns (3.4ms)   SHOW FIELDS FROM `replies`
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  Digg Load (1.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 10) 
  Reply Load (2.7ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 10) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  User Load (3.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  Digg Load (1.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 11) 
  Reply Load (2.1ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 11) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.9ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 12) 
  Reply Load (1.7ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 12) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (2.5ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 13) 
  Reply Load (1.8ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 13) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (11.0ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 14) 
  Reply Load (1.7ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 14) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.7ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 15) 
  Reply Load (1.9ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 15) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.7ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 16) 
  Reply Load (11.7ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 16) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.7ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 17) 
  Reply Load (1.8ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 17) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (10.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 18) 
  Reply Load (2.0ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 18) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg load (1.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 19) 
  Reply Load (2.1ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 19) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (8.6ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 20) 
  Reply Load (1.6ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 20) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 21) 
  Reply Load (1.6ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 21) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 22) 
  Reply Load (1.6ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 22) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.7ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 23) 
  Reply Load (7.3ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 23) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 24) 
  Reply Load (8.6ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 24) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 25) 
  Reply Load (2.0ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 25) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 9) 
  Digg Load (1.8ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 26) 
  Reply Load (1.8ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 26) 
  CACHE (0.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 4) 
  Digg Load (1.6ms)   SELECT * FROM `diggs` WHERE (`diggs`.answer_id = 27) 
  Reply Load (1.8ms)   SELECT * FROM `replies` WHERE (`replies`.answer_id = 27) 
Rendered common/_header (3.2ms)
Rendered common/_categories (1.5ms)
Rendered common/_footer (10.8ms)
Completed in 7407ms (View: 6376, DB: 194) | 200 OK [http://localhost/posts/1]

updated

seems like there is no indexing in my join tables.

Answer 1

Let's see more of the log, start with the "Processing ..." for the controller all the way through to the "Completed..."

Answer 2

My steps here: profile, fix issues found via that way... and if that still doesn't work, look into caching in Rails.

But only cache after profiling

Answer 3

There are various things that can result in this:

• Your server is slow. Consider using mod_rails. If you're already doing this, you might need some more RAM or another kind of hardware upgrade?

• You have too many requests to the database. Look at the log to see what's going on

• You're not using caching in an effective manner. Depending on your server there are various solutions

• Your code is not optimized. Try running benchmarks to see what you could improve.