Is it possible to fix the search process that requires CPU processing?

[iwadara]

I was using this plugin in Redmine 4.1.1. I was using it in a 200,000 ticket environment with about 500 people. And I was using the policy "Extended".

When opening a wiki page or ticket page in the Chrome browser, it has a response time of 2500ms. With this plugin disabled, the response time is now 1500ms.

Also, if you check the CPU usage of the web server with the "top" command when the plugin is enabled, ruby's CPU usage is very high.

I'm guessing that this is probably due to the heavy search process to see if a watcher is added to each user. Is it possible to fix the search process that requires CPU processing?

If fixed, I can measure the effectiveness. Thanks for a very useful plugin.

[maxrossello]

Hi, thanks for using this plugin and offering to help. Actually your large database is a very interesting test bed for me. I would be very grateful if you could log the profile of the SQL queries in the two cases, with and without the plugin, possibly by making a single query of the issues page at each server run on a clean logfile. Ideal would be to run a server in development environment and enable logging to console, so to have the profile on the logfile. In order to do so, you would edit the file config/environments/development.rb and add a line like:

config.logger = Logger.new STDOUT

Many thanks!

[iwadara]

Sorry, I am not able to upload the logs. Instead, I enabled the plugin and saw the following SQL log output

SELECT `issues`.* FROM `issues` INNER JOIN `watchers` ON `watchers`.`watchers_id` = `issue`.`id` AND `watchers`.`watchable_type` = `Issue` INNER JOIN `projects` ON ...

This SQL query seems to take 40-50 ms per transaction. It looks like the SQL query is called about 30 times per web page request.

I guess that's why it takes 1 second longer in my environment to enable the plugin. I'd be happy to help you.

[maxrossello]

Sorry for late responding. I believe that the problem is due to the watcher check within Issue.visible? which is called rather frequently. I'll try to validate a faster way to do the same. Thanks

[maxrossello]

I see little or no performance benefit on the small default database for automated tests by using the following patch, but it should avoid to repeat the sql statement that you mentioned. Can you please test if it is more effective on your large database? Thanks a lot

diff --git a/plugins/redmine_extended_watchers/lib/extended_watchers_issue_patch.rb b/plugins/redmine_extended_watchers/lib/extended_watchers_issue_patch.rb
index 92c182d5d..9b29917a7 100644
--- a/plugins/redmine_extended_watchers/lib/extended_watchers_issue_patch.rb
+++ b/plugins/redmine_extended_watchers/lib/extended_watchers_issue_patch.rb
@@ -47,7 +47,7 @@ end
 module ExtendedWatchersIssueInstancePatch

   def visible?(usr=nil)
-    return true if Setting.plugin_redmine_extended_watchers["policy"] == "extended" && self.watcher_users.include?(usr || User.current)
+    return true if Setting.plugin_redmine_extended_watchers["policy"] == "extended" && self.watched_by?(usr || User.current)

     (usr || User.current).allowed_to?(:view_issues, self.project, {issue: true}) do |role, user|
       visible = if user.logged?
@@ -67,7 +67,7 @@ module ExtendedWatchersIssueInstancePatch
       unless role.permissions_all_trackers?(:view_issues)
         visible &&= role.permissions_tracker_ids?(:view_issues, tracker_id)
       end
-      visible ||= (Setting.plugin_redmine_extended_watchers["policy"] == "protected" && self.watcher_users.include?(usr || User.current))
+      visible ||= (Setting.plugin_redmine_extended_watchers["policy"] == "protected" && self.watched_by?(usr || User.current))
       visible
     end
   end

[iwadara]

Thanks for the info. I measured it in a patched environment.

(Before patch) 1st time: 2546 ms 2nd time: 2451 ms

(After patch) 1st time: 2389 ms 2nd time: 2263 ms

(disable plugins) 1st time: 1382 ms 2nd time: 1056 ms

The above was determined from the following line in the log file.

INFO -- : Completed 200 OK

I hope this is helpful.

[maxrossello]

A marginal improvement then. A few questions:

• when you say "disable plugins" you mean this plugin only?
• have the culprit SQL queries disappeared? Where are the queries loosing most time now?

It would be really helpful if you could attach the log. Maybe the .log extension is not accepted, but as .txt it should. Thanks a lot

[iwadara]

I am very sorry. Due to security factors, I am unable to upload the log files. To answer your question.

when you say "disable plugins" you mean this plugin only?

Yes. This plugin only.

have the culprit SQL queries disappeared? Where are the queries loosing most time now?

SQL queries are being output in the same number as before. Slow and repetitive SQL queries are the same as before.

SELECT `issues`.* FROM `issues` INNER JOIN `watchers` ON `watchers`.`watchers_id` = `issue`.`id` AND `watchers`.`watchable_type` = `Issue` INNER JOIN `projects` ON ...

If you can't track the cause any further, you can have this issue closed. Thanks.

[maxrossello]

I will find the time to make some further investigation. Thanks

[maxrossello]

Tried over an installation with 16500+ issues and 150+ active users in production Rails env. Browsed the /issues global tickets page using 200 entries per page with no notable penalty (except on first view after web server just started, ~10% penalty could be due to empty caches). The ruby/passenger process did not even show in top. Agreed, I would not say that the users I tried had a large rate of watches over issues. However, the penalty you observe is rather large and should be detected in this environment too. Wondering if your ruby or web server environment is updated? I am using passenger 6.0.4 and ruby 2.4.6p354.

[iwadara]

I was using it in a 200,000 ticket environment with about 500 people. I am using passenger 6.0.5 and ruby 2.6.3.

In this environment, I can observe a penalty that goes from 1500ms to 2500ms when the plugin is enabled. This is the same for both tickets and wikis.

However, very unfortunately for security reasons I am not able to upload the log files. It is difficult to convey any more information. This ticket may be closed.

[maxrossello]

Hello @iwadara , I went through a long profiling session and optimized the code by compacting the most critical SQL queries. Most performance gains show with the 'protected' mode, but also 'extended' mode is rather improved. I am still testing against ruby 2.4, but that should not be the point. Would you please have a run and tell if things go better for you as well? Thanks a lot for your support

[iwadara]

Hello @maxrossello,

I tried redmine_extended_watchers 4.1.1.2 in this environment. As a result, I confirmed that redmine_extended_watchers 4.1.1.2 works in 'extended' mode with almost the same response time as when the plugin is disabled.

To be sure, I reverted back to 4.1.1 and confirmed that there was a delay of about 1000ms. It seems that 4.1.1.2 has improved the response time. Excellent!

I am very grateful for the response so far. If there are no problems, please close this issue.

[maxrossello]

Thanks @iwadara , your report against a real large database and the related possibility to test was the fundamental trigger to this improvement. I learnt a lot about the rack-mini-profiler gem, and this is a good thing too. Good job for both of us! Closing the issue