Project

General

Profile

Actions
Copy link

Defect #23275

open

Issue open takes too much time when member blongs many projects

Added by Wadim Incognito over 8 years ago. Updated over 7 years ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
Performance
Target version:
-
Start date:
Due date:
% Done:

0%

Estimated time:
Resolution:
Affected version:
3.2.1

Description

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.

Actions
Copy link
 #1

Updated by Toshi MARUYAMA over 8 years ago

  • Category changed from Issues to Performance
Actions
Copy link
 #2

Updated by Toshi MARUYAMA over 8 years ago

  • Status changed from New to Needs feedback

Please give us your information, ref: submissions and #11904.

Actions
Copy link
 #3

Updated by Wadim Incognito over 8 years ago

Hi !

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

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.

Actions
Copy link
 #4

Updated by Toshi MARUYAMA over 8 years ago

Do you use plugins?

Actions
Copy link
 #5

Updated by Wadim Incognito over 8 years ago

Yes, but it's doesn't matter - because without plugins behaviour is the same
Here is list of plugins:

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

Actions
Copy link
 #6

Updated by Toshi MARUYAMA over 8 years ago

  • Status changed from Needs feedback to New
Actions
Copy link
 #7

Updated by Jean-Philippe Lang over 8 years ago

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.

Actions
Copy link
 #8

Updated by Wadim Incognito over 8 years ago

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:

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)

Now, I'm a member of 79 projects. Issue opens for 3 seconds. Log follows:

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)

Actions
Copy link
 #9

Updated by Toshi MARUYAMA over 8 years ago

  • Subject changed from Issue open takes too much time. to Issue open takes too much time when member blongs many projects
Actions
Copy link
 #10

Updated by Wadim Incognito almost 8 years ago

Hi !
Any progress, plans, or anyting else ?
Can I help you in resolving this issue ?

Actions
Copy link
 #11

Updated by Stephane Evr almost 8 years ago

It seems that 50% of your performance problems are coming from this plugin "unread_issues":

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)

3176 ms spent in IssueReadsController#count alone!

Actions
Copy link
 #12

Updated by Wadim Incognito almost 8 years ago

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.

Actions
Copy link
 #13

Updated by Wadim Incognito almost 8 years ago

Hi !!
Any progress ?
May I help you ?

Actions
Copy link
 #14

Updated by Matthew Paul over 7 years ago

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

Actions
Copy link
 #15

Updated by Wadim Incognito over 7 years ago

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.

Actions
Copy link

Also available in: Atom PDF