MySQL 100% CPU + Slow query - Not using index properly

Question

I'm using the RDS database from amazon with a some very big tables, and yesterday I started to face 100% CPU utilisation on the server and a bunch of slow query logs that were not happening before.

I tried to check the queries that were running and faced this result from the explain command

+----+-------------+-------------------------------+--------+----------------------------------------------------------------------------------------------+---------------------------------------+---------+-----------------------------------------------------------------+------+----------------------------------------------+
| id | select_type | table                         | type   | possible_keys                                                                                | key                                   | key_len | ref                                                             | rows | Extra                                        |
+----+-------------+-------------------------------+--------+----------------------------------------------------------------------------------------------+---------------------------------------+---------+-----------------------------------------------------------------+------+----------------------------------------------+
|  1 | SIMPLE      | businesses                    | const  | PRIMARY                                                                                      | PRIMARY                               | 4       | const                                                           |    1 | Using index; Using temporary; Using filesort |
|  1 | SIMPLE      | activities_businesses         | ref    | PRIMARY,index_activities_users_on_business_id,index_tweets_users_on_tweet_id_and_business_id | index_activities_users_on_business_id | 9       | const                                                           | 2252 | Using index condition; Using where           |
|  1 | SIMPLE      | activities_b_taggings_975e9c4 | ref    | taggings_idx                                                                                 | taggings_idx                          | 782     | const,myapp_production.activities_businesses.id,const           |    1 | Using index condition; Using where           |
|  1 | SIMPLE      | activities                    | eq_ref | PRIMARY,index_activities_on_created_at                                                       | PRIMARY                               | 8       | myapp_production.activities_businesses.activity_id              |    1 | Using where                                  |
+----+-------------+-------------------------------+--------+----------------------------------------------------------------------------------------------+---------------------------------------+---------+-----------------------------------------------------------------+------+----------------------------------------------+

Also checkin in the process list, I got something like this:

+----+-----------------+-------------------------------------+----------------------------+---------+------+--------------+------------------------------------------------------------------------------------------------------+
| Id | User            | Host                                | db                         | Command | Time | State        | Info                                                                                                 |
+----+-----------------+-------------------------------------+----------------------------+---------+------+--------------+------------------------------------------------------------------------------------------------------+
|  1 | my_app          | my_ip:57152                         | my_app_production          | Sleep   |    0 |              | NULL                                                                                                 |
|  2 | my_app          | my_ip:57153                         | my_app_production          | Sleep   |    2 |              | NULL                                                                                                 |
|  3 | rdsadmin        | localhost:49441                     | NULL                       | Sleep   |    9 |              | NULL                                                                                                 |
|  6 | my_app          | my_other_ip:47802                   | my_app_production          | Sleep   |  242 |              | NULL                                                                                                 |
|  7 | my_app          | my_other_ip:47807                   | my_app_production          | Query   |  231 | Sending data | SELECT my_fields...                                                                                  |
|  8 | my_app          | my_other_ip:47809                   | my_app_production          | Query   |  231 | Sending data | SELECT my_fields...                                                                                  |
|  9 | my_app          | my_other_ip:47810                   | my_app_production          | Query   |  231 | Sending data | SELECT my_fields...                                                                                  |
| 10 | my_app          | my_other_ip:47811                   | my_app_production          | Query   |  231 | Sending data | SELECT my_fields...                                                                                  |
| 11 | my_app          | my_other_ip:47813                   | my_app_production          | Query   |  231 | Sending data | SELECT my_fields...                                                                                  |
...

So based on the numbers, it looks like there is no reason to have a slow query, since the worst execution plan is the one that goes through 2k rows which is not much.

Edit 1

Another information that might be useful is the slow query_log

SET timestamp=1401457485;
SELECT my_query...
# User@Host: myapp[myapp] @ ip-10-195-55-233.ec2.internal [IP] Id: 435
# Query_time: 95.830497 Lock_time: 0.000178 Rows_sent: 0 Rows_examined: 1129387

Edit 2

After profiling, I got this result. The result have approximately 250 rows with two columns each.

+----------------------+----------+
| state                | duration |
+----------------------+----------+
| Sending data         |      272 |
| removing tmp table   |        0 |
| optimizing           |        0 |
| Creating sort index  |        0 |
| init                 |        0 |
| cleaning up          |        0 |
| executing            |        0 |
| checking permissions |        0 |
| freeing items        |        0 |
| Creating tmp table   |        0 |
| query end            |        0 |
| statistics           |        0 |
| end                  |        0 |
| System lock          |        0 |
| Opening tables       |        0 |
| logging slow query   |        0 |
| Sorting result       |        0 |
| starting             |        0 |
| closing tables       |        0 |
| preparing            |        0 |
+----------------------+----------+

Edit 3

Adding query as requested

SELECT activities.share_count, 
       activities.created_at 
