Vote #77613
未完了Issue open takes too much time when member blongs many projects
0%
説明
When user is a member of many open projects (about 3000), each issue takes about 7 seconds to open. When user is a member of several projects (about 10-20), each issue takes about 3 seconds to open.
Top indicates, that most of time taken by "ruby" process, so it's not a database issue.
journals
--------------------------------------------------------------------------------
Please give us your information, ref: [[submissions]] and #11904.
--------------------------------------------------------------------------------
Hi !
<pre>
Environment:
Redmine version 3.2.1.stable
Ruby version 2.1.2-p95 (2014-05-08) [x86_64-linux]
Rails version 4.2.5.2
Environment production
Database adapter Mysql2
SCM:
Subversion 1.6.11
Git 1.7.1
Filesystem
</pre>
About #11904 - it's different. In my case - there is a single user which is a member of many projects, not a lot of users in single project.
--------------------------------------------------------------------------------
Do you use plugins?
--------------------------------------------------------------------------------
Yes, but it's doesn't matter - because without plugins behaviour is the same
Here is list of plugins:
<pre>
Redmine plugins:
a_common_libs 2.1.5
ajax_counters 1.4.0
clear_plan 2.1.9
easy_gantt 1.2
global_roles 2.1.0
luxury_buttons 3.6.8
redmine_favorite_projects 2.0.2
redmine_issue_tabs 1.1.1
redmine_my_page 0.1.9
unread_issues 2.0.0
usability 2.0.0
</pre>
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
How many projects do you have in your database? Could you also give the application log for displaying an issue. It gives usefull information about rendering times.
--------------------------------------------------------------------------------
Hi !
In our database - there is 3928 projects, 3208 is active.
I am a member of 3199 projects.
Opening an issue takes about 6 seconds. Log follows:
<pre>
Started GET "/issues/58028" for 192.168.21.190 at 2016-07-13 12:03:35 +0300
Processing by IssuesController#show as HTML
Parameters: {"id"=>"58028"}
Current user: Surkov.V (id=419)
Rendered issues/_action_menu.html.erb (38.5ms)
Rendered plugins/clear_plan/app/views/clear_plan/hooks/_issue_bottom_details.html.erb (0.4ms)
Rendered plugins/redmine_issue_tabs/app/views/redmine_issue_tabs/_blank.html.erb (0.0ms)
Rendered plugins/redmine_issue_tabs/app/views/redmine_issue_tabs/_blank.html.erb (0.0ms)
Rendered plugins/redmine_issue_tabs/app/views/redmine_issue_tabs/_blank.html.erb (0.0ms)
Rendered plugins/redmine_issue_tabs/app/views/redmine_issue_tabs/_timelog.html.erb (0.7ms)
Rendered common/_tabs.html.erb (2.0ms)
Rendered plugins/redmine_issue_tabs/app/views/hooks/redmine_issue_tabs/_rm_history_tabs.html.erb (2.5ms)
Rendered plugins/unread_issues/app/views/hooks/unread_isues/_issue_bottom_details.html.erb (0.2ms)
Rendered plugins/luxury_buttons/app/views/hooks/lu_buttons/_button_bar.html.erb (0.3ms)
Rendered issue_relations/_form.html.erb (1.1ms)
Rendered issues/_relations.html.erb (1.7ms)
Rendered plugins/luxury_buttons/app/views/issues/_relations.html.erb (2.0ms)
Rendered issues/_action_menu.html.erb (1.9ms)
Rendered plugins/luxury_buttons/app/views/hooks/lu_buttons/_view_issues_form_details_top.html.erb (0.0ms)
Rendered issues/_form_custom_fields.html.erb (31.1ms)
Rendered issues/_attributes.html.erb (46.5ms)
Rendered issues/_form.html.erb (441.6ms)
Rendered attachments/_form.html.erb (1.3ms)
Rendered issues/_edit.html.erb (450.1ms)
Rendered issues/_sidebar.html.erb (3.8ms)
Rendered watchers/_watchers.html.erb (2.0ms)
Rendered plugins/luxury_buttons/app/views/watchers/_watchers.html.erb (2.5ms)
Rendered issues/show.html.erb (552.2ms)
Rendered plugins/luxury_buttons/app/views/issues/show.html.erb within layouts/base (553.3ms)
Rendered plugins/a_common_libs/app/views/hooks/a_common_libs/_html_head.html.erb (1.2ms)
Rendered plugins/ajax_counters/app/views/hooks/ajax_counters/_html_head.html.erb (0.2ms)
Rendered plugins/clear_plan/app/views/clear_plan/hooks/_html_head.html.erb (0.2ms)
Rendered plugins/global_roles/app/views/hooks/global_roles/_head.html.erb (0.0ms)
Rendered plugins/luxury_buttons/app/views/hooks/lu_buttons/_page_header.html.erb (1.6ms)
Rendered plugins/unread_issues/app/views/hooks/unread_isues/_add_css.html.erb (0.1ms)
Rendered plugins/usability/app/views/hooks/usability/_html_head.html.erb (0.7ms)
Rendered plugins/global_roles/app/views/hooks/global_roles/_view_layouts_base_body_bottom.html.erb (0.1ms)
Rendered plugins/usability/app/views/hooks/usability/_body_bottom.html.erb (0.1ms)
Completed 200 OK in 2794ms (Views: 2552.9ms | ActiveRecord: 168.0ms)
Started GET "/issue_reads/count/updated?counter_id=87c0bb8d4cc3be31f4dea0e60883eb72&period=0" for 192.168.21.190 at 2016-07-13 12:03:40 +0300
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"87c0bb8d4cc3be31f4dea0e60883eb72", "period"=>"0", "req"=>"updated"}
Current user: Surkov.V (id=419)
Completed 200 OK in 807ms (Views: 0.3ms | ActiveRecord: 25.5ms)
Started GET "/issue_reads/count/unread?counter_id=c4aad251ee5e7ded9635ffe658447e92&period=0" for 192.168.21.190 at 2016-07-13 12:03:41 +0300
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"c4aad251ee5e7ded9635ffe658447e92", "period"=>"0", "req"=>"unread"}
Current user: Surkov.V (id=419)
Completed 200 OK in 1477ms (Views: 0.2ms | ActiveRecord: 23.9ms)
Started GET "/issue_reads/count/assigned?counter_id=e0c20af0ad02031c9b817fab3ea7c6e3&period=0" for 192.168.21.190 at 2016-07-13 12:03:42 +0300
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"e0c20af0ad02031c9b817fab3ea7c6e3", "period"=>"0", "req"=>"assigned"}
Current user: Surkov.V (id=419)
Completed 200 OK in 892ms (Views: 0.2ms | ActiveRecord: 33.8ms)
</pre>
Now, I'm a member of 79 projects. Issue opens for 3 seconds. Log follows:
<pre>
Started GET "/issues/58028" for 192.168.21.190 at 2016-07-13 13:00:02 +0300
Processing by IssuesController#show as HTML
Parameters: {"id"=>"58028"}
Current user: Surkov.V (id=419)
Rendered issues/_action_menu.html.erb (23.5ms)
Rendered plugins/clear_plan/app/views/clear_plan/hooks/_issue_bottom_details.html.erb (0.3ms)
Rendered plugins/redmine_issue_tabs/app/views/redmine_issue_tabs/_blank.html.erb (0.0ms)
Rendered plugins/redmine_issue_tabs/app/views/redmine_issue_tabs/_blank.html.erb (0.0ms)
Rendered plugins/redmine_issue_tabs/app/views/redmine_issue_tabs/_blank.html.erb (0.0ms)
Rendered plugins/redmine_issue_tabs/app/views/redmine_issue_tabs/_timelog.html.erb (0.9ms)
Rendered common/_tabs.html.erb (2.0ms)
Rendered plugins/redmine_issue_tabs/app/views/hooks/redmine_issue_tabs/_rm_history_tabs.html.erb (2.4ms)
Rendered plugins/unread_issues/app/views/hooks/unread_isues/_issue_bottom_details.html.erb (0.2ms)
Rendered plugins/luxury_buttons/app/views/hooks/lu_buttons/_button_bar.html.erb (0.3ms)
Rendered issue_relations/_form.html.erb (0.9ms)
Rendered issues/_relations.html.erb (1.6ms)
Rendered plugins/luxury_buttons/app/views/issues/_relations.html.erb (1.9ms)
Rendered issues/_action_menu.html.erb (1.8ms)
Rendered plugins/luxury_buttons/app/views/hooks/lu_buttons/_view_issues_form_details_top.html.erb (0.1ms)
Rendered issues/_form_custom_fields.html.erb (30.2ms)
Rendered issues/_attributes.html.erb (47.5ms)
Rendered issues/_form.html.erb (374.7ms)
Rendered attachments/_form.html.erb (1.5ms)
Rendered issues/_edit.html.erb (383.3ms)
Rendered issues/_sidebar.html.erb (4.1ms)
Rendered watchers/_watchers.html.erb (2.4ms)
Rendered plugins/luxury_buttons/app/views/watchers/_watchers.html.erb (3.1ms)
Rendered issues/show.html.erb (460.9ms)
Rendered plugins/luxury_buttons/app/views/issues/show.html.erb within layouts/base (461.4ms)
Rendered plugins/a_common_libs/app/views/hooks/a_common_libs/_html_head.html.erb (1.2ms)
Rendered plugins/ajax_counters/app/views/hooks/ajax_counters/_html_head.html.erb (0.2ms)
Rendered plugins/clear_plan/app/views/clear_plan/hooks/_html_head.html.erb (0.2ms)
Rendered plugins/global_roles/app/views/hooks/global_roles/_head.html.erb (0.0ms)
Rendered plugins/luxury_buttons/app/views/hooks/lu_buttons/_page_header.html.erb (1.8ms)
Rendered plugins/unread_issues/app/views/hooks/unread_isues/_add_css.html.erb (0.1ms)
Rendered plugins/usability/app/views/hooks/usability/_html_head.html.erb (0.8ms)
Rendered plugins/global_roles/app/views/hooks/global_roles/_view_layouts_base_body_bottom.html.erb (0.1ms)
Rendered plugins/usability/app/views/hooks/usability/_body_bottom.html.erb (0.1ms)
Completed 200 OK in 1352ms (Views: 1192.9ms | ActiveRecord: 102.1ms)
Started GET "/issue_reads/count/updated?counter_id=87c0bb8d4cc3be31f4dea0e60883eb72&period=0" for 192.168.21.190 at 2016-07-13 13:00:05 +0300
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"87c0bb8d4cc3be31f4dea0e60883eb72", "period"=>"0", "req"=>"updated"}
Current user: Surkov.V (id=419)
Completed 200 OK in 1022ms (Views: 0.3ms | ActiveRecord: 24.0ms)
Started GET "/issue_reads/count/unread?counter_id=c4aad251ee5e7ded9635ffe658447e92&period=0" for 192.168.21.190 at 2016-07-13 13:00:07 +0300
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"c4aad251ee5e7ded9635ffe658447e92", "period"=>"0", "req"=>"unread"}
Current user: Surkov.V (id=419)
Completed 200 OK in 843ms (Views: 0.2ms | ActiveRecord: 27.7ms)
Started GET "/issue_reads/count/assigned?counter_id=e0c20af0ad02031c9b817fab3ea7c6e3&period=0" for 192.168.21.190 at 2016-07-13 13:00:08 +0300
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"e0c20af0ad02031c9b817fab3ea7c6e3", "period"=>"0", "req"=>"assigned"}
Current user: Surkov.V (id=419)
Completed 200 OK in 1258ms (Views: 0.2ms | ActiveRecord: 40.4ms)
</pre>
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
Hi !
Any progress, plans, or anyting else ?
Can I help you in resolving this issue ?
--------------------------------------------------------------------------------
It seems that 50% of your performance problems are coming from this plugin "unread_issues":
<pre>
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"87c0bb8d4cc3be31f4dea0e60883eb72", "period"=>"0", "req"=>"updated"}
Current user: Surkov.V (id=419)
Completed 200 OK in 807ms (Views: 0.3ms | ActiveRecord: 25.5ms)
Started GET "/issue_reads/count/unread?counter_id=c4aad251ee5e7ded9635ffe658447e92&period=0" for 192.168.21.190 at 2016-07-13 12:03:41 +0300
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"c4aad251ee5e7ded9635ffe658447e92", "period"=>"0", "req"=>"unread"}
Current user: Surkov.V (id=419)
Completed 200 OK in 1477ms (Views: 0.2ms | ActiveRecord: 23.9ms)
Started GET "/issue_reads/count/assigned?counter_id=e0c20af0ad02031c9b817fab3ea7c6e3&period=0" for 192.168.21.190 at 2016-07-13 12:03:42 +0300
Processing by IssueReadsController#count as JSON
Parameters: {"counter_id"=>"e0c20af0ad02031c9b817fab3ea7c6e3", "period"=>"0", "req"=>"assigned"}
Current user: Surkov.V (id=419)
Completed 200 OK in 892ms (Views: 0.2ms | ActiveRecord: 33.8ms)
</pre>
3176 ms spent in IssueReadsController#count alone!
--------------------------------------------------------------------------------
You right, but this is not a problem, because as you see, this plugin works in async mode - it don't suspends main page rendering.
--------------------------------------------------------------------------------
Hi !!
Any progress ?
May I help you ?
--------------------------------------------------------------------------------
I dont know if this is still an issue for you, but I wanted to update the ticket here with a solution so it can be closed out. The problem I think you are having is with redmine+ unread_issues.
If you look at that plugin, it creates a table, issue_reads with no indexes. This is a table of who viewed what issues.
So, the solution is to add an index like -
create index index_issue_reads_on_issue_id on issue_reads(issue_id);
That took my updates/views etc down from 30 seconds to around 4
--------------------------------------------------------------------------------
Hi !!
Unfortunately, we always have this index.
And as I've mentioned earlier #23275#note-5 without plugins we have the same behavior.
So no, it's not unread_issues problem - it's in redmine's core.
--------------------------------------------------------------------------------