search

maxrossello / redmine_app_timesheets

A true timesheet plugin using orders, not bound to timelogs over issues
GNU General Public License v2.0
32 stars 10 forks source link

Slow activerecord / database query causing 8-15s timesheet load times #77

Open sammcj opened 8 years ago

sammcj commented 8 years ago

Hi Max, Hope all is well?

We've been having a problem where whenever someone tries to access / update their timesheets the page takes between 8 and 15 seconds to load, needless to say this is making a lot of people... unhappy (heh).

I'm wondering if perhaps it could be an issue like an index that needs to be created etc...?

Here's a sample log from the application side for a query that took 9 seconds:

Processing by IssuesController#show as HTML
  Parameters: {"id"=>"110701"}
  Current user: someuser (id=260)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/_add_row.html.erb (22.7ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/_add_entry.html.erb (57.8ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/_navigation.html.erb (1.8ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/_weekly.html.erb (20.3ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/index.html.erb within layouts/base (135.3ms)
  Rendered plugins/a_common_libs/app/views/hooks/a_common_libs/_html_head.html.erb (1.7ms)
  Rendered plugins/redmine_rouge/app/views/application/_rouge_css.erb (0.3ms)
Completed 200 OK in 8767ms (Views: 159.6ms | ActiveRecord: 2187.5ms)**

If you need I could turn on full database logging (out of hours) and give you the query it's running?

Any help greatly appreciated! 🍻

-Sam.

Extra info:

PostgreSQL: 9.5

Environment:
  Redmine version                3.1.3.stable
  Ruby version                   2.3.0-p0 (2015-12-25) [x86_64-linux]
  Rails version                  4.2.5
  Environment                    production
  Database adapter               PostgreSQL
SCM:
  Subversion                     1.7.14
  Git                            1.8.3.1
  Filesystem                     
Redmine plugins:
  a_common_libs                  2.1.0
  ixa_hacks                      0.0.1
  redmine_agile                  1.3.12
  redmine_app__space             1.0.4
  redmine_app_timesheets         1.5.9
  redmine_checklists             3.1.3
  redmine_contacts               4.0.4
  redmine_contacts_helpdesk      3.0.1
  redmine_custom_css             0.1.6
  redmine_rouge                  0.0.1
  redmine_spent_time_in_issue_description 2.8.0
maxrossello commented 8 years ago

Hello Sam, I guess you are working with lots of data entries? Ok, let's try, but a) I can't make tests on a similar data set, and b) often these delays may be introduced from memory management, garbage collection and the like. I'm not really sure, but the fact that ActiveRecord reports just a fraction of the total time may indicate so. There could surely be optimizations on code for using objects more efficiently, but at a certain point I think the problem arises anyway. You may try to reduce or add RAM memory on the web server machine to see if there's any impact there, before we optimize the db query.

sammcj commented 8 years ago

Hey Max,

Thanks for your reply.

The server has plenty of memory (16GB of DDR3 ECC), it doesn't really use it all to be honest, it's also running off 16 brand new Xeon CPU cores across two physical CPUs, the disks are all SSDs capable of over 500MB/s read and write and over 60,000 random 4k IOP/s read or write.

I think there is quite a large data set although the database itself is tiny - it's only 751 MB with most of that just in the issues and notes_id_seq tables which I don't think should impact the timesheets.

I don't know enough about databases from an application perspective but would it be possible to get activerecord to add an index across the various billing codes that it uses or something like that?

I really wish I knew more about activerecord / databases in general so that I could help and submit a fix to contribute but I don't and am tied up on other tasks.

If you were to be able to spend some time to fix it, I could perhaps swap you some of my time as an experienced *nix systems engineer which @greyman888 will attest to, to help offset your time? Happy to optimise any servers you have that are running sluggish or provide you with a penetration test / security audit in return or something like that?

maxrossello commented 8 years ago

I know you are professional (I follow you on twitter), and thanks for the offer, but I don't think my company will trust to open a VPN to someone else than employees, especially for working on core systems. Unfortunately DBs do need a specific competence which I would also need more. I may try to ask a competent colleague for some advice.

So let's try to identify the offending query and if we can identify a needed index. I will then ask you to do a test over a copy with same data. However, I'll try to do what I can, since I am tied to too many things currently as well

sammcj commented 8 years ago

Totally understand to both comments.

I've enabled long query logging on postgresql just yesterday but I can't see anything relating to timesheets, which makes me wonder if it's several queries being joined by the application or something?

Here's the application logs during loading timesheets while no one else is logged into Redmine (it's 1.30AM here!) and I click timesheets:

Started GET "/apps/timesheets" for 127.0.0.1 at 2016-06-08 01:30:05 +1000
Processing by TimesheetsController#index as HTML
  Current user: samm (id=303)
Starting Timesheets Application
Starting Application Space plugin for Redmine
Starting Timesheets Application
git log error: git exited with non-zero status: 128
Started GET "/login" for 127.0.0.1 at 2016-06-08 01:30:09 +1000
Processing by AccountController#login as HTML
  Current user: anonymous
  Rendered account/login.html.erb within layouts/base (1.7ms)
  Rendered plugins/a_common_libs/app/views/hooks/a_common_libs/_html_head.html.erb (1.9ms)
  Rendered plugins/redmine_rouge/app/views/application/_rouge_css.erb (0.3ms)
Completed 200 OK in 28ms (Views: 18.9ms | ActiveRecord: 3.7ms)
Started GET "/issues.json?project_id=1&priority_id=5" for 127.0.0.1 at 2016-06-08 01:30:11 +1000
Processing by IssuesController#index as JSON
  Parameters: {"project_id"=>"1", "priority_id"=>"5"}
  Current user: samm (id=303)
  Rendered issues/index.api.rsb (16.4ms)
Completed 200 OK in 319ms (Views: 15.0ms | ActiveRecord: 116.4ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/_add_row.html.erb (22.7ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/_add_entry.html.erb (5.5ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/_navigation.html.erb (1.8ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/_weekly.html.erb (158.9ms)
  Rendered plugins/redmine_app_timesheets/app/views/timesheets/index.html.erb within layouts/base (220.8ms)
  Rendered plugins/a_common_libs/app/views/hooks/a_common_libs/_html_head.html.erb (1.8ms)
  Rendered plugins/redmine_rouge/app/views/application/_rouge_css.erb (0.4ms)
Completed 200 OK in 8457ms (Views: 245.6ms | ActiveRecord: 2064.2ms)

There are some really gross long queries though as I said I don't think they're related to the timesheets plugin:

< 2016-06-06 14:35:47.713 AEST >LOG:  duration: 7487.130 ms  execute <unnamed>: SELECT DISTINCT "issues"."created_on", "issues"."id" FROM "issues" INNER JOIN "projects" ON "projects"."id" = "issues"."project_id" WHERE (((projects.status <> 9 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')) AND (((projects.is_public = 't' AND projects.id NOT IN (SELECT project_id FROM members WHERE user_id = 523)) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444)))) OR (projects.id IN (168,33,316,347,326,327,328,331,330,337,342,339,341,340,332,257,366,193,368,325,344,345,343,359,352,194,197,186,239,240,258,255,241,242,253,280,300,369,370,365,364,363,376,377,385,372,358,353,362,281,378,283,282,379,244,346,388,389,391,392,393,394,397,399,401,405,406) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444)))) OR (projects.id IN (326,327,328) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444)))) OR (projects.id IN (326,327,328) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444)))) OR (projects.id IN (327) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444))))))) AND (((subject ILIKE '%Hi%') OR (issues.description ILIKE '%Hi%')) AND ((subject ILIKE '%Kelly.%') OR (issues.description ILIKE '%Kelly.%')) AND ((subject ILIKE '%With%') OR (issues.description ILIKE '%With%')) AND ((subject ILIKE '%one%') OR (issues.description ILIKE '%one%')) AND ((subject ILIKE '%this%') OR (issues.description ILIKE '%this%')))  ORDER BY "issues"."created_on" DESC, "issues"."id" DESC
< 2016-06-06 14:35:53.542 AEST >LOG:  duration: 5746.022 ms  execute a5395: SELECT DISTINCT "issues"."created_on", "issues"."id" FROM "issues" INNER JOIN "projects" ON "projects"."id" = "issues"."project_id" INNER JOIN "journals" ON "journals"."journalized_id" = "issues"."id" AND "journals"."journalized_type" = $1 WHERE (((projects.status <> 9 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')) AND (((projects.is_public = 't' AND projects.id NOT IN (SELECT project_id FROM members WHERE user_id = 523)) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444)))) OR (projects.id IN (168,33,316,347,326,327,328,331,330,337,342,339,341,340,332,257,366,193,368,325,344,345,343,359,352,194,197,186,239,240,258,255,241,242,253,280,300,369,370,365,364,363,376,377,385,372,358,353,362,281,378,283,282,379,244,346,388,389,391,392,393,394,397,399,401,405,406) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444)))) OR (projects.id IN (326,327,328) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444)))) OR (projects.id IN (326,327,328) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444)))) OR (projects.id IN (327) AND ((issues.is_private = 'f' OR issues.author_id = 523 OR issues.assigned_to_id IN (523,422,414,444))))))) AND (journals.private_notes = 'f' OR (1=0)) AND (((journals.notes ILIKE '%Hi%')) AND ((journals.notes ILIKE '%Kelly.%')) AND ((journals.notes ILIKE '%With%')) AND ((journals.notes ILIKE '%one%')) AND ((journals.notes ILIKE '%this%')))  ORDER BY "issues"."created_on" DESC, "issues"."id" DESC
< 2016-06-06 14:35:53.542 AEST >DETAIL:  parameters: $1 = 'Issue'
< 2016-06-06 14:36:01.049 AEST >LOG:  duration: 6420.157 ms  execute a5396: SELECT DISTINCT "contacts"."created_on", "contacts"."id" FROM "contacts" LEFT OUTER JOIN "contacts_projects" ON "contacts_projects"."contact_id" = "contacts"."id" LEFT OUTER JOIN "projects" ON "projects"."id" = "contacts_projects"."project_id" LEFT OUTER JOIN "addresses" ON "addresses"."addressable_id" = "contacts"."id" AND "addresses"."address_type" = $1 AND "addresses"."addressable_type" = $2 LEFT OUTER JOIN "notes" ON "notes"."source_id" = "contacts"."id" AND "notes"."source_type" = $3 WHERE ((projects.id <> -1 ) AND ( (contacts.visibility = 1) OR (projects.id IN (168,231,167,112,30,326,29,401) AND contacts.visibility <> 2)  OR (projects.id IN (326,401,168)  OR (projects.id IN (168,231,167,112,30,326,29,401)  AND (contacts.author_id = 523 OR contacts.assigned_to_id IN (523,422,414,444) ))))) AND (((contacts.first_name ILIKE '%Hi%') OR (contacts.middle_name ILIKE '%Hi%') OR (contacts.last_name ILIKE '%Hi%') OR (contacts.company ILIKE '%Hi%') OR (contacts.email ILIKE '%Hi%') OR (addresses.full_address ILIKE '%Hi%') OR (contacts.background ILIKE '%Hi%') OR (notes.content ILIKE '%Hi%')) AND ((contacts.first_name ILIKE '%Kelly.%') OR (contacts.middle_name ILIKE '%Kelly.%') OR (contacts.last_name ILIKE '%Kelly.%') OR (contacts.company ILIKE '%Kelly.%') OR (contacts.email ILIKE '%Kelly.%') OR (addresses.full_address ILIKE '%Kelly.%') OR (contacts.background ILIKE '%Kelly.%') OR (notes.content ILIKE '%Kelly.%')) AND ((contacts.first_name ILIKE '%With%') OR (contacts.middle_name ILIKE '%With%') OR (contacts.last_name ILIKE '%With%') OR (contacts.company ILIKE '%With%') OR (contacts.email ILIKE '%With%') OR (addresses.full_address ILIKE '%With%') OR (contacts.background ILIKE '%With%') OR (notes.content ILIKE '%With%')) AND ((contacts.first_name ILIKE '%one%') OR (contacts.middle_name ILIKE '%one%') OR (contacts.last_name ILIKE '%one%') OR (contacts.company ILIKE '%one%') OR (contacts.email ILIKE '%one%') OR (addresses.full_address ILIKE '%one%') OR (contacts.background ILIKE '%one%') OR (notes.content ILIKE '%one%')) AND ((contacts.first_name ILIKE '%this%') OR (contacts.middle_name ILIKE '%this%') OR (contacts.last_name ILIKE '%this%') OR (contacts.company ILIKE '%this%') OR (contacts.email ILIKE '%this%') OR (addresses.full_address ILIKE '%this%') OR (contacts.background ILIKE '%this%') OR (notes.content ILIKE '%this%')))  ORDER BY "contacts"."created_on" DESC, "contacts"."id" DESC
< 2016-06-06 14:36:01.049 AEST >DETAIL:  parameters: $1 = 'business', $2 = 'Contact', $3 = 'Contact'
< 2016-06-06 21:22:17.992 AEST >LOG:  duration: 8502.132 ms  statement: COPY public.issues (id, tracker_id, project_id, subject, description, due_date, category_id, status_id, assigned_to_id, priority_id, fixed_version_id, author_id, lock_version, created_on, updated_on, start_date, done_ratio, estimated_hours, parent_id, root_id, lft, rgt, is_private, closed_on) TO stdout;
< 2016-06-06 21:22:29.676 AEST >LOG:  duration: 9091.629 ms  statement: COPY public.journals (id, journalized_id, journalized_type, user_id, notes, created_on, private_notes) TO stdout;
< 2016-06-06 21:22:36.318 AEST >LOG:  duration: 6551.291 ms  statement: COPY public.notes (id, subject, content, source_id, source_type, author_id, created_on, updated_on, type_id) TO stdout;
< 2016-06-06 21:22:56.919 AEST >LOG:  duration: 7518.050 ms  statement: COPY public.issues (id, tracker_id, project_id, subject, description, due_date, category_id, status_id, assigned_to_id, priority_id, fixed_version_id, author_id, lock_version, created_on, updated_on, start_date, done_ratio, estimated_hours, parent_id, root_id, lft, rgt, is_private, closed_on) TO stdout;
< 2016-06-06 21:23:07.000 AEST >LOG:  duration: 7781.755 ms  statement: COPY public.journals (id, journalized_id, journalized_type, user_id, notes, created_on, private_notes) TO stdout;
< 2016-06-06 21:23:13.549 AEST >LOG:  duration: 6400.080 ms  statement: COPY public.notes (id, subject, content, source_id, source_type, author_id, created_on, updated_on, type_id) TO stdout;
< 2016-06-07 14:39:42.281 AEST >LOG:  duration: 5886.276 ms  execute <unnamed>: SELECT DISTINCT "issues"."created_on", "issues"."id" FROM "issues" INNER JOIN "projects" ON "projects"."id" = "issues"."project_id" WHERE (((projects.status <> 9 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')) AND (((projects.is_public = 't' AND projects.id NOT IN (SELECT project_id FROM members WHERE user_id = 503)) AND ((issues.is_private = 'f' OR issues.author_id = 503 OR issues.assigned_to_id IN (503,422,292,414,444)))) OR (projects.id IN (364,365,368,369,167,370,229,194,193,197,325,344,345,343,352,231,125,168,359,186,300,358,362,363,372,376,377,388,239,240,255,241,242,253,280,281,378,283,282,379,244,346,258,353,385,401) AND ((issues.is_private = 'f' OR issues.author_id = 503 OR issues.assigned_to_id IN (503,422,292,414,444)))) OR (projects.id IN (364,365,331,369,370,330,300,358,362,363,372,376,377,257,326,327,328,353,385,332) AND ((issues.is_private = 'f' OR issues.author_id = 503 OR issues.assigned_to_id IN (503,422,292,414,444))))))) AND (((subject ILIKE '%effort%') OR (issues.description ILIKE '%effort%')) AND ((subject ILIKE '%level%') OR (issues.description ILIKE '%level%')) AND ((subject ILIKE '%of%') OR (issues.description ILIKE '%of%')))  ORDER BY "issues"."created_on" DESC, "issues"."id" DESC
< 2016-06-07 14:39:45.159 AEST >LOG:  duration: 5582.490 ms  execute <unnamed>: SELECT DISTINCT "issues"."created_on", "issues"."id" FROM "issues" INNER JOIN "projects" ON "projects"."id" = "issues"."project_id" WHERE (((projects.status <> 9 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')) AND (((projects.is_public = 't' AND projects.id NOT IN (SELECT project_id FROM members WHERE user_id = 503)) AND ((issues.is_private = 'f' OR issues.author_id = 503 OR issues.assigned_to_id IN (503,422,292,414,444)))) OR (projects.id IN (364,365,368,369,167,370,229,194,193,197,325,344,345,343,352,231,125,168,359,186,300,358,362,363,372,376,377,388,239,240,255,241,242,253,280,281,378,283,282,379,244,346,258,353,385,401) AND ((issues.is_private = 'f' OR issues.author_id = 503 OR issues.assigned_to_id IN (503,422,292,414,444)))) OR (projects.id IN (364,365,331,369,370,330,300,358,362,363,372,376,377,257,326,327,328,353,385,332) AND ((issues.is_private = 'f' OR issues.author_id = 503 OR issues.assigned_to_id IN (503,422,292,414,444))))))) AND (((subject ILIKE '%effort%') OR (issues.description ILIKE '%effort%')) AND ((subject ILIKE '%level%') OR (issues.description ILIKE '%level%')) AND ((subject ILIKE '%of%') OR (issues.description ILIKE '%of%')))  ORDER BY "issues"."created_on" DESC, "issues"."id" DESC
< 2016-06-07 15:05:23.541 AEST >LOG:  duration: 5295.930 ms  execute <unnamed>: SELECT DISTINCT "issues"."created_on", "issues"."id" FROM "issues" INNER JOIN "projects" ON "projects"."id" = "issues"."project_id" WHERE (((projects.status <> 9 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')) AND (((projects.is_public = 't' AND projects.id NOT IN (SELECT project_id FROM members WHERE user_id = 542)) AND ((issues.is_private = 'f' OR issues.author_id = 542 OR issues.assigned_to_id IN (542,414)))) OR (projects.id IN (29,175,122,119,176,183,321,320,185,184,222,93,217,269,289,373,249,410,126,173,182,189,232,298,294,246,260,116,318,402,303,411,276,348,273,179,210,293,261,312,108,153,384,275,278,279,245,295,228,151,338,297,267,323,322,143,190,412,351,215,361,417,290,121,285,286,409,219,192,265,270,227,250,115,117,204,223,234,268,163,213,225,180,191,230,277,214,272,350,200,299,292,415,349,360,374,404,256,284,329,274,205,196,152,271,307,235,418,357,259,237,291,287,195,314,403,177,252,233,302,317,120,135,174,164,92,30,420,422) AND ((issues.is_private = 'f' OR issues.author_id = 542 OR issues.assigned_to_id IN (542,414)))) OR (projects.id IN (186) AND ((issues.is_private = 'f' OR issues.author_id = 542 OR issues.assigned_to_id IN (542,414))))))) AND (((subject ILIKE '%acn02%') OR (issues.description ILIKE '%acn02%')))  ORDER BY "issues"."created_on" DESC, "issues"."id" DESC
< 2016-06-07 21:22:19.905 AEST >LOG:  duration: 10115.934 ms  statement: COPY public.issues (id, tracker_id, project_id, subject, description, due_date, category_id, status_id, assigned_to_id, priority_id, fixed_version_id, author_id, lock_version, created_on, updated_on, start_date, done_ratio, estimated_hours, parent_id, root_id, lft, rgt, is_private, closed_on) TO stdout;

As you can see below the load and memory really aren't doing much:

bloat

load and memory

relation size

Here is iostat running for a few seconds, then me clicking on timesheets which took about 5 seconds to load, you can see that while the disks are doing a bit, it's not like they're waiting heavily or anything:

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           1.83    0.01    0.32    0.05    0.07   97.72

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     3.09    4.34    3.35   115.33    34.42    38.97     0.04    5.54    2.37    9.64   0.62   0.47
xvda              0.00     5.92    1.17    3.06    14.70    51.27    31.19     0.03    6.48    1.98    8.20   0.95   0.40
dm-0              0.00     0.00    2.53   14.50   127.35    85.65    25.02     0.13    7.78    1.38    8.90   0.43   0.72

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.84    0.00    0.84    0.17    0.17   97.99

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00   18.00    0.00    72.00     0.00     8.00     0.01    0.50    0.50    0.00   0.50   0.90
xvda              0.00     0.00   28.00    0.00    88.00     0.00     6.29     0.02    0.57    0.57    0.00   0.57   1.60
dm-0              0.00     0.00   10.00    0.00    40.00     0.00     8.00     0.01    0.60    0.60    0.00   0.60   0.60

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2.59    0.00    0.08    0.00    0.08   97.25

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          10.35    0.00    0.25    0.00    0.00   89.40

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           8.09    0.00    0.17    0.00    0.17   91.58

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           8.25    0.00    0.25    0.00    0.08   91.42

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     4.00    0.00   17.00     0.00    84.00     9.88     0.05    3.06    0.00    3.06   0.24   0.40
xvda              0.00    14.00    0.00   17.00     0.00   120.00    14.12     0.03    1.94    0.00    1.94   0.24   0.40
dm-0              0.00     0.00    0.00   50.00     0.00   204.00     8.16     0.13    2.52    0.00    2.52   0.10   0.50

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           8.10    0.00    0.17    0.00    0.08   91.65

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           8.26    0.00    0.33    0.00    0.08   91.33

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          21.40    0.00    3.93    0.00    0.17   74.50

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvda              0.00     0.00    0.00    1.00     0.00     4.00     8.00     0.00    1.00    0.00    1.00   1.00   0.10
dm-0              0.00     0.00    0.00    1.00     0.00     4.00     8.00     0.00    1.00    0.00    1.00   1.00   0.10

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          21.80    0.00    3.34    0.00    0.08   74.77

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          14.86    0.00    1.75    0.08    0.08   83.22

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00   56.00     0.00   340.00    12.14     0.16    2.82    0.00    2.82   0.11   0.60
xvda              0.00     1.00    0.00    1.00     0.00    16.00    32.00     0.00    1.00    0.00    1.00   1.00   0.10
dm-0              0.00     0.00    0.00   58.00     0.00   356.00    12.28     0.17    2.84    0.00    2.84   0.10   0.60

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          14.31    0.00    2.43    0.00    0.00   83.26

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvdb              0.00     0.00    0.00    1.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvda              0.00    27.00    0.00    5.00     0.00   124.00    49.60     0.00    0.60    0.00    0.60   0.20   0.10
dm-0              0.00     0.00    0.00   31.00     0.00   124.00     8.00     0.03    0.97    0.00    0.97   0.03   0.10

Off to bed now, long day - I'll reply tomorrow if you spot anything, but I don't expect anything of you - I know how busy we all get and this is an open source project after all :)

maxrossello commented 8 years ago

Hi Sam, the query is relevant because ruby can override methods and my plugin is just one of the many to extend some core functionality. I think the problem is in iterative management to verify the :view_time_entries permission in overridden Project::allowed_to_condition method. Having several projects with order management, this makes the query linearly grow.

lib/timesheets_app_project_patch.rb

        Project.find(Setting.plugin_redmine_app_timesheets['project'].to_i).versions.each do |version|
          perm = TsPermission.over(version).for_user(user).first
          own_orders << version.id if perm.present? and perm.access >= TsPermission::NONE
          orders << version.id if perm.present? and perm.access >= TsPermission::VIEW
        end

This could be partially confirmed if you login with the admin user which would skip the permissions check, and you don't see the same delay.

If this is the case, I should take the time to understand how to improve this part without harming the functionality.