search

maxrossello / redmine_extended_watchers

Grant additional issue and project view permissions to watcher users
GNU General Public License v3.0
44 stars 20 forks source link

Slowness #6

Closed atopcu closed 4 years ago

atopcu commented 10 years ago

Hi, This plugin function is importand for our redmine instance. However, each click take 2 seconds normally, but this time is 8 seconds when this plugin activated. Is there any way to decrease this time?

Environment: Redmine version 2.3.3.stable Ruby version 1.9.3-p448 (2013-06-27) [x86_64-linux] Rails version 3.2.13 Environment production Database adapter Mysql2 Redmine plugins: author 0.1.0 autowatch 0.1.0 due_date_reminder 0.3.2 extended_fields 0.2.2 periodictask 2.0.0 redmine_assets_plugin 0.0.1 redmine_banner 0.0.9 redmine_category_tree 0.0.3 redmine_changeauthor 1.0.0 redmine_contacts 3.2.5-pro redmine_contacts_helpdesk 2.2.5-pro redmine_dmsf 1.4.6 stable redmine_extended_watchers 0.0.4 redmine_favourite_projects 0.6.3 redmine_gemavatar 1.0.3 redmine_ics_export 2.0.0.dev redmine_information 1.0.2 redmine_inline_attach_screenshot 0.4.6 redmine_inline_note_images_plugin 0.0.1 redmine_issue_checklist 2.0.5 redmine_ldap_sync 2.0.2 redmine_login_audit 0.1.1 redmine_logs 0.0.5 redmine_reorder_links_arbitrary 0.0.7 redmine_stealth 0.6.0 redmine_textilizable_custom_fields 0.0.1 redmine_theme_changer 0.1.0 redmine_wiki_extensions 0.6.4 role_shift 0.1.0b sidebar_hide 0.0.4 under_construction 0.0.1 wiking 0.0.4

Best Regards, Adnan

maxrossello commented 10 years ago

Hi, my sites do not suffer for this evident slowness.

Is there any particular action you are doing or is it a general slowness? Can you report some log after such an activity?

atopcu commented 10 years ago

I was test it. when the remove plugin, issue list take about 2 sec. when reinstall the plugin, this time is back to 8 seconds again. there are 150 open, 1200 closed issues in that project. I'll report some log.

maxrossello commented 10 years ago

I see you are complaining for slowness in smart issue sort plugin too. There is the possibility that the slowness is not due these two plugins, rather from some operation introduced by some third plugin that affects performances of operations used frequently into both extended watchers or smart issue sort.

For example, let's say that both extended watchers and smart issue sort use the issues' "watched_by" scope (just an example), and a third plugin inserts some weighy operation into it through a redefined scope or some method alias. In this case, the responsibility for slowness is into the third plugin.

The test you should do is to remove ALL plugins except the one under test. Then, if things go faster, reintroduce one plugin at a time. If the system is slow even with just one plugin, there is more evidence that performance responsibility is into that plugin.

atopcu commented 10 years ago

Yes. I have problems these both plugins. I was tested them separately. if smart issue sort plugin is A and extended watcher is B; redmine + all other pulugin = ~ 1.5 sec. redmine + all other pulugin +A = ~ 5.5 sec. redmine + all other pulugin +B = ~ 8 sec. redmine + all other pulugin + A + B = ~ 12 sec.

note: extended watcher plugin version was 0.4 in this test. But this version has some other bugs and I don't yer reported them. Because of them, I was switched to version 0.2. 0.2 is fast!

Thanks for attendence.

maxrossello commented 10 years ago

I understand, but version 0.2 MAY not call some service while 0.4 and following may do. IF that service is modified by some other plugin, here comes the difference. So, I'm asking you to try just redmine + A = ?

Also some log may be useful to look at database queries

atopcu commented 10 years ago

Ok. I Will report.

atopcu commented 10 years ago

redmine + A is about 4 sec (3.8).

maxrossello commented 10 years ago

Ok, thank you.

If you can temporarily set

config.logger.level = Logger::INFO

