#1453
- Created on2014-03-03 00:55
- Reported by
- StatusMigrated
- PriorityNormal (3)
- Assigned to
- Milestone
- Plan Level-
- Due Date-
Insanely slow update
I have a single todo item that many other todos depend on. Let's call it X.
In numbers, there are 42 tasks depending on X. Now, while this is slightly unusual, it should not cause problems.
However, I often experience long delays when I update a todo that somehow is connected to X. Changing the project of a single todo which depends on X from project A to project B just took 67 seconds according to the log file: "Completed 200 OK in 67441ms (Views: 66598.7ms | ActiveRecord: 526.7ms)". My server is not very fast, but changing the project from some todo not related to X just takes 0.3 seconds.
In the past I also observed single updates that took about half an hour.
In the log file for the fast change I see this:
Processing by RecurringTodosController#update as JS
Parameters: (something)
Rendered recurring_todos/_recurring_todo.html.erb (25.1ms)
Rendered recurring_todos/update.js.erb (42.3ms)
Completed 200 OK in 297ms (Views: 54.8ms | ActiveRecord: 131.8ms)
For the slow change I see:
Processing by TodosController#update as JS
Parameters: (something)
Read fragment views/todos/3148-20140302144709/20140302/project/true/f6b1f1676905500ed5685760722d24b6 (19.3ms)
Write fragment views/todos/3148-20140302144709/20140302/project/true/f6b1f1676905500ed5685760722d24b6 (6.1ms)
Rendered todos/_todo.html.erb (177.0ms)
Read fragment views/todos/2502-20140302104308/20140302/project/true/f6b1f1676905500ed5685760722d24b6 (23.2ms)
Rendered todos/_successor.html.erb (24.6ms)
Rendered todos/_successor.html.erb (17.4ms)
Rendered todos/_successor.html.erb (17.2ms)
Rendered todos/_successor.html.erb (17.6ms)
Rendered todos/_successor.html.erb (18.1ms)
Rendered todos/_successor.html.erb (47.0ms)
Rendered todos/_successor.html.erb (139.2ms)
Rendered todos/_successor.html.erb (17.3ms)
Rendered todos Rendered todos/update.js.erb (67003.5ms)
[...]
Completed 200 OK in 67441ms (Views: 66598.7ms | ActiveRecord: 526.7ms)
In the part marked with [...] I see 2673 lines showing "Read fragment views/todos/somethingA/somethingB/project/true/somethingC" where somethingB and somethingC are fixed values.
I also see 2674 lines of "Rendered todos/_todo.html.erb". In between I have 33 lines of "Write fragment views/todos/somethingA/somethingB/project/true/somethingC", again with somethingB and somethingC being fixed.
Finally, there also are another six lines "Rendered todos/_successor.html.erb".
The problem can easily be reproduced, so feel free to ask me for further information if necessary.
In numbers, there are 42 tasks depending on X. Now, while this is slightly unusual, it should not cause problems.
However, I often experience long delays when I update a todo that somehow is connected to X. Changing the project of a single todo which depends on X from project A to project B just took 67 seconds according to the log file: "Completed 200 OK in 67441ms (Views: 66598.7ms | ActiveRecord: 526.7ms)". My server is not very fast, but changing the project from some todo not related to X just takes 0.3 seconds.
In the past I also observed single updates that took about half an hour.
In the log file for the fast change I see this:
Processing by RecurringTodosController#update as JS
Parameters: (something)
Rendered recurring_todos/_recurring_todo.html.erb (25.1ms)
Rendered recurring_todos/update.js.erb (42.3ms)
Completed 200 OK in 297ms (Views: 54.8ms | ActiveRecord: 131.8ms)
For the slow change I see:
Processing by TodosController#update as JS
Parameters: (something)
Read fragment views/todos/3148-20140302144709/20140302/project/true/f6b1f1676905500ed5685760722d24b6 (19.3ms)
Write fragment views/todos/3148-20140302144709/20140302/project/true/f6b1f1676905500ed5685760722d24b6 (6.1ms)
Rendered todos/_todo.html.erb (177.0ms)
Read fragment views/todos/2502-20140302104308/20140302/project/true/f6b1f1676905500ed5685760722d24b6 (23.2ms)
Rendered todos/_successor.html.erb (24.6ms)
Rendered todos/_successor.html.erb (17.4ms)
Rendered todos/_successor.html.erb (17.2ms)
Rendered todos/_successor.html.erb (17.6ms)
Rendered todos/_successor.html.erb (18.1ms)
Rendered todos/_successor.html.erb (47.0ms)
Rendered todos/_successor.html.erb (139.2ms)
Rendered todos/_successor.html.erb (17.3ms)
Rendered todos Rendered todos/update.js.erb (67003.5ms)
[...]
Completed 200 OK in 67441ms (Views: 66598.7ms | ActiveRecord: 526.7ms)
In the part marked with [...] I see 2673 lines showing "Read fragment views/todos/somethingA/somethingB/project/true/somethingC" where somethingB and somethingC are fixed values.
I also see 2674 lines of "Rendered todos/_todo.html.erb". In between I have 33 lines of "Write fragment views/todos/somethingA/somethingB/project/true/somethingC", again with somethingB and somethingC being fixed.
Finally, there also are another six lines "Rendered todos/_successor.html.erb".
The problem can easily be reproduced, so feel free to ask me for further information if necessary.
Leave a comment
on 2014-03-03 01:02 *
By carsten.otto
Sorry, the log file copy-paste was slightly wrong.
The line "Rendered todos/update.js.erb (67003.5ms)" appears directly before "Completed 200 OK". The fragment "Rendered todos" (without anything behind that) does not appear in the log file at all, this was a copy-paste-mistake.
The line "Rendered todos/update.js.erb (67003.5ms)" appears directly before "Completed 200 OK". The fragment "Rendered todos" (without anything behind that) does not appear in the log file at all, this was a copy-paste-mistake.
A todo with multiple dependencies has always been troublesome :-)
If you “touch” a todo or one of its dependencies, all todos are marked touched. This causes the cached rendered partials to be invalidated. You can see this happening in the log Carsten attached. Since all todos are touched, also the todos in de “deferred/pending” container are rerendered. So one todo with 42 dependend todos wil regenerate 42+1=43 times a _todo.html.erb. The _successor.html.erb is the partial that is shown when you open the triangle. So if all 42 are directly dependent on the one root-todo (aka procastination), it will render 42 _successor.html.erb. Things will get more complex when the 42 dependend todos form a deep tree. That would mean various _successors being rendered on _todo partials in the deferred/pending container
What I don’t understand is why a todo with 42 dependend todos causes 2673 renderings. Do you have that many todos on your page? Reading a fragment is retrieving the cached partial without rendering it, so for 2673 todos that is expected behavior
The 33 writes are newly / updated rendered partials that are written to disk.
If you “touch” a todo or one of its dependencies, all todos are marked touched. This causes the cached rendered partials to be invalidated. You can see this happening in the log Carsten attached. Since all todos are touched, also the todos in de “deferred/pending” container are rerendered. So one todo with 42 dependend todos wil regenerate 42+1=43 times a _todo.html.erb. The _successor.html.erb is the partial that is shown when you open the triangle. So if all 42 are directly dependent on the one root-todo (aka procastination), it will render 42 _successor.html.erb. Things will get more complex when the 42 dependend todos form a deep tree. That would mean various _successors being rendered on _todo partials in the deferred/pending container
What I don’t understand is why a todo with 42 dependend todos causes 2673 renderings. Do you have that many todos on your page? Reading a fragment is retrieving the cached partial without rendering it, so for 2673 todos that is expected behavior
The 33 writes are newly / updated rendered partials that are written to disk.
on 2014-03-03 17:12 *
By carsten.otto
Matt, it was exactly 42. Right now it is 40, but it still is slow.
Reiner, it's not procrastination, but writing a PhD thesis. Sadly, this task is not as easy to accomplish :) I'm getting there, though.
As for your understanding issue: I don't really know. The page shows at most 20 items, I'd say. But if it is important, some of the todos leading to "X" (which is completing the whole thesis) represent chapters, most of which also have a large number of incoming/outgoing dependencies. However, in the updated mentioned in the bug report, those todos were not touched directly.
Reiner, it's not procrastination, but writing a PhD thesis. Sadly, this task is not as easy to accomplish :) I'm getting there, though.
As for your understanding issue: I don't really know. The page shows at most 20 items, I'd say. But if it is important, some of the todos leading to "X" (which is completing the whole thesis) represent chapters, most of which also have a large number of incoming/outgoing dependencies. However, in the updated mentioned in the bug report, those todos were not touched directly.
I'm curious how you use dependencies. Is the root-todo "write PhD thesis" with "sub-todos" for "write chapter 1" and "write chapter 2" with sub-todos for "read paper A for chapter 1"?
In GTD terms, you should consider defining fine-grained projects for large todos :-)
The way you define your dependecy tree could be helpfull to find out where the big numbers come from. Since you only have 20 items, why are there 2673 renderings?
In GTD terms, you should consider defining fine-grained projects for large todos :-)
The way you define your dependecy tree could be helpfull to find out where the big numbers come from. Since you only have 20 items, why are there 2673 renderings?
on 2014-03-04 14:05 *
By carsten.otto
Attachment dependencies.txt added
Attachment dependencies.txt added
file:dJeh0eO88r44oFacwqjQYw
dump of dependencies table
dump of dependencies table
on 2014-03-04 14:09 *
By carsten.otto
I added a dump of the dependencies table, I hope that helps. The task "X" has ID 2502.
On the organization of my todos: Organization of my thesis actually is rather nice (I think), with several projects for chapters (or parts of chapters!). However, there is a lot of stuff that I only want to start after I hand in my thesis (for example, reorganizing Track's state model of todos, as I mentioned in some mail or bug report). So while there are some todos I still need to do in order to hand in my thesis, there also is a pile of todos that I'd like to do only afterwards. I think this is a rather natural use of dependencies (where I'd love to model dependencies also based on projects, not only todos, as mentioned earlier).
On the organization of my todos: Organization of my thesis actually is rather nice (I think), with several projects for chapters (or parts of chapters!). However, there is a lot of stuff that I only want to start after I hand in my thesis (for example, reorganizing Track's state model of todos, as I mentioned in some mail or bug report). So while there are some todos I still need to do in order to hand in my thesis, there also is a pile of todos that I'd like to do only afterwards. I think this is a rather natural use of dependencies (where I'd love to model dependencies also based on projects, not only todos, as mentioned earlier).
on 2014-03-04 14:10 *
By carsten.otto
Another thing, with 20 items I meant what I see on the screen in an individual project. However, I did not feel any change in speed depending on how many todos are shown on my screen. From my experience, the connected (invisible) todos may be more relevant.
Migrated to GitHub issue #1453