Defect #23275

Issue open takes too much time when member blongs many projects

Added by Wadim Incognito about 6 years ago. Updated about 5 years ago.

Status:NewStart date:
Priority:NormalDue date:
Assignee:-% Done:

0%

Category:Performance
Target version:-
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.

History

#1 Updated by Toshi MARUYAMA about 6 years ago

  • Category changed from Issues to Performance

#2 Updated by Toshi MARUYAMA about 6 years ago

  • Status changed from New to Needs feedback

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

#3 Updated by Wadim Incognito about 6 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.

#4 Updated by Toshi MARUYAMA about 6 years ago

Do you use plugins?

#5 Updated by Wadim Incognito about 6 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

#6 Updated by Toshi MARUYAMA about 6 years ago

  • Status changed from Needs feedback to New

#7 Updated by Jean-Philippe Lang about 6 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.

#8 Updated by Wadim Incognito about 6 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)

#9 Updated by Toshi MARUYAMA about 6 years ago

  • Subject changed from Issue open takes too much time. to Issue open takes too much time when member blongs many projects

#10 Updated by Wadim Incognito almost 6 years ago

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

#11 Updated by Stephane Evr almost 6 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!

#12 Updated by Wadim Incognito almost 6 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.

#13 Updated by Wadim Incognito over 5 years ago

Hi !!
Any progress ?
May I help you ?

#14 Updated by Matthew Paul about 5 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

#15 Updated by Wadim Incognito about 5 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.

Also available in: Atom PDF