FROM   `activities_businesses` 
       INNER JOIN `businesses` 
               ON `businesses`.`id` = `activities_businesses`.`business_id` 
       INNER JOIN `activities` 
               ON `activities`.`id` = `activities_businesses`.`activity_id` 
       JOIN taggings activities_b_taggings_975e9c4 
         ON activities_b_taggings_975e9c4.taggable_id = activities_businesses.id 
            AND activities_b_taggings_975e9c4.taggable_type = 
                'ActivitiesBusiness' 
            AND activities_b_taggings_975e9c4.tag_id = 104 
            AND activities_b_taggings_975e9c4.created_at >= 
                '2014-04-30 13:36:44' 
WHERE  ( businesses.id = 1 ) 
       AND ( activities.created_at > '2014-04-30 13:36:44' ) 
       AND ( activities.created_at < '2014-05-30 12:27:03' ) 
ORDER  BY activities.created_at; 

Edit 4

There may be a chance that the indexes are not being applied due to difference in column type between the taggings and the activities_businesses, on the taggable_id column.

mysql> SHOW COLUMNS FROM activities_businesses;
+-------------+------------+------+-----+---------+----------------+
| Field       | Type       | Null | Key | Default | Extra          |
+-------------+------------+------+-----+---------+----------------+
| id          | int(11)    | NO   | PRI | NULL    | auto_increment |
| activity_id | bigint(20) | YES  | MUL | NULL    |                |
| business_id | bigint(20) | YES  | MUL | NULL    |                |
+-------------+------------+------+-----+---------+----------------+
3 rows in set (0.01 sec)

mysql> SHOW COLUMNS FROM taggings;
+---------------+--------------+------+-----+---------+----------------+
| Field         | Type         | Null | Key | Default | Extra          |
+---------------+--------------+------+-----+---------+----------------+
| id            | int(11)      | NO   | PRI | NULL    | auto_increment |
| tag_id        | int(11)      | YES  | MUL | NULL    |                |
| taggable_id   | bigint(20)   | YES  |     | NULL    |                |
| taggable_type | varchar(255) | YES  |     | NULL    |                |
| tagger_id     | int(11)      | YES  |     | NULL    |                |
| tagger_type   | varchar(255) | YES  |     | NULL    |                |
| context       | varchar(128) | YES  |     | NULL    |                |
| created_at    | datetime     | YES  |     | NULL    |                |
+---------------+--------------+------+-----+---------+----------------+

So it is examining way more rows than it shows in the explain query, probably because some indexes are not being applied.

Do you guys can help m with that?

Murchison

Why don't you post the query? – Univalent

Any thoughts after the last edit adding the query? – Murchison

My first try would be move this "AND activities_b_taggings_975e9c4.taggable_type = 'ActivitiesBusiness' AND activities_b_taggings_975e9c4.tag_id = 104 AND activities_b_taggings_975e9c4.created_at >= '2014-04-30 13:36:44'" to the WHERE Instead of the ON clause. Any difference? – Univalent

Also do you have any tools to see if index are used correctly or MYSQL does a table Scan? – Univalent

@Univalent I don't think moving the WHERE instead of On would have any impact. Also this is not generated by me, but by the Rails gem itself, so I don't want to go in that direction from beggining. – Murchison

@Univalent Yes, checking if it is doing table scan instead of indexing is nice, do you have any thoughts on how to do that? – Murchison

