New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Speed problems: suggestions for targets to focus on? #39

Open
cleary opened this Issue Nov 27, 2018 · 29 comments

Comments

Projects
None yet
2 participants
@cleary

cleary commented Nov 27, 2018

Hi Adam,
We've been using our install for a long time (well over a decade?) and have amassed about 1600 projects.

We're finding that there are certain areas in dotProject are extremely slow, where the mysqld process maxes out a cpu core, and we have to wait for significant amounts of time for a return - I assume this is by and large as a result of the sheer quantity of projects that are dealt with during a query.

Examples:

  1. Saving a task after Edit - 9-10s
  2. Clicking the Tasks module in the top menu - 80s (and only returning 13 tasks)
  3. Opening a project in Project Designer module - 9-10s

Now 2) is particularly bad, but can be avoided. 1) and 3) are what are most commonly used for doing cleanup/maintenance - ie times when you just want to duck in quickly and change a few things, but after doing this a few times, waiting for the saves feels like an eternity.

Do you have any recommendations on how/what we could do to start optimising some of these functions?

(@mattbell87 is potentially looking for some short and sweet tasks so this may be suitable for him to work on)

I had an idea (but I'm not a db guy, so it's likely terrible) that we could move all archived projects into a completely separate table that would exclude them from having to be considered in most queries - is that a possible/feasible option?

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 27, 2018

I think we probably need to look at the queries being generated and determining why they are slow. It may simply be that we are missing correct indices or that we are generating overly complex queries. My gut feeling would be that the permissions phase may be the problem - but I'd have to delve into it a bit more deeply.

If you have a staging system with the same data on it then it might be a good idea to enable slow query logging in MySQL, then we can get an idea of the exact queries causing the issue. https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html

Alternatively if you have one that runs for a length of time you can use:

SHOW FULL PROCESSLIST;

If you do this while it is running it will show the complete query and we can take it from there.

@cleary

This comment has been minimized.

cleary commented Nov 28, 2018

Ok, I've set up the slow_query settings, the query it's getting stuck on is as follows:

  1. SELECT pref_value FROM (user_preferences) WHERE pref_user = 0 AND pref_name = 'TASKASSIGNMAX';
  2. SELECT pref_value FROM (user_preferences) WHERE pref_user = 0 AND pref_name = 'TASKASSIGNMAX';
  3. SELECT pref_value FROM (user_preferences) WHERE pref_user = 0 AND pref_name = 'TASKASSIGNMAX';

Maybe it's just me, but I'm seeing a pattern emerging :P

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 28, 2018

I suspect that will be a side effect and not the main game. That table is very small and there is an appropriate index on it. They might be getting stuck because of a large number of them happening at the same time, which might mean we need to cache those.

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 28, 2018

Looking at the code that query comes from the CTask::getAllocation method, which is run on every task - and since it is getting a user preference, even though it is the system-wide preference, it should be getting it from $AppUI->getPref() which pre-loads all the user preferences at login. If it truly needs to be the system default, then we should load those in $AppUI as well. Happy to commit a fix, or you can get @mattbell87 to take a look - there might also be some improvements to the rest of the queries in that function that are possible.

@cleary

This comment has been minimized.

cleary commented Nov 28, 2018

Fantastic, that particular fix is of really high value to us in the short term - it'd be great if you have an opportunity to take a look.

For further improvements, I'm happy to pass them to Matt (he's out of commission for a few weeks though)

ajdonnison added a commit that referenced this issue Nov 28, 2018

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 28, 2018

Give that a go, it should remove at least part of the problem.

@cleary

This comment has been minimized.

cleary commented Nov 28, 2018

Ok I had a look at it, I'm getting the following error in most scenarios where I was previously affected (submitting Task Edits, Tasks module, Project Designer module)

Fatal error: Uncaught Error: Call to a member function getSystemPref() on null in /data/srv/debortoli.private/dotProject.git/modules/tasks/tasks.class.php:1766 Stack trace: #0 /data/srv/debortoli.private/dotProject.git/modules/tasks/tasks.class.php(1714): CTask->getAllocation('user_id') #1 /data/srv/debortoli.private/dotProject.git/modules/tasks/do_task_aed.php(176): CTask->updateAssigned('', Array) #2 /data/srv/debortoli.private/dotProject.git/index.php(241): require('/data/srv/debor...') #3 {main} thrown in /data/srv/debortoli.private/dotProject.git/modules/tasks/tasks.class.php on line 1766

ajdonnison added a commit that referenced this issue Nov 28, 2018

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 28, 2018

Sorry about that - not sure why it didn't show up in my testing - but that last push should fix that.

@cleary

This comment has been minimized.

cleary commented Nov 28, 2018

Ok, I've given it a bit of a trial - gut feeling is there's no improvement, but if I time it:

  1. Saving a task after Edit - 8.32s
  2. Clicking the Tasks module in the top menu - 66.73s
  3. Opening a project in Project Designer module - 8.55s

So it's an improvement, but in the ~10-15% range by the looks

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 28, 2018

Yeah, I didn't think it would be the most likely culprit. It amazes me that saving a task would be that slow. Do you mind running the following command from the MySQL CLI and providing the output?

SHOW TABLE STATUS;

That will give me an idea of the size of tables and indexes involved.

@cleary

