SugarCRM – Team security query caching

Following up on my previous article about Sugar’s Team Security implementation, I thought it would be interesting and useful to discuss and mention a new setting to improve it.

Prerequisites

For this article I’ve used:

• Sugar Enterprise v7.6.0.0
• The infrastructure setup described on my previous article Setup a Debian Based Sugar development environment (or similar)
• In-memory caching is enabled using memcache/memcached (my current preference) depending on the linux flavour used

Introduction

Some time ago, I was analysing the performance of the Team Security query. The slowest part of the query seems to be caused by the subquery with joins between the tables team_sets_teams and team_memberships within listview queries.

Then I thought: Sugar caches most of the semi-static data (vardefs, language files, etc) into whatever caching mechanism is used by the system, why don’t we run an IN() condition using the cached list of ids per user, instead of a subquery on every listview load?

Basically we would want to change a listview query from something like this (let’s call this “Query A“):

SELECT
  ...
FROM
  contacts INNER JOIN
    (select
      tst.team_set_id
    from
      team_sets_teams tst INNER JOIN
        team_memberships team_memberships
      ON tst.team_id = team_memberships.team_id
        AND team_memberships.user_id = 'seed_will_id'
        AND team_memberships.deleted=0
      group by tst.team_set_id)
    contacts_tf
  ON contacts_tf.team_set_id = contacts.team_set_id
  LEFT JOIN ...
WHERE
  ...
ORDER BY
  ...
LIMIT 0,21

To something like this (with cached list of ids coming from memcached or similar) (let’s call this “Query B“):

SELECT
  ...
FROM
  contacts
  LEFT JOIN ...
WHERE
  (contacts.team_set_id IN( ... )) AND ...
ORDER BY
  ...
LIMIT 0,21

And what would be the estimated performance gain?

Performance Testing and queries Analysis

First of all, I should mention that my data sample was the default demo data set, so it was not a huge amount.

I’ve run some tests using the MySQL “EXPLAIN” command to estimate the number of total rows of each of the two queries and to understand their complexity, by using the MySQL “PROFILER”, and finally I monitored the MySQL server’s status variables. I made sure I cleared the query cache, flushes status variables, swapped multiple times the order of queries to verify that the result was consistently similar.

MySQL EXPLAIN

The MySQL “EXPLAIN” of Query A looks like the following:

+----+-------------+-----------------------------+--------+---------------------------------------------------------------------------------+--------------------------------+---------+---------------------------------------------------+------+----------------------------------------------+
| id | select_type | table                       | type   | possible_keys                                                                   | key                            | key_len | ref                                               | rows | Extra                                        |
+----+-------------+-----------------------------+--------+---------------------------------------------------------------------------------+--------------------------------+---------+---------------------------------------------------+------+----------------------------------------------+
|  1 | PRIMARY     | <derived2>                  | ALL    | NULL                                                                            | NULL                           | NULL    | NULL                                              |    7 | Using temporary; Using filesort              |
|  1 | PRIMARY     | contacts                    | ref    | idx_contacts_tmst_id,idx_contacts_del_last,idx_cont_del_reports,idx_del_id_user | idx_contacts_tmst_id           | 109     | contacts_tf.team_set_id                           |   10 | Using where                                  |
|  1 | PRIMARY     | sf_contacts                 | ref    | idx_favs_module_record_deleted,idx_favs_id_record_id                            | idx_favs_module_record_deleted | 266     | const,sugarcrm.contacts.id,const                  |    1 |                                              |
|  1 | PRIMARY     | jt2_subscriptions           | ref    | subscription_parent                                                             | subscription_parent            | 108     | sugarcrm.contacts.id                              |    1 |                                              |
|  1 | PRIMARY     | jt1_following_link          | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt2_subscriptions.created_by             |    1 |                                              |
|  1 | PRIMARY     | jt1_following_link_cstm     | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt1_following_link.id                    |    1 | Using index                                  |
|  1 | PRIMARY     | jt4_accounts_contacts       | ref    | idx_contid_del_accid                                                            | idx_contid_del_accid           | 113     | sugarcrm.contacts.id,const                        |    1 |                                              |
|  1 | PRIMARY     | jt3_accounts                | eq_ref | PRIMARY,idx_accounts_id_del,idx_accnt_assigned_del                              | PRIMARY                        | 108     | sugarcrm.jt4_accounts_contacts.account_id         |    1 |                                              |
|  1 | PRIMARY     | jt3_accounts_cstm           | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt3_accounts.id                          |    1 | Using index                                  |
|  1 | PRIMARY     | jt6_email_addr_bean_rel     | ref    | idx_bean_id                                                                     | idx_bean_id                    | 411     | sugarcrm.contacts.id,const                        |    1 |                                              |
|  1 | PRIMARY     | jt5_email_addresses_primary | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt6_email_addr_bean_rel.email_address_id |    1 |                                              |
|  1 | PRIMARY     | jt7_assigned_user_link      | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.contacts.assigned_user_id                |    1 |                                              |
|  1 | PRIMARY     | jt7_assigned_user_link_cstm | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt7_assigned_user_link.id                |    1 | Using index                                  |
|  1 | PRIMARY     | jt8_favorite_link           | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.sf_contacts.modified_user_id             |    1 |                                              |
|  1 | PRIMARY     | jt8_favorite_link_cstm      | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt8_favorite_link.id                     |    1 | Using index                                  |
|  1 | PRIMARY     | contacts_cstm               | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.contacts.id                              |    1 | Using index                                  |
|  2 | DERIVED     | team_memberships            | ref    | idx_team_membership,idx_teammemb_team_user                                      | idx_team_membership            | 109     |                                                   |   10 | Using where; Using temporary; Using filesort |
|  2 | DERIVED     | tst                         | ref    | idx_ud_team_id                                                                  | idx_ud_team_id                 | 109     | sugarcrm.team_memberships.team_id                 |    1 | Using where                                  |
+----+-------------+-----------------------------+--------+---------------------------------------------------------------------------------+--------------------------------+---------+---------------------------------------------------+------+----------------------------------------------+

