Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Same query, same system, different execution time

The queries below all execute instantly on our development server where as they can take upto 2 minutes 20 seconds.

The query execution time seems to be affected by home ambiguous the LIKE string's are. If they closely match a country that has few matches it will take less time, and if you use something like 'ge' for germany - it will take longer to execute. But this doesn't always work out like that, at times its quite erratic.

Sending data appears to be the culprit but why and what does that mean. Also memory on production looks to be quite low (free memory)?

Production:
Intel Quad Xeon E3-1220 3.1GHz
4GB DDR3
2x 1TB SATA in RAID1
Network speed 100Mb
Ubuntu

Development
Intel Core i3-2100, 2C/4T, 3.10GHz
500 GB SATA - No RAID
4GB DDR3

This query is NOT the query in question but is related so ill post it.

SELECT 
    f.form_question_has_answer_id 
FROM 
    form_question_has_answer f 
INNER JOIN 
    project_company_has_user p ON f.form_question_has_answer_user_id = p.project_company_has_user_user_id 
INNER JOIN 
    company c ON p.project_company_has_user_company_id = c.company_id 
INNER JOIN 
    project p2 ON p.project_company_has_user_project_id = p2.project_id 
INNER JOIN 
    user u ON p.project_company_has_user_user_id = u.user_id 
INNER JOIN 
    form f2 ON p.project_company_has_user_project_id = f2.form_project_id 
WHERE 
    (f2.form_template_name = 'custom' AND p.project_company_has_user_garbage_collection = 0 AND p.project_company_has_user_project_id = '29') AND (LCASE(c.company_country) LIKE '%ge%' OR LCASE(c.company_country) LIKE '%abcde%') AND f.form_question_has_answer_form_id = '174'

And the explain plan for the above query is, run on both dev and production produce the same plan.

+----+-------------+-------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+---------+----------------------------------------------------+------+-------------+
| id | select_type | table | type   | possible_keys                                                                                                                                | key                              | key_len | ref                                                | rows | Extra       |
+----+-------------+-------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+---------+----------------------------------------------------+------+-------------+
|  1 | SIMPLE      | p2    | const  | PRIMARY                                                                                                                                      | PRIMARY                          | 4       | const                                              |    1 | Using index |
|  1 | SIMPLE      | f     | ref    | form_question_has_answer_form_id,form_question_has_answer_user_id                                                                            | form_question_has_answer_form_id | 4       | const                                              |  796 | Using where |
|  1 | SIMPLE      | u     | eq_ref | PRIMARY                                                                                                                                      | PRIMARY                          | 4       | new_klarents.f.form_question_has_answer_user_id    |    1 | Using index |
|  1 | SIMPLE      | p     | ref    | project_company_has_user_unique_key,project_company_has_user_user_id,project_company_has_user_company_id,project_company_has_user_project_id | project_company_has_user_user_id | 4       | new_klarents.f.form_question_has_answer_user_id    |    1 | Using where |
|  1 | SIMPLE      | f2    | ref    | form_project_id                                                                                                                              | form_project_id                  | 4       | const                                              |   15 | Using where |
|  1 | SIMPLE      | c     | eq_ref | PRIMARY                                                                                                                                      | PRIMARY                          | 4       | new_klarents.p.project_company_has_user_company_id |    1 | Using where |
+----+-------------+-------+--------+----------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+---------+----------------------------------------------------+------+-------------+

This query takes 2 minutes ~20 seconds to execute.

The query that is ACTUALLY being run on the server is this one:

SELECT 
    COUNT(*) AS num_results 
FROM (SELECT 
        f.form_question_has_answer_id 
    FROM 
        form_question_has_answer f 
    INNER JOIN 
        project_company_has_user p ON f.form_question_has_answer_user_id = p.project_company_has_user_user_id 
    INNER JOIN 
        company c ON p.project_company_has_user_company_id = c.company_id 
    INNER JOIN 
        project p2 ON p.project_company_has_user_project_id = p2.project_id 
    INNER JOIN 
        user u ON p.project_company_has_user_user_id = u.user_id 
    INNER JOIN 
        form f2 ON p.project_company_has_user_project_id = f2.form_project_id 
    WHERE 
        (f2.form_template_name = 'custom' AND p.project_company_has_user_garbage_collection = 0 AND p.project_company_has_user_project_id = '29') AND (LCASE(c.company_country) LIKE '%ge%' OR LCASE(c.company_country) LIKE '%abcde%') AND f.form_question_has_answer_form_id = '174' 
    GROUP BY 
        f.form_question_has_answer_id;) dctrn_count_query;

With explain plans (again same on dev and production):

+----+-------------+-------+--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+---------+----------------------------------------------------+------+------------------------------+
    | id | select_type | table | type   | possible_keys                                                                                                                                                                            | key                              | key_len | ref                                                | rows | Extra                        |
    +----+-------------+-------+--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+---------+----------------------------------------------------+------+------------------------------+
    |  1 | PRIMARY     | NULL  | NULL   | NULL                                                                                                                                                                                     | NULL                             | NULL    | NULL                                               | NULL | Select tables optimized away |
    |  2 | DERIVED     | p2    | const  | PRIMARY                                                                                                                                                                                  | PRIMARY                          | 4       |                                                    |    1 | Using index                  |
    |  2 | DERIVED     | f     | ref    | form_question_has_answer_form_id,form_question_has_answer_user_id                                                                                                                        | form_question_has_answer_form_id | 4       |                                                    |  797 | Using where                  |
    |  2 | DERIVED     | p     | ref    | project_company_has_user_unique_key,project_company_has_user_user_id,project_company_has_user_company_id,project_company_has_user_project_id,project_company_has_user_garbage_collection | project_company_has_user_user_id | 4       | new_klarents.f.form_question_has_answer_user_id    |    1 | Using where                  |
    |  2 | DERIVED     | f2    | ref    | form_project_id                                                                                                                                                                          | form_project_id                  | 4       |                                                    |   15 | Using where                  |
    |  2 | DERIVED     | c     | eq_ref | PRIMARY                                                                                                                                                                                  | PRIMARY                          | 4       | new_klarents.p.project_company_has_user_company_id |    1 | Using where                  |
    |  2 | DERIVED     | u     | eq_ref | PRIMARY                                                                                                                                                                                  | PRIMARY                          | 4       | new_klarents.p.project_company_has_user_user_id    |    1 | Using where; Using index     |
    +----+-------------+-------+--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+---------+----------------------------------------------------+------+------------------------------+

