Database performance can have a huge affect on the performance of a web application, especially one as large and complex as SugarCRM. Tuning your database to deal with Sugar’s many queries can have a huge impact on its performance. But how do you find out what exactly Sugar is doing, and which queries are causing a bottleneck?
Sugar comes with an option in the logging section of system settings called “log slow queries”. This option adds an extra entry to the log file when a query takes longer than a certain (configurable) threshold to execute. While this is useful to a point it doesn’t really help an admin to find out what queries are using up the most database time. For one thing some queries, while executing very quickly, are repeated many, many times. When you add these repetitions together they can amount to a surprisingly large amount of time.
I wanted a tool to give me a realistic analysis of the queries running on the various Sugar installations I deal with. Finding nothing available online I “rolled my own” and have decided to make my code available for others to use.
Here’s an example of the analysis from my script:
----- Query Analysis -----
sorting by: combined
log file used: fetch-cr.log
log entries read: 3126
max queries to display: 200
min time to displayed: 0.01
total queries: 537
unique queries: 203
slowest query: 0.429
slowest combination: 0.5058
average query time: 0.0078
average combined time: 0.0208
total unknown time: 0.0408
total db time: 4.2129
----- Query #1 ran 30 times ----- total: 0.5058 max: 0.429 avg: 0.0169 -----
LEFT JOIN contacts_cstm ON contacts.id = contacts_cstm.id_c
WHERE contacts_cstm.contact_type_c = 'Core'
WHERE cr_id = '5ead17bf-3c54-1a73-6f8d-4a4d74b9ffcb'
----- Query #2 ran 1 times ----- execution time: 0.1621 -----
select top 11 * from ((select tasks.id , tasks.name , tasks.status , isnull(contacts.first_name,'') + ' ' + isnull(contacts.last_name,'') contact_name , tasks.contact_id , '
That was an extract from the log when opening a detail view of an object in a custom module. From the analysis I could see that just over four seconds of the time taken to render the page was taken by database time. From that I was able to change some queries’ syntax to make them run faster, and add indexes and other optimisations to the database where queries couldn’t be changed, eventually cutting the db time down by almost 75%.
You may wonder what “unknown time” means in the statistics. This is db time accounted for by Sugar where no query was output to the log. For example, you’ll see entries like this in your log file:
03/29/11 11:03:55 [-none-][DEBUG] Ignoring this database message:
03/29/11 11:03:55 [-none-][INFO] Query Execution Time:0.021867036819458
The easiest way to get a log extract for a specific action (e.g. fetching a contact list) is as follows:
- delete the sugarcrm.log file
- perform the action (i.e. open the contact list view) in a browser
- rename the log file to something like contact-list.log
You can then run the analysis script against that particular log file using the -f parameter. Note that the script is currently only designed to handle Sugar’s standard log format.
The options available are:
- Sorting – sort by individual query time, combined time of repeated queries or number of times a query was run
- Untimed queries – include queries run where Sugar didn’t write a corresponding execution time to the log
- Thresholds – choose how many queries to display, and the minimum query time
Running the script
Before you begin you will need to set Sugar’s logging level to “debug” so that it logs the details for every query run.
The script needs to be run from a command line, as below:
./analyse_sugar_queries.php -f contact-list.log -s combined -mt 0.001
Download the script using the link below:
If you’d like to see any other features added to the script I’d love to hear about them, and any feedback on how the script has helped you analyse your SugarCRM queries 🙂