The MySQL “EXPLAIN” of Query B looks like the following:

+----+-------------+-----------------------------+--------+---------------------------------------------------------------------------------+--------------------------------+---------+---------------------------------------------------+------+-------------+
| id | select_type | table                       | type   | possible_keys                                                                   | key                            | key_len | ref                                               | rows | Extra       |
+----+-------------+-----------------------------+--------+---------------------------------------------------------------------------------+--------------------------------+---------+---------------------------------------------------+------+-------------+
|  1 | SIMPLE      | contacts                    | index  | idx_contacts_tmst_id,idx_contacts_del_last,idx_cont_del_reports,idx_del_id_user | idx_contacts_date_modfied      | 9       | NULL                                              |   32 | Using where |
|  1 | SIMPLE      | sf_contacts                 | ref    | idx_favs_module_record_deleted,idx_favs_id_record_id                            | idx_favs_module_record_deleted | 266     | const,sugarcrm.contacts.id,const                  |    1 |             |
|  1 | SIMPLE      | jt2_subscriptions           | ref    | subscription_parent                                                             | subscription_parent            | 108     | sugarcrm.contacts.id                              |    1 |             |
|  1 | SIMPLE      | jt1_following_link          | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt2_subscriptions.created_by             |    1 |             |
|  1 | SIMPLE      | jt1_following_link_cstm     | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt1_following_link.id                    |    1 | Using index |
|  1 | SIMPLE      | jt4_accounts_contacts       | ref    | idx_contid_del_accid                                                            | idx_contid_del_accid           | 113     | sugarcrm.contacts.id,const                        |    1 |             |
|  1 | SIMPLE      | jt3_accounts                | eq_ref | PRIMARY,idx_accounts_id_del,idx_accnt_assigned_del                              | PRIMARY                        | 108     | sugarcrm.jt4_accounts_contacts.account_id         |    1 |             |
|  1 | SIMPLE      | jt3_accounts_cstm           | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt3_accounts.id                          |    1 | Using index |
|  1 | SIMPLE      | jt6_email_addr_bean_rel     | ref    | idx_bean_id                                                                     | idx_bean_id                    | 411     | sugarcrm.contacts.id,const                        |    1 |             |
|  1 | SIMPLE      | jt5_email_addresses_primary | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt6_email_addr_bean_rel.email_address_id |    1 |             |
|  1 | SIMPLE      | jt7_assigned_user_link      | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.contacts.assigned_user_id                |    1 |             |
|  1 | SIMPLE      | jt7_assigned_user_link_cstm | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt7_assigned_user_link.id                |    1 | Using index |
|  1 | SIMPLE      | jt8_favorite_link           | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.sf_contacts.modified_user_id             |    1 |             |
|  1 | SIMPLE      | jt8_favorite_link_cstm      | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.jt8_favorite_link.id                     |    1 | Using index |
|  1 | SIMPLE      | contacts_cstm               | eq_ref | PRIMARY                                                                         | PRIMARY                        | 108     | sugarcrm.contacts.id                              |    1 | Using index |
+----+-------------+-----------------------------+--------+---------------------------------------------------------------------------------+--------------------------------+---------+---------------------------------------------------+------+-------------+