This comment has been minimized.

cleary commented Nov 28, 2018

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 28, 2018

While none of the tables are super large by modern standards one thing that does stand out is that they are all MyISAM. If you migrate them to InnoDB you'll see improvements in both search and update - search because a primary key lookup doesn't need to load the data (the primary key is stored with the row data, so a primary key lookup returns the data already), and because on insert/delete/update it can make use of row-level locking. MyISAM uses table-level locks.

To do this on existing tables you need to run the following command on each table:

ALTER TABLE tablename ENGINE InnoDB;

On some of the bigger tables that is going to take some time, and you need to ensure your MySQL configuration is optimised for InnoDB - although recent versions default to that so even the base setup should be fine.

@cleary

This comment has been minimized.

cleary commented Nov 29, 2018

Alright, I've gone through that, verified each table is now using the InnoDB engine.
I'm using a default mariadb install in CentOS 7, I don't know what that means for InnoDB optimisation, google isn't really helping me out there -

Restarted, and I'm not really seeing any improvements still

billingcode InnoDB                                                             
common_notes InnoDB                                                             
companies InnoDB                                                                
config InnoDB                                                                  
config_list InnoDB                                                        
contacts InnoDB                                                              
custom_fields_lists InnoDB                                                       
custom_fields_option_id InnoDB                                                
custom_fields_struct InnoDB                                                   
custom_fields_struct_id InnoDB                                                 
custom_fields_values InnoDB                                                    
custom_fields_values_id InnoDB  
...
@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 29, 2018

That's a little disappointing. Still, it removes yet another possible pain point. Let's just check that we don't have index issues, can you run a mysqldump with the -d option on the dotProject database? This only puts out the create table statements, no data. If you'd prefer, just check it against that in the db/dotproject.sql file from the dotProject distro and make sure all the indices are there.

If they are all there, then we need to look at what queries are being run and see if we can identify the problem that way.

With the editing of tasks taking 8+ seconds, does it matter what type of task? If there is a difference, are there obvious differences in the task setup (e.g. one using dependencies, one not)?.

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 29, 2018

Just looking at the table status, it looks like the entire database is less than 200MB, did you want to send me a copy privately and I'll run some tests against it here and see if I can figure out where the slowness is coming from?

@cleary

This comment has been minimized.

cleary commented Nov 29, 2018

That would be amazing, thank you

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 29, 2018

It looks like it is still that same function - getAllocation() - it has a seriously ugly and badly performing query and given that it does it for all users for all tasks, it looks again like something that could be cached - and certainly should be rewritten to make it less troublesome. I may get time over the next day or so to take a look, and given that each iteration can last 17 seconds or more on my system, I would say that once we fix that we should see a marked improvement in performance.

ajdonnison added a commit that referenced this issue Nov 29, 2018

@cleary

This comment has been minimized.

cleary commented Nov 29, 2018

That'd be fantastic, thanks again

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 29, 2018

This new push shows promise at least for the full task listing - on my system it stopped the full task list from timing out (I'm running it on a very lowly configured test server). There looks to be room for more performance improvements in that area, but if you could run this up the flagpole and see who salutes that would be great.

@cleary

This comment has been minimized.

cleary commented Nov 29, 2018

66s -> 7s(!) for the full task listing

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 29, 2018

A great start! I'm sure there are more performance improvements we can get along the way.

ajdonnison added a commit that referenced this issue Nov 29, 2018

Add support for multiple inserts in single query
Addresses #39 - should help with task saves.
@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Nov 29, 2018

This push should help with saving of tasks that have a lot of dependencies and/or assignees. This adds a change to the query class so please treat with caution and let me know of any issues. Local testing shows it working reasonably well.

@cleary

This comment has been minimized.

cleary commented Nov 30, 2018

@cleary

This comment has been minimized.

cleary commented Dec 3, 2018

Hi Adam,
I just gave it a run - times are consistently 7.6s now, down from 8-9s -

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Dec 3, 2018

So is this the same (7.6s) for saving a task as well as for task listings?

@cleary

This comment has been minimized.

cleary commented Dec 3, 2018

...yes - I didn't notice the correlation til you mentioned it ;)

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Dec 3, 2018

I'm getting a lot quicker response on saving tasks - sub 2s. I note your setup is to send emails out synchronously - if you enable queuing of emails does that make a difference?

@cleary

This comment has been minimized.

cleary commented Dec 3, 2018

Ok, I've enabled the queueing for email, it doesn't make a noticeable difference here - mysqld is still using 100% of cpu for the duration of the wait too

@ajdonnison

This comment has been minimized.

Contributor

ajdonnison commented Dec 3, 2018

Interesting. The last push should have removed the call to getAllocation from the task save, it was being called but the results weren't being used anyway. Does it matter what type of task you are saving? Would you perhaps have the task_id handy? I'll make sure I'm trying to save the same task. Also if you could run a few SHOW PROCESSLIST; commands in the MySQL CLI while it is at 100% CPU and let me know what sort of processes are running it might help to track down the culprit.

I've also had a few thoughts over the weekend of a generic caching mechanism that might assist in this and in permissions handling - there was some work done on that, although I think a more general approach is likely to offer better performance overall - especially if we can combine it with non-database-backed caching mechanisms (like memcached or redis, for instance).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment