Ticket #542 (defect)
Opened 1 year ago
Last modified 8 months ago
Performance of the home page, seems slow
Status: assigned
| Reported by: | hajee@moretIA.com | Assigned to: | bsag (accepted) |
|---|---|---|---|
| Priority: | high | Milestone: | 2.0 |
| Component: | Coding | Version: | trunk |
| Severity: | major | Keywords: | performance |
| Cc: |
I'm using the truck version. Performance of the home page seems much slower then previous versions. Included is the log of rendering the home page. hajee004s:/Library/WebServer/Documents/tracks/current root# script/server => Booting Mongrel (use 'script/server webrick' to force WEBrick) => Rails application starting on http://0.0.0.0:3000 => Call with -d to detach => Ctrl-C to shutdown server ** Starting Mongrel listening at 0.0.0.0:3000 ** Starting Rails with development environment... has_many_polymorphs: Rails environment detected has_many_polymorphs: loaded ok SwitchEnvironmentController?: missing default helper path switch_environment_helper UnobtrusiveJavascriptController?: missing default helper path unobtrusive_javascript_helper has_many_polymorphs: autoload hook invoked has_many_polymorphs: INIT ** Rails loaded. ** Loading any Rails specific GemPlugins? ** Signals ready. TERM => stop. USR2 => restart. INT => stop (no restart). ** Rails signals registered. HUP => reload (without restart). It might not work well. ** Mongrel available at 0.0.0.0:3000 ** Use CTRL-C to stop.
SQL (0.000479) SET SQL_AUTO_IS_NULL=0 Tagging Columns (0.004406) SHOW FIELDS FROM taggings Todo Columns (0.005293) SHOW FIELDS FROM todos has_many_polymorphs: injecting dependencies has_many_polymorphs: preloaded parent model Tag
Processing TodosController#index? (for 10.0.0.156 at 2007-07-30 22:43:37) [GET]
Session ID: 055722f63fe444e76e91c24f5c92e09b Parameters: {"action"=>"index", "controller"=>"todos"} User Columns (0.004880) SHOW FIELDS FROM users Preference Columns (0.007723) SHOW FIELDS FROM preferences User Load Including Associations (0.006263) SELECT users.id AS t0_r0, users.login AS t0_r1, users.crypted_password AS t0_r2, users.token AS t0_r3, users.is_admin AS t0_r4, users.first_name AS t0_r5, users.last_name AS t0_r6, users.auth_type AS t0_r7, users.open_id_url AS t0_r8, users.remember_token AS t0_r9, users.remember_token_expires_at AS t0_r10, preferences.id AS t1_r0, preferences.user_id AS t1_r1, preferences.date_format AS t1_r2, preferences.week_starts AS t1_r3, preferences.show_number_completed AS t1_r4, preferences.staleness_starts AS t1_r5, preferences.show_completed_projects_in_sidebar AS t1_r6, preferences.show_hidden_contexts_in_sidebar AS t1_r7, preferences.due_style AS t1_r8, preferences.admin_email AS t1_r9, preferences.refresh AS t1_r10, preferences.verbose_action_descriptors AS t1_r11, preferences.show_hidden_projects_in_sidebar AS t1_r12, preferences.time_zone AS t1_r13, preferences.show_project_on_todo_done AS t1_r14, preferences.title_date_format AS t1_r15, preferences.mobile_todos_per_page AS t1_r16 FROM users LEFT OUTER JOIN preferences ON preferences.user_id = users.id WHERE (users.id = 1) SQL (0.005529) SELECT count(*) AS count_all, project_id AS project_id FROM todos WHERE (user_id = 1 and state = 'active') GROUP BY project_id SQL (0.002191) SELECT count(*) AS count_all, context_id AS context_id FROM todos WHERE (user_id = 1 and state = 'active') GROUP BY context_id Project Columns (0.004824) SHOW FIELDS FROM projects Context Columns (0.006303) SHOW FIELDS FROM contexts Tag Columns (0.005997) SHOW FIELDS FROM tags Todo Load Including Associations (0.190127) SELECT todos.id AS t0_r0, todos.context_id AS t0_r1, todos.project_id AS t0_r2, todos.description AS t0_r3, todos.notes AS t0_r4, todos.created_at AS t0_r5, todos.due AS t0_r6, todos.completed_at AS t0_r7, todos.user_id AS t0_r8, todos.show_from AS t0_r9, todos.state AS t0_r10, projects.id AS t1_r0, projects.name AS t1_r1, projects.position AS t1_r2, projects.user_id AS t1_r3, projects.description AS t1_r4, projects.state AS t1_r5, projects.created_at AS t1_r6, projects.updated_at AS t1_r7, projects.default_context_id AS t1_r8, contexts.id AS t2_r0, contexts.name AS t2_r1, contexts.position AS t2_r2, contexts.hide AS t2_r3, contexts.user_id AS t2_r4, contexts.created_at AS t2_r5, contexts.updated_at AS t2_r6, tags.id AS t3_r0, tags.name AS t3_r1, tags.created_at AS t3_r2, tags.updated_at AS t3_r3 FROM todos LEFT OUTER JOIN projects ON projects.id = todos.project_id LEFT OUTER JOIN contexts ON contexts.id = todos.context_id LEFT OUTER JOIN taggings ON (todos.id = taggings.taggable_id AND taggings.taggable_type = 'Todo') LEFT OUTER JOIN tags ON (tags.id = taggings.tag_id) WHERE (todos.user_id = 1 AND (todos.state = 'active' or todos.state = 'completed')) ORDER BY completed_at DESC, todos.created_at DESC Todo Load Including Associations (0.018530) SELECT todos.id AS t0_r0, todos.context_id AS t0_r1, todos.project_id AS t0_r2, todos.description AS t0_r3, todos.notes AS t0_r4, todos.created_at AS t0_r5, todos.due AS t0_r6, todos.completed_at AS t0_r7, todos.user_id AS t0_r8, todos.show_from AS t0_r9, todos.state AS t0_r10, projects.id AS t1_r0, projects.name AS t1_r1, projects.position AS t1_r2, projects.user_id AS t1_r3, projects.description AS t1_r4, projects.state AS t1_r5, projects.created_at AS t1_r6, projects.updated_at AS t1_r7, projects.default_context_id AS t1_r8, contexts.id AS t2_r0, contexts.name AS t2_r1, contexts.position AS t2_r2, contexts.hide AS t2_r3, contexts.user_id AS t2_r4, contexts.created_at AS t2_r5, contexts.updated_at AS t2_r6, tags.id AS t3_r0, tags.name AS t3_r1, tags.created_at AS t3_r2, tags.updated_at AS t3_r3 FROM todos LEFT OUTER JOIN projects ON projects.id = todos.project_id LEFT OUTER JOIN contexts ON contexts.id = todos.context_id LEFT OUTER JOIN taggings ON (todos.id = taggings.taggable_id AND taggings.taggable_type = 'Todo') LEFT OUTER JOIN tags ON (tags.id = taggings.tag_id) WHERE (todos.user_id = 1 AND (todos.state = 'active')) ORDER BY todos.due IS NULL, todos.due ASC, todos.created_at ASC, completed_at DESC, todos.created_at DESC Project Load Including Associations (0.108122) SELECT projects.id AS t0_r0, projects.name AS t0_r1, projects.position AS t0_r2, projects.user_id AS t0_r3, projects.description AS t0_r4, projects.state AS t0_r5, projects.created_at AS t0_r6, projects.updated_at AS t0_r7, projects.default_context_id AS t0_r8, todos.id AS t1_r0, todos.context_id AS t1_r1, todos.project_id AS t1_r2, todos.description AS t1_r3, todos.notes AS t1_r4, todos.created_at AS t1_r5, todos.due AS t1_r6, todos.completed_at AS t1_r7, todos.user_id AS t1_r8, todos.show_from AS t1_r9, todos.state AS t1_r10 FROM projects LEFT OUTER JOIN todos ON todos.project_id = projects.id WHERE (projects.user_id = 1) ORDER BY position ASC Context Load Including Associations (0.104260) SELECT contexts.id AS t0_r0, contexts.name AS t0_r1, contexts.position AS t0_r2, contexts.hide AS t0_r3, contexts.user_id AS t0_r4, contexts.created_at AS t0_r5, contexts.updated_at AS t0_r6, todos.id AS t1_r0, todos.context_id AS t1_r1, todos.project_id AS t1_r2, todos.description AS t1_r3, todos.notes AS t1_r4, todos.created_at AS t1_r5, todos.due AS t1_r6, todos.completed_at AS t1_r7, todos.user_id AS t1_r8, todos.show_from AS t1_r9, todos.state AS t1_r10 FROM contexts LEFT OUTER JOIN todos ON todos.context_id = contexts.id WHERE (contexts.user_id = 1) ORDER BY position ASC Todo Load IDs For Limited Eager Loading (0.009136) SELECT id FROM todos WHERE (todos.user_id = 1 AND (todos.state = 'completed' and todos.completed_at is not null)) ORDER BY todos.completed_at DESC LIMIT 5 Todo Load Including Associations (0.011276) SELECT todos.id AS t0_r0, todos.context_id AS t0_r1, todos.project_id AS t0_r2, todos.description AS t0_r3, todos.notes AS t0_r4, todos.created_at AS t0_r5, todos.due AS t0_r6, todos.completed_at AS t0_r7, todos.user_id AS t0_r8, todos.show_from AS t0_r9, todos.state AS t0_r10, contexts.id AS t1_r0, contexts.name AS t1_r1, contexts.position AS t1_r2, contexts.hide AS t1_r3, contexts.user_id AS t1_r4, contexts.created_at AS t1_r5, contexts.updated_at AS t1_r6, projects.id AS t2_r0, projects.name AS t2_r1, projects.position AS t2_r2, projects.user_id AS t2_r3, projects.description AS t2_r4, projects.state AS t2_r5, projects.created_at AS t2_r6, projects.updated_at AS t2_r7, projects.default_context_id AS t2_r8, tags.id AS t3_r0, tags.name AS t3_r1, tags.created_at AS t3_r2, tags.updated_at AS t3_r3 FROM todos LEFT OUTER JOIN contexts ON contexts.id = todos.context_id LEFT OUTER JOIN projects ON projects.id = todos.project_id LEFT OUTER JOIN taggings ON (todos.id = taggings.taggable_id AND taggings.taggable_type = 'Todo') LEFT OUTER JOIN tags ON (tags.id = taggings.tag_id) WHERE (todos.user_id = 1 AND (todos.state = 'completed' and todos.completed_at is not null)) AND todos.id IN ('451', '591', '635', '634', '616') ORDER BY todos.completed_at DESC Context Load (0.003730) SELECT * FROM contexts WHERE (contexts.id = 2) Context Load (0.002074) SELECT * FROM contexts WHERE (contexts.id = 2) Context Load (0.001839) SELECT * FROM contexts WHERE (contexts.id = 2) Context Load (0.001816) SELECT * FROM contexts WHERE (contexts.id = 2) Context Load (0.001970) SELECT * FROM contexts WHERE (contexts.id = 1) Context Load (0.001740) SELECT * FROM contexts WHERE (contexts.id = 2) Context Load (0.001709) SELECT * FROM contexts WHERE (contexts.id = 1) Context Load (0.001975) SELECT * FROM contexts WHERE (contexts.id = 1) Context Load (0.001727) SELECT * FROM contexts WHERE (contexts.id = 1) Context Load (0.001762) SELECT * FROM contexts WHERE (contexts.id = 2) Context Load (0.001805) SELECT * FROM contexts WHERE (contexts.id = 1) Context Load (0.001735) SELECT * FROM contexts WHERE (contexts.id = 1) Rendering within layouts/standard Rendering todos/index Rendered todos/_todo (0.06213) Rendered todos/_todo (0.04967) Rendered todos/_todo (0.04772) Rendered todos/_todo (0.04522) Rendered todos/_todo (0.04587) Rendered todos/_todo (0.04447) Rendered todos/_todo (0.04450) Rendered todos/_todo (0.04510) Rendered todos/_todo (0.04928) Rendered contexts/_context (0.47278) Rendered todos/_todo (0.04561) Rendered todos/_todo (0.04354) Rendered todos/_todo (0.04617) Rendered todos/_todo (0.22122) Rendered todos/_todo (0.04637) Rendered todos/_todo (0.05110) Rendered todos/_toggle_notes (0.03037) Rendered todos/_todo (0.08107) Rendered todos/_todo (0.04284) Rendered contexts/_context (0.60880) Rendered contexts/_context (0.01735) Rendered todos/_todo (0.04302) Rendered contexts/_context (0.06246) Rendered contexts/_context (0.01685) Rendered contexts/_context (0.01862) Rendered todos/_todo (0.04514) Rendered todos/_todo (0.04097) Rendered todos/_todo (0.04097) Rendered todos/_todo (0.04176) Rendered todos/_todo (0.04246) Rendered todos/_todo (0.04277) Rendered todos/_todo (0.04145) Rendered todos/_todo (0.20716) Rendered todos/_todo (0.04731) Rendered todos/_todo (0.04360) Rendered todos/_todo (0.04384) Rendered todos/_todo (0.04243) Rendered todos/_todo (0.04398) Rendered todos/_todo (0.04285) Rendered contexts/_context (0.80283) Rendered todos/_todo (0.04100) Rendered todos/_todo (0.04235) Rendered todos/_todo (0.04168) Rendered todos/_todo (0.04742) Rendered todos/_toggle_notes (0.02100) Rendered todos/_todo (0.06922) Rendered contexts/_context (0.26472) Rendered contexts/_context (0.01828) Rendered todos/_toggle_notes (0.01989) Rendered todos/_todo (0.04487) Rendered todos/_todo (0.02457) Rendered todos/_todo (0.18734) Rendered todos/_todo (0.02741) Rendered todos/_todo (0.02664) Rendered todos/_completed (0.32564) Rendered shared/_add_new_item_form (0.02341) Rendered sidebar/_project (0.00944) Rendered sidebar/_project (0.00129) Rendered sidebar/_project (0.00125) Rendered sidebar/_project (0.00122) Rendered sidebar/_project (0.00128) Rendered sidebar/_project (0.00131) Rendered sidebar/_project (0.00126) Rendered sidebar/_project (0.00120) Rendered sidebar/_project (0.00121) Rendered sidebar/_project (0.00121) Rendered sidebar/_project (0.00124) Rendered sidebar/_project (0.00131) Rendered sidebar/_project_list (0.04197) Rendered sidebar/_context (0.00934) Rendered sidebar/_context (0.00183) Rendered sidebar/_context (0.00135) Rendered sidebar/_context (0.00184) Rendered sidebar/_context (0.00152) Rendered sidebar/_context (0.00125) Rendered sidebar/_context (0.00198) Rendered sidebar/_context (0.00128) Rendered sidebar/_context (0.00130) Rendered sidebar/_context_list (0.04002) Rendered shared/_flash (0.00903) Rendered shared/_footer (0.00866) Completed in 5.66548 (0 reqs/sec) | Rendering: 2.83032 (49%) | DB: 0.51922 (9%) | 200 OK http://hajee004s/
Processing UnobtrusiveJavascriptController#generate? (for 10.0.0.156 at 2007-07-30 22:43:44) [GET]
Session ID: 055722f63fe444e76e91c24f5c92e09b Parameters: {"page_path"=>["index.js"], "action"=>"generate", "controller"=>"unobtrusive_javascript"} Completed in 0.00646 (154 reqs/sec) | Rendering: 0.00018 (2%) | DB: 0.00000 (0%) | 200 OK http://hajee004s/behaviours/index.js
Change History
07/31/07 02:10:57: Modified by lukemelia
07/31/07 11:20:17: Modified by bsag
- status changed from new to assigned.
You also seem to be running in Development mode, which is very slow with tagging. Try running in production:
script/server -e production
and see it if improves.
03/13/08 20:35:45: Modified by lanwin
- priority changed from normal to high.
This happens for me too. Ive upgraded today from 1 to 1.5rc1 version. I am running tracks inside Lighttpd in production mode. But "script/server -e production" seems to be slow to.
Tracks is slow on all sites with a lot if items. This happends at most an Home page but on context sites with a lot of itmes to.
03/18/08 19:26:15: Modified by jkebinger
I looked into this a bit today and I don't think there are any real low hanging fruit.
I put together a "torture test" with 1000 todos averaging 3 tags each spread over 100 contexts and 200 projects, the homepage definitely takes some time to render. With a freshly analyzed db (postgres) I get around 26 seconds on a 1.8Ghz macbook
Completed in 26.23109 (0 reqs/sec) | Rendering: 23.08664 (88%) | DB: 0.33078 (1%)
The good news is the db fraction is really small. The bad news is that would be the easiest part to tweak!
I have a hunch that it's probably time to investigate fragment caching parts of the homepage.
03/18/08 20:59:40: Modified by lrbalt
I think that a big part of the problem is that the todo_controller is loading all data. For me, the biggest queries are one line 414 and 417 (init_todos)
@todos = Todo.find(:all, :conditions => ['todos.user_id = ? and todos.state = ? or todos.state = ?', current_user.id, 'active', 'completed'], :include => [ :project, :context, :tags ]) @not_done_todos = Todo.find(:all, :conditions => ['todos.user_id = ? and todos.state = ? AND contexts.hide = ? AND (projects.state = ? OR todos.project_id IS NULL)', current_user.id, 'active', false, 'active'], :order => "todos.due IS NULL, todos.due ASC, todos.created_at ASC", :include => [ :project, :context, :tags ])
These queries bring in almost all of your database if you look at the resulting SQL
Todo Load Including Associations (6.829000) SELECT todos.`id` AS t0_r0, todos.`context_id` AS t0_r1, todos.`project_id` AS t0_r2, todos.`description` AS t0_r3, todos.`notes` AS t0_r4, todos.`created_at` AS t0_r5, todos.`due` AS t0_r6, todos.`completed_at` AS t0_r7, todos.`user_id` AS t0_r8, todos.`show_from` AS t0_r9, todos.`state` AS t0_r10, projects.`id` AS t1_r0, projects.`name` AS t1_r1, projects.`position` AS t1_r2, projects.`user_id` AS t1_r3, projects.`description` AS t1_r4, projects.`state` AS t1_r5, projects.`created_at` AS t1_r6, projects.`updated_at` AS t1_r7, projects.`default_context_id` AS t1_r8, projects.`completed_at` AS t1_r9, contexts.`id` AS t2_r0, contexts.`name` AS t2_r1, contexts.`position` AS t2_r2, contexts.`hide` AS t2_r3, contexts.`user_id` AS t2_r4, contexts.`created_at` AS t2_r5, contexts.`updated_at` AS t2_r6, tags.`id` AS t3_r0, tags.`name` AS t3_r1, tags.`created_at` AS t3_r2, tags.`updated_at` AS t3_r3 FROM todos LEFT OUTER JOIN projects ON projects.id = todos.project_id LEFT OUTER JOIN contexts ON contexts.id = todos.context_id LEFT OUTER JOIN taggings ON (todos.`id` = taggings.`taggable_id` AND taggings.`taggable_type` = 'Todo') LEFT OUTER JOIN tags ON (tags.`id` = taggings.`tag_id`) WHERE (todos.user_id = 2 and todos.state = 'active' or todos.state = 'completed')
and
SELECT todos.`id` AS t0_r0, todos.`context_id` AS t0_r1, todos.`project_id` AS t0_r2, todos.`description` AS t0_r3, todos.`notes` AS t0_r4, todos.`created_at` AS t0_r5, todos.`due` AS t0_r6, todos.`completed_at` AS t0_r7, todos.`user_id` AS t0_r8, todos.`show_from` AS t0_r9, todos.`state` AS t0_r10, projects.`id` AS t1_r0, projects.`name` AS t1_r1, projects.`position` AS t1_r2, projects.`user_id` AS t1_r3, projects.`description` AS t1_r4, projects.`state` AS t1_r5, projects.`created_at` AS t1_r6, projects.`updated_at` AS t1_r7, projects.`default_context_id` AS t1_r8, projects.`completed_at` AS t1_r9, contexts.`id` AS t2_r0, contexts.`name` AS t2_r1, contexts.`position` AS t2_r2, contexts.`hide` AS t2_r3, contexts.`user_id` AS t2_r4, contexts.`created_at` AS t2_r5, contexts.`updated_at` AS t2_r6, tags.`id` AS t3_r0, tags.`name` AS t3_r1, tags.`created_at` AS t3_r2, tags.`updated_at` AS t3_r3 FROM todos LEFT OUTER JOIN projects ON projects.id = todos.project_id LEFT OUTER JOIN contexts ON contexts.id = todos.context_id LEFT OUTER JOIN taggings ON (todos.`id` = taggings.`taggable_id` AND taggings.`taggable_type` = 'Todo') LEFT OUTER JOIN tags ON (tags.`id` = taggings.`tag_id`) WHERE (todos.user_id = 2 and todos.state = 'active' AND contexts.hide = 0 AND (projects.state = 'active' OR todos.project_id IS NULL)) ORDER BY todos.due IS NULL, todos.due ASC, todos.created_at ASC
running the first query in mysql query browser returns in my case 3615 records in 7.6 seconds (including network). This means that ALL completed actions are downloaded
Perhaps we can remove the first query completely?
03/18/08 21:14:19: Modified by jkebinger
The two queries are a bit redundant, but in my experience they don't take nearly as long as they do for you. I just ran the first one in pgadmin and it returns 3057 records in about 350 ms the first time, and down to 150ms after running repeatedly. So it would appear that removing one of them wouldn't be a huge win. I'm curious why it takes so long on mysql for you.
Do you have up to date table statistics? Earlier today when I first looked into the performance of the home page the queries took about 14 seconds each, but when I ran analyze, the query plan changed completely and ran much,much faster.
BTW what's the syntax to create those text areas you included your query results in?
03/18/08 21:20:55: Modified by lrbalt
Ive committed [749] which removes the downloading of completed todos in the first query mentioned above. All tests including selenium pass, but please test
I get a nice 37% increase in performance (27 sec to 17 sec)
I have a slow network connection from my laptop to my mysql server. This causes the long query times.
See http://dev.rousette.org.uk/wiki/WikiFormatting#PreformattedText for the text areas
03/18/08 21:45:06: Modified by lrbalt
I've updated my copy of tracks I use daily. It is running -e production and mysql is running locally. In my production.log: before [749] 16.9 sec. and after [749] 8.5 sec. So this gives 50%
Perhaps the overhead of parsing the large result is part of this? When using mysql query browser on my server with local mysql takes even 20 sec. It looks cpu bound. I think this is because of mysql query browser parsing the result and filling the gui with the data. Perhaps the rails overhead is logged in the category database?
03/18/08 22:43:45: Modified by lrbalt
I've removed the loading of todos for projects and contexts completely. All tests pass. The time is now reduced to 2.9 sec, so 83% better results
I still think that todos_controller.rb / home page needs refactoring though.
03/18/08 23:39:56: Modified by jkebinger
Please restore the eager load of :default_context on line 13 of todos_controller - I added that just today and it is being used to prevent individual context loads. See ticket 677.
While I applaud any changes that reduce needless data transmission and I like the results they give you, on my machine the rendering still dominates the time:
Completed in 24.94033 (0 reqs/sec) | Rendering: 22.31225 (89%) | DB: 0.39291 (1%) |
03/19/08 07:57:32: Modified by lrbalt
sorry about that :-) Restored in [751].
My stats are now
Completed in 2.97233 (0 reqs/sec) | Rendering: 2.26206 (76%) | DB: 0.37999 (12%)
03/28/08 09:18:05: Modified by lrbalt
- milestone changed from 1.5 to 2.0.
This is likely due to the tagging feature.