MySQL Profiler

To profile more accurately, we need to make sure we do not allow caching on every query run so that we have consistent results. There are multiple layers of caching: query caching, InnoDB buffer caching, OS caching. Looking around I’ve found some commands that allow us to remove all the caching I know of.

First of all we force the kernel to “drop clean caches, as well as reclaimable slab objects like dentries and inodes. Once dropped, their memory becomes free” (source kernel.org). The command is as follows:

sync && echo 3 | sudo tee /proc/sys/vm/drop_caches

Then we restart MySQL to make sure we clear the InnoDB buffer pool.

Finally within MySQL we make sure that the query will not cache:

SET SESSION query_cache_type = OFF;
reset query cache;

Now we can enable the profiler (with “SET PROFILING=1”), run the query and see the profile result (with “SHOW PROFILE”). I’ve formatted the results from the slowest to the fastest portion of the query, to have a clearer picture.

Query A Profile

+----------------------+----------+-------+-------+--------------+
| Action               | Time     | Perc. | Calls | Time/Call    |
+----------------------+----------+-------+-------+--------------+
| Copying to tmp table | 0.008959 | 70.75 |     2 | 0.0044795000 |
| System lock          | 0.001425 | 11.25 |     1 | 0.0014250000 |
| freeing items        | 0.000925 |  7.30 |     1 | 0.0009250000 |
| statistics           | 0.000412 |  3.25 |     2 | 0.0002060000 |
| starting             | 0.000190 |  1.50 |     1 | 0.0001900000 |
| cleaning up          | 0.000122 |  0.96 |     1 | 0.0001220000 |
| Opening tables       | 0.000119 |  0.94 |     1 | 0.0001190000 |
| Sorting result       | 0.000112 |  0.88 |     2 | 0.0000560000 |
| init                 | 0.000102 |  0.81 |     1 | 0.0001020000 |
| preparing            | 0.000086 |  0.68 |     2 | 0.0000430000 |
| optimizing           | 0.000061 |  0.48 |     2 | 0.0000305000 |
| Sending data         | 0.000043 |  0.34 |     3 | 0.0000143333 |
| Creating tmp table   | 0.000037 |  0.29 |     2 | 0.0000185000 |
| checking permissions | 0.000027 |  0.21 |    17 | 0.0000015882 |
| closing tables       | 0.000017 |  0.13 |     2 | 0.0000085000 |
| removing tmp table   | 0.000010 |  0.08 |     3 | 0.0000033333 |
| end                  | 0.000005 |  0.04 |     2 | 0.0000025000 |
| executing            | 0.000004 |  0.03 |     2 | 0.0000020000 |
| logging slow query   | 0.000004 |  0.03 |     1 | 0.0000040000 |
| query end            | 0.000003 |  0.02 |     1 | 0.0000030000 |
+----------------------+----------+-------+-------+--------------+

Query B Profile

+----------------------+----------+-------+-------+--------------+
| Action               | Time     | Perc. | Calls | Time/Call    |
+----------------------+----------+-------+-------+--------------+
| Sending data         | 0.001596 | 51.25 |     1 | 0.0015960000 |
| freeing items        | 0.000519 | 16.67 |     1 | 0.0005190000 |
| starting             | 0.000244 |  7.84 |     1 | 0.0002440000 |
| statistics           | 0.000223 |  7.16 |     1 | 0.0002230000 |
| preparing            | 0.000155 |  4.98 |     1 | 0.0001550000 |
| init                 | 0.000139 |  4.46 |     1 | 0.0001390000 |
| Opening tables       | 0.000110 |  3.53 |     1 | 0.0001100000 |
| checking permissions | 0.000036 |  1.16 |    15 | 0.0000024000 |
| optimizing           | 0.000025 |  0.80 |     1 | 0.0000250000 |
| closing tables       | 0.000016 |  0.51 |     1 | 0.0000160000 |
| System lock          | 0.000015 |  0.48 |     1 | 0.0000150000 |
| end                  | 0.000010 |  0.32 |     1 | 0.0000100000 |
| cleaning up          | 0.000007 |  0.22 |     1 | 0.0000070000 |
| Sorting result       | 0.000006 |  0.19 |     1 | 0.0000060000 |
| query end            | 0.000005 |  0.16 |     1 | 0.0000050000 |
| executing            | 0.000004 |  0.13 |     1 | 0.0000040000 |
| logging slow query   | 0.000004 |  0.13 |     1 | 0.0000040000 |
+----------------------+----------+-------+-------+--------------+

As we can see, the bulk of the time of Query A is spent generating the two temporary tables required by the query!