Well depends on you DBMS. In sure MYSQL it seems to be a product call "mysql query analizer" to do that. Also you should "play" with the query yourself (it doesn't matter how generate it) to see where the performance issue is. – Univalent

How many rows are being returned? – Rotator

Answer 1

As I was expecting in the 4th edit, there was a misleading information that MySQL was providing with the DESCRIBE command.

Even though the execution plan provided by the command was telling that it would be as following:

+----+-------------+-------------------------------+--------+----------------------------------------------------------------------------------------------+---------------------------------------+---------+-----------------------------------------------------------------+------+----------------------------------------------+
| id | select_type | table                         | type   | possible_keys                                                                                | key                                   | key_len | ref                                                             | rows | Extra                                        |
+----+-------------+-------------------------------+--------+----------------------------------------------------------------------------------------------+---------------------------------------+---------+-----------------------------------------------------------------+------+----------------------------------------------+
|  1 | SIMPLE      | businesses                    | const  | PRIMARY                                                                                      | PRIMARY                               | 4       | const                                                           |    1 | Using index; Using temporary; Using filesort |
|  1 | SIMPLE      | activities_businesses         | ref    | PRIMARY,index_activities_users_on_business_id,index_tweets_users_on_tweet_id_and_business_id | index_activities_users_on_business_id | 9       | const                                                           | 2252 | Using index condition; Using where           |
|  1 | SIMPLE      | activities_b_taggings_975e9c4 | ref    | taggings_idx                                                                                 | taggings_idx                          | 782     | const,myapp_production.activities_businesses.id,const           |    1 | Using index condition; Using where           |
|  1 | SIMPLE      | activities                    | eq_ref | PRIMARY,index_activities_on_created_at                                                       | PRIMARY                               | 8       | myapp_production.activities_businesses.activity_id              |    1 | Using where                                  |
+----+-------------+-------------------------------+--------+----------------------------------------------------------------------------------------------+---------------------------------------+---------+-----------------------------------------------------------------+------+----------------------------------------------+

Clearly that was not what was happening, since in the slow query we could see the amount of rows examined was much greater.

# Query_time: 95.830497 Lock_time: 0.000178 Rows_sent: 0 Rows_examined: 1129387

With that information in hand, it was possible to verify the joins and find that the ids in the tables were not using the same type:

mysql> SHOW COLUMNS FROM activities_businesses;
+-------------+------------+------+-----+---------+----------------+
| Field       | Type       | Null | Key | Default | Extra          |
+-------------+------------+------+-----+---------+----------------+
| id          | int(11)    | NO   | PRI | NULL    | auto_increment |
3 rows in set (0.01 sec)

mysql> SHOW COLUMNS FROM taggings;
+---------------+--------------+------+-----+---------+----------------+
| Field         | Type         | Null | Key | Default | Extra          |
+---------------+--------------+------+-----+---------+----------------+
| id            | int(11)      | NO   | PRI | NULL    | auto_increment |

Researching a little bit about the subject , it was easy to state that MySQL don't index columns of different types, or at least not properly, even though the EXPLAIN command would say that.

Joining on columns of different type?

Performance of JOIN using columns of different numeric types

So finally after making the changes to turn both columns into the same type, the queries started to perform better then 50ms, that is good enough for my scenario.

Murchison

Answer 2

i suspect the order by clause is the culprit. Try a couple of things. Add an index to the created_at column. If that works, great, read no further! Else, (or if it worked and you want an even faster query) Run this query, see if it takes longer to execute:

SELECT activities.share_count, 
       activities.created_at 
FROM   `activities`  
       JOIN `businesses` 
               ON `businesses`.`id` = `activities_businesses`.`business_id` 
       JOIN `activities_businesses`
               ON `activities`.`id` = `activities_businesses`.`activity_id` 
       JOIN taggings activities_b_taggings_975e9c4 
         ON activities_b_taggings_975e9c4.taggable_id = activities_businesses.id 
            AND activities_b_taggings_975e9c4.taggable_type = 
                'ActivitiesBusiness' 
            AND activities_b_taggings_975e9c4.tag_id = 104 
            AND activities_b_taggings_975e9c4.created_at >= 
                '2014-04-30 13:36:44' 
WHERE  ( businesses.id = 1 ) 
       AND ( activities.created_at > '2014-04-30 13:36:44' ) 
       AND ( activities.created_at < '2014-05-30 12:27:03' ) 
ORDER  BY activities.created_at; 

If that solves it, great!

Else, (or if the previous suggestions worked and you want an even even faster faster query) do the following two step process: 1. run the same query without the order by clause:

SELECT activities.share_count, 
       activities.created_at 
FROM   `activities`  
       JOIN `businesses` 
               ON `businesses`.`id` = `activities_businesses`.`business_id` 
       JOIN `activities_businesses`
               ON `activities`.`id` = `activities_businesses`.`activity_id` 
       JOIN taggings activities_b_taggings_975e9c4 
         ON activities_b_taggings_975e9c4.taggable_id = activities_businesses.id 
            AND activities_b_taggings_975e9c4.taggable_type = 
                'ActivitiesBusiness' 
            AND activities_b_taggings_975e9c4.tag_id = 104 
            AND activities_b_taggings_975e9c4.created_at >= 
                '2014-04-30 13:36:44' 
WHERE  ( businesses.id = 1 ) 
       AND ( activities.created_at > '2014-04-30 13:36:44' ) 
       AND ( activities.created_at < '2014-05-30 12:27:03' ) 

If that executes super duper fast, great. Dump the result of this into a temporary table, and sort on that. This breaks down your expensive operation into smaller ones that are easier for the server to execute, i.e.

CREATE TEMPORARY TABLE temp_activities (INDEX(created_at))
SELECT activities.share_count, 
           activities.created_at 
    FROM   `activities`  
           JOIN `businesses` 
                   ON `businesses`.`id` = `activities_businesses`.`business_id` 
           JOIN `activities_businesses`
                   ON `activities`.`id` = `activities_businesses`.`activity_id` 
           JOIN taggings activities_b_taggings_975e9c4 
             ON activities_b_taggings_975e9c4.taggable_id = activities_businesses.id 
                AND activities_b_taggings_975e9c4.taggable_type = 
                    'ActivitiesBusiness' 
                AND activities_b_taggings_975e9c4.tag_id = 104 
                AND activities_b_taggings_975e9c4.created_at >= 
                    '2014-04-30 13:36:44' 
    WHERE  ( businesses.id = 1 ) 
           AND ( activities.created_at > '2014-04-30 13:36:44' ) 
           AND ( activities.created_at < '2014-05-30 12:27:03' );
SELECT * FROM temp_activities ORDER BY created_at;

Cota

Clearly the problem was not in the query, since the execution plan was properly indexed accordingly with the EXPLAIN command. – Murchison