On the production server the information I have is as follows.

Upon execution:

+-------------+
| num_results |
+-------------+
|           3 |
+-------------+
1 row in set (2 min 14.28 sec)

Show profile:

+--------------------------------+------------+
| Status                         | Duration   |
+--------------------------------+------------+
| starting                       |   0.000016 |
| checking query cache for query |   0.000057 |
| Opening tables                 |   0.004388 |
| System lock                    |   0.000003 |
| Table lock                     |   0.000036 |
| init                           |   0.000030 |
| optimizing                     |   0.000016 |
| statistics                     |   0.000111 |
| preparing                      |   0.000022 |
| executing                      |   0.000004 |
| Sorting result                 |   0.000002 |
| Sending data                   | 136.213836 |
| end                            |   0.000007 |
| query end                      |   0.000002 |
| freeing items                  |   0.004273 |
| storing result in query cache  |   0.000010 |
| logging slow query             |   0.000001 |
| logging slow query             |   0.000002 |
| cleaning up                    |   0.000002 |
+--------------------------------+------------+

On development the results are as follows.

+-------------+
| num_results |
+-------------+
|           3 |
+-------------+
1 row in set (0.08 sec)

Again the profile for this query:

+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000022 |
| checking query cache for query | 0.000148 |
| Opening tables                 | 0.000025 |
| System lock                    | 0.000008 |
| Table lock                     | 0.000101 |
| optimizing                     | 0.000035 |
| statistics                     | 0.001019 |
| preparing                      | 0.000047 |
| executing                      | 0.000008 |
| Sorting result                 | 0.000005 |
| Sending data                   | 0.086565 |
| init                           | 0.000015 |
| optimizing                     | 0.000006 |
| executing                      | 0.000020 |
| end                            | 0.000004 |
| query end                      | 0.000004 |
| freeing items                  | 0.000028 |
| storing result in query cache  | 0.000005 |
| removing tmp table             | 0.000008 |
| closing tables                 | 0.000008 |
| logging slow query             | 0.000002 |
| cleaning up                    | 0.000005 |
+--------------------------------+----------+

If i remove user and/or project innerjoins the query is reduced to 30s.

Last bit of information I have:

Mysqlserver and Apache are on the same box, there is only one box for production.

Production output from top: before & after.

top - 15:43:25 up 78 days, 12:11,  4 users,  load average: 1.42, 0.99, 0.78
Tasks: 162 total,   2 running, 160 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.1%us, 50.4%sy,  0.0%ni, 49.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   4037868k total,  3772580k used,   265288k free,   243704k buffers
Swap:  3905528k total,   265384k used,  3640144k free,  1207944k cached

top - 15:44:31 up 78 days, 12:13,  4 users,  load average: 1.94, 1.23, 0.87
Tasks: 160 total,   2 running, 157 sleeping,   0 stopped,   1 zombie
Cpu(s):  0.2%us, 50.6%sy,  0.0%ni, 49.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   4037868k total,  3834300k used,   203568k free,   243736k buffers
Swap:  3905528k total,   265384k used,  3640144k free,  1207804k cached

But this isn't a good representation of production's normal status so here is a grab of it from today outside of executing the queries.

top - 11:04:58 up 79 days,  7:33,  4 users,  load average: 0.39, 0.58, 0.76
Tasks: 156 total,   1 running, 155 sleeping,   0 stopped,   0 zombie
Cpu(s):  3.3%us,  2.8%sy,  0.0%ni, 93.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   4037868k total,  3676136k used,   361732k free,   271480k buffers
Swap:  3905528k total,   268736k used,  3636792k free,  1063432k cached

Development: This one doesn't change during or after.

top - 15:47:07 up 110 days, 22:11,  7 users,  load average: 0.17, 0.07, 0.06
Tasks: 210 total,   2 running, 208 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.1%us,  0.2%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   4111972k total,  1821100k used,  2290872k free,   238860k buffers
Swap:  4183036k total,    66472k used,  4116564k free,   921072k cached
like image 225
mr12086 Avatar asked Sep 12 '26 16:09

mr12086


1 Answers

If the slowness is intermittent, it's either server load or other resource contention (in your case, most likely memory). Your system needs to have enough RAM to store all of the indexes in memory at once, otherwise, it will have to swap out memory if the needed index isn't already loaded in RAM.

Your TOP results show that there is a low amount of RAM available.

Use the innodb_buffer_pool_size setting to configure the size of the buffer pool for InnoDB, and key_buffer_size for MyISAM. Ensure you set it high enough to hold all of the indexes in RAM at the same time, and that your system has enough RAM to accomplish this.

like image 179
Marcus Adams Avatar answered Sep 15 '26 07:09

Marcus Adams



Donate For Us

If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!