MySQL Status

To be able to read status variables, we need to flush them before the query’s execution.

To flush the status variable we execute “flush status;”, then run the query and finally execute “show status;”.

Refer to the MySQL manual server status variable page to find the full description of the status variables.

Query A Status

+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Handler_read_key           | 1915  |
| Handler_read_last          | 0     |
| Handler_read_next          | 893   |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 28    |
| Handler_read_rnd_next      | 221   |
| Handler_write              | 171   |
| Created_tmp_tables         | 3*    |
+----------------------------+-------+
*Created_tmp_tables is incremented once by the "show status" command. The real result is 2.

Query B Status

+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Handler_read_key           | 146   |
| Handler_read_last          | 1     |
| Handler_read_next          | 18    |
| Handler_read_prev          | 20    |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 0     |
| Handler_write              | 0     |
| Created_tmp_tables         | 0     |
+----------------------------+-------+

The MySQL status variables “Handler_read_rnd” and “Handler_read_rnd_next” on the Query A, show us that indexes are not utilised at their best (additional info can be found on this url).

Results Summary

Standard demo data (non tuned db)

	Query A	Query B	Gain
Explain – Estimated Row Cardinality	700	32	22x
Explain – Temporary Tables and Filesorts	2	0	> 2x
Profiler – Total Time (seconds)	0.0127	0.0031	4x
Status – read_rnd	28	0	> 28x
Status – read_rnd_next	221	0	> 221x
Status – write	171	0	> 171x
Status – tmp_tables	2	0	> 2x

To make the tests more relevant, I have produced a substantial data set and tested again similar queries (different set of Teams). The User has been added to many Teams, and about only 2,000 records were visible to the User over 10,000 available. Based on those conditions, the results are as described below:

Over 10,000 records per table of demo data (non tuned db)

	Query A	Query B	Gain
Explain – Estimated Row Cardinality	> 1Billion	116	> 1B
Explain – Temporary Tables and Filesorts	2	0	> 2x
Profiler – Total Time (seconds)	26.5	0.88	30x
Status – read_rnd	3,054	0	> 3,054x
Status – read_rnd_next	921,340	0	> 1Mx
Status – write	63,214	0	> 63,214x
Status – tmp_tables	2	0	> 2x

As we can see, if the data increases, the results between Query A and Query B start to be substantially different, especially if the database is limited in resources and it has not been configured to deal with the increasing dataset.

Enable Teams on the where condition

With Sugar version 7, it is now really easy to move the Teams query from the JOIN condition to the WHERE condition. Additionally, if a caching mechanism is enabled for the system, there is a really easy way to enable the caching of Team ids of a user, and use them within an IN() condition to speed up even further the system.

It is important to note that there are different options and combinations of options available, described below.

To enable Teams pre-fetching and using an IN() condition on the where clause of the query, you can use the following configuration settings:

$sugar_config['perfProfile']['TeamSecurity']['default']['where_condition'] = true;
$sugar_config['perfProfile']['TeamSecurity']['default']['teamset_prefetch'] = true;

Additionally there is a certain limit where the join would most likely become better performing (eg: if there are many Teams per User). For that specific reason, and probably for the fact that caching has size limits too (eg: memcache/memcached has 1MB limit per object normally), there is an additional setting that can be tweaked based on performance testing on your specific case.

The setting that will help you set the maximum number of prefetched Teams is:

$sugar_config['perfProfile']['TeamSecurity']['default']['teamset_prefetch_max'] = 500; // default 500

Moving the Team query on the WHERE clause as a subquery, will give a performance improvement compared to the out of the box query. Obviously the improvement is much lower than the combination of the “pre-fetch” functionality and WHERE condition IN() clause. I would definitely recommend combining the two options if in-memory caching is available for your system.

There is a third and last option available, that allows you to split the query in two. At first the system will be running the subquery, then once results are obtained (list of Team ids), it will run the query with the IN() condition within the WHERE clause and no subquery. This is only possible if caching is completely disabled for the system, and the options “teamset_prefetch” and “where_condition” are enabled.

To disable completely caching (NOTE: this will impact ANY caching that the system does including vardefs, languages etc.) the following setting is required:

$sugar_config['external_cache_disabled'] = true;

I did not personally profile this last use case, but I thought it would be worth mentioning. I suspect that the Team separate queries would be cached by MySQL and would still have a decent performance compared to the other cases, but obviously will perform worse than the full “pre-fetch” functionality.

This blog post should give an idea on what to look for to understand performance problems on a MySQL query, as well as help you understand what is the best setting for your specific SugarCRM setup.