in your config/environments/production.rb, we will be able to look at the most recurrent and inefficient sql queries.

There will be entries like the following (which is my longer query reported in an issue listing):

(186.6ms) SELECT COUNT(DISTINCT issues.id) FROM issues LEFT OUTER JOIN projects ON projects.id = issues.project_id LEFT OUTER JOIN issue_statuses ON issue_statuses.id = issues.status_id WHERE (( projects.status <> 9 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking') OR issues.id IN (441,571,572)) ) AND ((issues.status_id IN (SELECT id FROM issue_statuses WHERE is_closed=0)))

We should compare the queries in redmine or in redmine + A configuration, identifying the ones that mostly add time consumption.

Thank you

atopcu commented 10 years ago

I tried but not successfully. This change of production.rb causes an error. I'm not ruby expert, I don't understand the problem. :(

rake aborted! undefined method level=' for nil:NilClass /opt/bitnami/apps/redmine/htdocs/config/environments/production.rb:16:inblock in <top (required)>'

maxrossello commented 10 years ago

Sorry, it's my fault. Try to add

config.log_path = '<my_log_path>/production.log'
config.logger = Logger.new(config.log_path, 7, 1048576)
config.logger.level = Logger::INFO

Of course the logfile path can be any of your choice

atopcu commented 10 years ago

sorry for delay. I have tried two times. but I can't get the log. I get "Sometings are Wrong" message on Web Interface.

maxrossello commented 10 years ago

Can't help you this way, sorry, this is too generic. Check filesystem permissions and then search the internet for how to get a proper log with Redmine, this is a problem unrelated to the plugin. Once you can provide a log, set it to INFO level as described above, and finally provide details on query timings.

atopcu commented 10 years ago

Dear maxrossello, We use RM 2.5.2 now.

I found logging settings for this version at ./config/additional_environment.rb file:

config.logger = Logger.new('/opt/redmine/current/log/production.log', 2, 1000000) config.logger.level = Logger::DEBUG

I activated DEBUG log. I have reproduce this stuation. but proccess take a long time and this proccess make a big log file. log file was rotated a couple of times, I don't know how many.

I am still using version 0.0.2 of plugin now. It seems to be working. There is only one problem in this version (0.0.2): Search not working on watcher add GUI. We must find watcher with manuel scroll up or scroll down. Number of members close to 200 some project. thus, manuel search is problem for this kind of projects. However, this is not importand case for us. I wanted feedback to you only.

Regards..

maxrossello commented 10 years ago

Search is fixed on latest version of the plugin. I can't mantain older versions.

Ok with log in DEBUG mode. You may just try to use the latest version for just one issue listing and report the last, let's say, 50-100 lines.

How many issues do you list usually?

atopcu commented 10 years ago

most weight project has 250 open, total 2100 issues. Our system has ~15 active project and ~5000 (closed+open) issues for this time.

I will incerase size of log capacity and try to capture it. Regards

maxrossello commented 9 years ago

@atopcu latest merge could have improved performances. May you test with your system? Thanks

atopcu commented 9 years ago

Thank you for notification. Yes, of course! I tested latest master now. Issue list take 9 sec one of our project (1) this time is 3 sec in 0.0.2 release of this plugin in same project

(1) There are 150 users, 9 groups and 225 open issues in this project

Regards.

2014-10-18 17:28 GMT+03:00 maxrossello notifications@github.com:

@atopcu https://github.com/atopcu latest merge could have improved performances. May you test with your system? Thanks

— Reply to this email directly or view it on GitHub https://github.com/maxrossello/redmine_extended_watchers/issues/6#issuecomment-59615811 .

Saygılar, Sevgiler, Adnan Topçu

+++ E-posta adreslerimizin istenmeyen üçüncü şahısların eline geçmemesi için öneri +++

İlginize Şimdiden Teşekkürler...

+++++++++

xaionaro commented 9 years ago

I tested latest master now. Issue list take 9 sec one of our project (1) this time is 3 sec in 0.0.2 release of this plugin in same project

Sorry for my English skills, but I don't see 0.0.2 release in this project on GitHub so I cannot get it. It works faster or slower after commit 7ce319702b820f2e47a80ec3cec47dc777a00bc0? :)

I understand your comment as: Was 3 seconds, became 9 seconds. The total time increased by 6 seconds.

Right?

atopcu commented 9 years ago

I am using 0.0.2 version of this plugin. I don't test previous of commit 7ce3197. Yes, the total time increased by 6 seconds between version 0.0.2 (I don't know commit ID) and commit 7ce3197. Regards.

18 Ekim 2014 Cumartesi tarihinde, Okunev Yu Dmitry notifications@github.com yazdı:

I tested latest master now. Issue list take 9 sec one of our project (1) this time is 3 sec in 0.0.2 release of this plugin in same project

Sorry for my English skills, but I don't see 0.0.2 release in this project on GitHub so I cannot get it. It works faster or slower after commit 7ce3197 https://github.com/maxrossello/redmine_extended_watchers/commit/7ce319702b820f2e47a80ec3cec47dc777a00bc0? :)

I understand your comment as: Was 3 seconds, become 9 seconds. The total time increased by 6 seconds.

Right?

— Reply to this email directly or view it on GitHub https://github.com/maxrossello/redmine_extended_watchers/issues/6#issuecomment-59626540 .

(Mobil cihazdan gönderildi)

xaionaro commented 9 years ago

That is very strange because the commit decreases (or leaves it the same, but not increases) the number of operations in any case. Could you provide the log?

And can you find out the problem patch (which adds the huge delay)? You can try to just comment them one by one in init.rb of the plugin:

Issue.send(:include, ExtendedWatchersIssuePatch)
WatchersController.send(:include, ExtendedWatchersControllerPatch)
User.send(:include, ExtendedWatchersUserPatch)
Project.send(:include, ExtendedWatchersProjectPatch)
ApplicationController.send(:include, ExtendedWatchersApplicationControllerPatch)
maxrossello commented 9 years ago

As I understand, in order to keep higher performances @atopcu uses a very old version of the plugin, which required users to have at least "view own issues" permission in the project in order to have issue visibility through watching. He's not comparing against 1.0.0 which probably lends even worse performances to him.

I assume that performances degraded at https://github.com/maxrossello/redmine_extended_watchers/commit/57fc2e13ba0530d1d893d023a551b98d8a5cf0a7 (version 0.0.3) when I removed the need for that permission. Allegedly, it could be due to the introduction of the 'authorize_with_extwatch' alias in ApplicationController.

@xalonaro, probably we can introduce an optimization similar to yours there too, what you think?

xaionaro commented 9 years ago

@xalonaro, probably we can introduce an optimization similar to yours there too, what you think?

Yeah. I think we should try. However I can't repeat the slowness on my systems (I use redmine 3 [unreleased, yet] and rails 4).

atopcu commented 9 years ago

Maxrossello is right. Performance is more important than latest features for us. Regards.

mpyrev commented 9 years ago

In our company all issues are private. And users, who are added as watchers at almost every issue (i.e. ceo), experience really slow issue opening. We have approximately 10000 issues.

maxrossello commented 9 years ago

@AlefGarden it would be extremely helpful if you could do some profiling as suggested in https://github.com/maxrossello/redmine_extended_watchers/issues/6#issuecomment-59641257

maxrossello commented 9 years ago

Was not possible to introduce a similar trick in authorization due to the logic, yet I embedded some operations in a single query. @atopcu @AlefGarden could you report please?

mpyrev commented 9 years ago

@maxrossello Today we have updated Redmine to latest stable version. And looks like it did the trick — issue loading time decreased dramatically.

maxrossello commented 9 years ago

do you mean you updated Redmine or the plugin?

xaionaro commented 9 years ago

@AlefGarden, seems you got the same problem as it was at my Redmine. :)

mpyrev commented 9 years ago

@maxrossello Redmine was updated to version 2.5.2. @xaionaro I think using watchers like this will be always a big slowdown because (as I understand it from source) watchers storage schema is not ready for that kind of queries.

atopcu commented 9 years ago

I have tested some conditions:

The latest version (1.0.2 master) of this plugin has 5 patch:

a. ExtendedWatchersIssuePatch b. ExtendedWatchersControllerPatch c. ExtendedWatchersUserPatch d. ExtendedWatchersProjectPatch e. ExtendedWatchersApplicationControllerPatch

I was enabled/disabled these patches separately by the editing init.rb and measure the proccess time. proccess is displaying issue list.

scenarios:

  1. plugin not installed: 2.5 sec. (redmine + all other plugins)
  2. 0.0.2 version full installed: +0.5 sec (total 3 sec.)
  3. 1.0.2 with only a patch: +2.5 sec.
  4. 1.0.2 with only b patch: +0 sec.
  5. a & b: +2.5 sec.
  6. a & b & c: +2.5 sec.
  7. a & b & c & d: +4.2 sec.
  8. 1.0.2 version full installed: +4.5 sec (total 7 sec)

times are average of 3-5 samples.

summary: In 1.0.2 version, process times of a & d are longer than others. they are about 2 sec for me.

Regards.

xaionaro commented 9 years ago

@atopcu,

  1. Can you try https://github.com/mephi-ut/redmine_extended_watchers ? If this solves the performance problem with "a" then I think @maxrossello will agree to merge the commit :)
  2. About the "d". IMHO, there should be no delay due to the projects patch while issues indexing. Do you display a project list somewhere on issues index page?

UPD: Sorry for the typo. Fixed: "there should be no delay due to" (as above).

maxrossello commented 9 years ago

I think that following your trick, the "a" case can be further iper-simplified. I'm going to release a new patch which sounds reducing delay to 1/4 even with few issues

atopcu commented 9 years ago

Dear @xaionaro,

I tried https://github.com/mephi-ut/redmine_extended_watchers.

  1. The a patch take 2 seconds. this is very close to previous result.
  2. I'm not sure, some other plugin may query project list during the issue indexing ?

Regards,

xaionaro commented 9 years ago

The a patch take 2 seconds. this is very close to previous result.

I see :(

I'm not sure, some other plugin may query project list during the issue indexing ?

May be. I wrote one plugin that queries project list on every page. But the performance problem was easily solved by a simple cache(@projects) do.

Also. It's not about the plugin, but about the performance. I found that redmine3 on rails4 from Debian/sid works much faster than redmine2.4 on rails3. However there's a lot of bugs, but I fixed almost every that we found.

atopcu commented 9 years ago

Thank you.

maxrossello commented 9 years ago

@atopcu would you try my latest commit please?

atopcu commented 9 years ago

@maxrossello,

I tried. but it caused an error on add issue page. I switched to with_view_own. I can't get log yet. I will report details soon.

Regards.

maxrossello commented 9 years ago

I have made a general review eliminating unneeded code inherited from the with_view_own approach and optimizing where possible.

My feeling is that with_view_own approach has a mean to filter issue accessibility before entering the methods that check for the user watching the issue, and so it could be faster for this reason.

However, my preliminary tests seem to report a significative speedup in project listing

maxrossello commented 9 years ago

@atopcu I think I found the bug causing you error 500. Please retry with latest version. Thanks

atopcu commented 9 years ago

@maxrossello, firstly, thank you so much for your effort. Yes, error 500 was solved. but the time difference between master and with_view_own brance still longer than 5 sec for same condition in our instance. Regards.

maiconzucco commented 9 years ago

Hi,

I tried the alteration above.

In the file lib/extended_watchers_issue_patch.rb a replaced:

watched_group_issues_clause << " OR #{table_name}.id IN (#{watched_issues.join(',')})" <<

    watched_group_issues_clause <<  " OR #{table_name}.id IN ( select watchable_id from watchers where watchable_type = 'Issue' and user_id = #{user.id} )" <<

For me works fine and improve the page load speed.

maxrossello commented 4 years ago

The plugin has now a refreshed architecture. Closing this very important issue as obsoleted. In case a problem still holds, please open a new issue based on Redmine 3.4 or later (support for 4.x is coming soon). Thanks everybody for your effort and collaboration!