How to Use Slow Query Logging

[Jacob]

Slow query logging is used to determine where database time is spent. If there is a query that is running inefficiently this mechanism will help isolate it.

Question: How do I turn on slow query logging?
Answer: To log all slow queries , follow these steps:

There are two major methods to turn on slow query logging:
1) Log into the application as an administrator
2) Click the "Admin" link
3) Click "System Settings"
4) Make sure "Log slow queries:" is checked.
5) Set "Slow query time threshold (msec):" to 100

Or...

1) Open your config.php file, located in the main Sugar directory
2) Locate this line:

          'dump_slow_queries' => false, 
  

3) Change the line to:

          'dump_slow_queries' => true, 
  

4) Locate this line:

          'slow_query_time_msec' => '500', 
  

5) Change the line to:

          'slow_query_time_msec' => '100', 
  

6) Save the file

(If you want a full log of all queries change the slow query time to -1 since many queries run in less than 1 ms).


Here is a sample of the contents of sugarcrm.log after the slow query log is turned on. Note: all messages are logged as FATAL to ensure that they make it into the logfile.

11/22/05 10:47:41,170 [6448] FATAL SugarCRM - Slow Query (time:0.031598
        SELECT count(*) FROM contacts LEFT JOIN users
                                ON contacts.assigned_user_id=users.id
                                LEFT JOIN accounts_contacts
                                ON contacts.id=accounts_contacts.contact_id  
                                LEFT JOIN accounts
                                ON accounts_contacts.account_id=accounts.id  LEFT JOIN teams ON contacts.team_id=teams.id AND (teams.deleted=0) where  contacts.deleted=0  AND (accounts.deleted is NULL or accounts.deleted=0)   
        11/22/05 10:47:41,183 [6448] FATAL SugarCRM - Slow Query (time:0.012344
        SELECT 
                        contacts.*,
                        accounts.name as account_name,
                        accounts.id as account_id,
                        accounts.assigned_user_id account_id_owner,
                        users.user_name as assigned_user_name ,teams.name AS team_name 
                        FROM contacts LEFT JOIN users
                                ON contacts.assigned_user_id=users.id
                                LEFT JOIN accounts_contacts
                                ON contacts.id=accounts_contacts.contact_id  
                                LEFT JOIN accounts
                                ON accounts_contacts.account_id=accounts.id  LEFT JOIN teams ON contacts.team_id=teams.id AND (teams.deleted=0) where  contacts.deleted=0  AND (accounts.deleted is NULL or accounts.deleted=0)   ORDER BY contacts.last_name, contacts.first_name asc LIMIT 0,20

This sample shows 2 "slow" queries. Each one has an easily identified log statement "FATAL SugarCRM - Slow Query", followed by the etime in seconds for the query. After this, there is a newline and then the query is presented in the formatting in which it was sent to the database. Putting the query on its own line make it easy to find and easy to cut/paste into another program for further diagnosis.

Lets take apart the first log entry in the example:

11/22/05 10:47:41,170 [6448] FATAL SugarCRM - Slow Query (time:0.031598

This shows the time and date when the query was executed. Then comes the common log statement to identify it as a slow query "FATAL SugarCRM - Slow Query".

SELECT count(*) FROM contacts LEFT JOIN users
                                ON contacts.assigned_user_id=users.id
                                LEFT JOIN accounts_contacts
                                ON contacts.id=accounts_contacts.contact_id  
                                LEFT JOIN accounts
                                ON accounts_contacts.account_id=accounts.id  LEFT JOIN teams ON contacts.team_id=teams.id AND (teams.deleted=0) where  contacts.deleted=0  AND (accounts.deleted is NULL or accounts.deleted=0)

This is the actual query that was executed against the database.

If you have a use case that is bad, turn on logging, clear the sugarcrm.log file, and perform the use case. Then copy the logfile. At this point, you should have a log of all the queries that took more that 1/10th of a second to execute along with the exact time of the query. These queries can be used to run explain plans for determining why the query is slow and hopefully optimizing indexes on the database.

Jacob

[goran]

Yup, we're using now this method like you already mentioned. Before we were using mysql logging...

this way it is a lot more efficient.

thanks
first two:

Thu Nov 24 16:20:36 2005,917 [3575] FATAL SugarCRM - Slow Query (time:1.005223
SELECT count(*) FROM accounts LEFT JOIN users
ON accounts.assigned_user_id=users.id where (accounts.assigned_user_id='1') AND accounts.deleted=0
Thu Nov 24 16:21:16 2005,718 [3575] FATAL SugarCRM - Slow Query (time:39.799844
SELECT
users.user_name assigned_user_name,
accounts.* FROM accounts LEFT JOIN users
ON accounts.assigned_user_id=users.id where (accounts.assigned_user_id='1') AND accounts.deleted=0 ORDER BY billing_address_city desc LIMIT 620260,20

[creos]

I'm seeing horrible performance as well... db server is a dual 3ghz xeon, 4gb ram.. absolutely no load.

Only seeing the problem with sugarcrm db.

Queries just seem to take *forever*. It takes 3-5 seconds to log in. 5+ seconds for portal to appear. With sample populated data.

Only thing here that may be different from a basic install (I haven't tested this scenerio) is that it's using mysql/tcp as the front-end webs are in a load balanced cluster.

I'm going to try setting it up directly and using the mysql socket to see if performance improves..

[Jacob]

Are you using MyISAM or InnoDB?

We actually are getting better performance with a separate DB server (under load).

Jacob

[atheimer98]

How much better performance are you getting from a seperate db server? We are running into slowdowns especially in saving calls area moving around between modules except calendar is still quite good.

[Jacob]

It really depends on what issues you are running into. For a low number of users, you might actually experience a small decrease in performance.

How many users do you have concurrently using the system?
Are you using MySQL (assuming)? If so, which database engine are you using (MyISAM or InnoDB)?

What Sugar Version are you using?

Jacob

[atheimer98]

We are using MyISAM with only 16 concurrent users. I believe Inno is the optimum choice correct?
We are running 4.2a currently.

[marlo]

Has there been any resolution with the slowness issue, especially in the saving calls area?

We are experiencing the same problems after we upgraded from 4.0.1 to 4.2. It was always somewhat slow, especially if you use IE, but now our support staff can hardly use it. It takes 30 - 40 seconds to save a call. It seems to be the scheduling/saving calls, sometimes emails that are the big problem, the rest of the modules are manageable. I have seen other people complain about the calls, there seems to be a problem. Has this been or will it be fixed in an patch or upgrade? If so, is there something I can do to speed things up now?

Any help is greatly appreciated.

Thanks,
Marlo

[jnassi]

Has there been any resolution with the slowness issue, especially in the saving calls area?

We are experiencing the same problems after we upgraded from 4.0.1 to 4.2. It was always somewhat slow, especially if you use IE, but now our support staff can hardly use it. It takes 30 - 40 seconds to save a call. It seems to be the scheduling/saving calls, sometimes emails that are the big problem, the rest of the modules are manageable. I have seen other people complain about the calls, there seems to be a problem. Has this been or will it be fixed in an patch or upgrade? If so, is there something I can do to speed things up now?

Any help is greatly appreciated.

Thanks,
Marlo

Marlo,

Specifically for calls, you can try this. In the file modules/Calls/Call.php, there's a line that reads:

	var $update_vcal = true;

Change the true to be false, and save the file. Now compare the time it takes for saving a call for your support staff.

The same workaround is valid for meetings, in the file modules/Meetings/Meeting.php.

See bug #6639 for the background information.

[wjohnson]

I must be missing something because turning on slow query logging with the above instructions (seems to be same info as on wiki) does not log anything in sugarcrm.log. I even tried the -1 setting to log all queries.

I'm using 4.5.1a. Anybody got any ideas?