Wednesday, January 4, 2012

MySQL LIMIT slows down query with ORDER BY

Over the last few months I've had a slow query show up that was unexplained to why the results were so slow. Just today I finally had sometime to investigate the query. First, all of my servers are using the Percona Build with full slow query logging turn on, this is nice because you get details about why the query showed up in the slow query log. Before we look at the query, let me tell you what its for. This query is used for Dr name autocomplete within a X mile radius of a given zip code. Typically we have last and first name, however the cardinality at first is low. We start searching when the user types at least two characters. This doesn't do well with you last name is 'smith'.
Here is the query:
# Time: 120104  9:51:19
# User@Host: xxx[xxx] @  [xxxx]
# Thread_id: 4896448  Schema: xxx  Last_errno: 0  Killed: 0
# Query_time: 9.399905  Lock_time: 0.000081  Rows_sent: 1  Rows_examined: 2845320  Rows_affected: 0  Rows_read: 2
# Bytes_sent: 3987  Tmp_tables: 1  Tmp_disk_tables: 0  Tmp_table_sizes: 127800
# InnoDB_trx_id: D2B50B88
# QC_Hit: No  Full_scan: No  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: No
# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0
#   InnoDB_IO_r_ops: 4  InnoDB_IO_r_bytes: 65536  InnoDB_IO_r_wait: 0.015564
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 38054

SELECT 1 FROM users u INNER JOIN rxdb_v1.zip_100 z ON LEFT(u.zip,5)=z.toz AND z.fromz='46804' WHERE u.first_name LIKE 'Lisa%' AND last_name LIKE 'Gu%' AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') AND u.status!=0 GROUP BY u.user_id ORDER BY z.distance ASC, u.last_name ASC, u.first_name, u.user_id ASC LIMIT 50;
Lets look at query handler stats:
mysql> flush status;
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT u.user_id,u.revision_number,u.universal_id,u.dea_number,u.nat_pro_id,u.license_number,u.tax_id_number,u.status,u.username,u.alias,u.pin,u.password,u.pincode,u.realm,u.organization,u.last_name,u.last_name_phone,u.first_name,u.first_name_phone,u.middle_name,u.title,u.suffix,u.degree,u.address1,u.address2,u.city,u.state,u.zip,u.tz_id,u.home_phone,u.work_phone,u.cell_phone,u.cellco_id,u.fax_number,u.pager,u.email,u.preferred_alert_method,u.edited_by,u.edit_date,u.create_date,u.pwd_expire,u.login_expire,u.login_failcount,u.login_lastfailure,u.security_role_id,u.preferred_route,u.route_comment,u.preferred_route_detail,u.sig_storage_id,u.pic_storage_id,u.securityquestion,u.securityanswer,u.termschecked,u.terms_version,u.terms_dt,u.user_role_id,u.spi FROM users u INNER JOIN rxdb_v1.zip_100 z ON left(u.zip,5)=z.toz AND z.fromz='46804' WHERE u.first_name LIKE 'Lisa%' AND last_name LIKE 'G%' AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') AND u.status!=0 GROUP BY u.user_id ORDER BY z.distance ASC, u.last_name ASC, u.first_name, u.user_id ASC LIMIT 50;

...

10 rows in set (10.94 sec)

mysql>  show status like 'Handler%';
+----------------------------+---------+
| Variable_name              | Value   |
+----------------------------+---------+
| Handler_commit             | 1       |
| Handler_delete             | 0       |
| Handler_discover           | 0       |
| Handler_prepare            | 0       |
| Handler_read_first         | 1       |
| Handler_read_key           | 623     |
| Handler_read_next          | 2845328 |
| Handler_read_prev          | 0       |
| Handler_read_rnd           | 10      |
| Handler_read_rnd_next      | 11      |
| Handler_rollback           | 0       |
| Handler_savepoint          | 0       |
| Handler_savepoint_rollback | 0       |
| Handler_update             | 0       |
| Handler_write              | 10      |
+----------------------------+---------+
15 rows in set (0.00 sec)
  • There are 623 Handler_read_key, which means 623 index range scans where initiated.
  • There are 2845328 Handler_read_next, which means 2845328 rows were analyzed during this scan, ouch!
  • Handler_read_rnd=10 means there were 10 direct rows read for sorting.
  • and Handler_read_rnd_next=11 means that there were 11 times MySQL had to read the next row. This is an indication of poor indexing.
Why so many rows, lets do an explain on the query:
mysql> EXPLAIN SELECT 1 FROM users u INNER JOIN rxdb_v1.zip_100 z ON LEFT(u.zip,5)=z.toz AND z.fromz='46804' WHERE u.first_name LIKE 'Lisa%' AND last_name LIKE 'Gu%' AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') AND u.status!=0 GROUP BY u.user_id ORDER BY z.distance ASC, u.last_name ASC, u.first_name, u.user_id ASC LIMIT 50;
+----+-------------+-------+--------+------------------------------------------------------+---------+---------+------------+---------+----------------------------------------------+
| id | select_type | table | type   | possible_keys                                        | key     | key_len | ref        | rows    | Extra                                        |
+----+-------------+-------+--------+------------------------------------------------------+---------+---------+------------+---------+----------------------------------------------+
|  1 | SIMPLE      | u     | index  | idx5,idx4,first_name_idx,status_name,idx2,status_fax | PRIMARY | 4       | NULL       | 2881512 | Using where; Using temporary; Using filesort |
|  1 | SIMPLE      | z     | eq_ref | PRIMARY,distidx                                      | PRIMARY | 14      | const,func |       1 | Using where                                  |
+----+-------------+-------+--------+------------------------------------------------------+---------+---------+------------+---------+----------------------------------------------+
2 rows in set (0.00 sec)

The user's table has a plethora of indexes on it, 30 to be exact, to satisfy most if not all of the name autocomplete queries. However - why is this particular query using the users table Primary Key, which is the auto increment column named user_id? I can't help but think this query is doomed from the start, especially when its examining almost 3 million rows and looking at the Extra column, we have "Using where; Using temporary: Using filesort". MySQL is doing a lot of extra work to just return 1 row in the result.

How do we proceed? Personally I start by making the query as simple as possible by removing GROUP BY, ORDER BY and LIMIT's. (I can always hit ctrl+c to stop a large query result)

Lets start by removing the ORDER BY:
mysql> SELECT 1 FROM users u INNER JOIN rxdb_v1.zip_100 z ON LEFT(u.zip,5)=z.toz AND z.fromz='46804' WHERE u.first_name LIKE 'Lisa%' AND last_name LIKE 'Gu%' AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') AND u.status!=0 GROUP BY u.user_id LIMIT 50;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (2.78 sec)
Much better, we're only examining 6125 rows - however the query still takes 2.78 sec to complete, its better than 9 sec but not good enough yet. Lets remove the GROUP BY:
mysql> SELECT 1 FROM users u INNER JOIN rxdb_v1.zip_100 z ON LEFT(u.zip,5)=z.toz AND z.fromz='46804' WHERE u.first_name LIKE 'Lisa%' AND last_name LIKE 'Gu%' AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') AND u.status!=0 LIMIT 50;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.05 sec)
Interesting, more rows examined but the query returned 5/100 of a sec...What Gives? Lets run the query with the GROUP BY again, but without the LIMIT:
mysql> EXPLAIN SELECT 1 FROM users u INNER JOIN rxdb_v1.zip_100 z ON LEFT(u.zip,5)=z.toz AND z.fromz='46804' WHERE u.first_name LIKE 'Lisa%' AND last_name LIKE 'Gu%' AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') AND u.status!=0 GROUP BY u.user_id;
+----+-------------+-------+--------+------------------------------------------------------+---------+---------+------------+-------+----------------------------------------------+
| id | select_type | table | type   | possible_keys                                        | key     | key_len | ref        | rows  | Extra                                        |
+----+-------------+-------+--------+------------------------------------------------------+---------+---------+------------+-------+----------------------------------------------+
|  1 | SIMPLE      | u     | range  | idx5,idx4,first_name_idx,status_name,idx2,status_fax | idx5    | 204     | NULL       | 22344 | Using where; Using temporary; Using filesort |
|  1 | SIMPLE      | z     | eq_ref | PRIMARY,distidx                                      | PRIMARY | 14      | const,func |     1 | Using where; Using index                     |
+----+-------------+-------+--------+------------------------------------------------------+---------+---------+------------+-------+----------------------------------------------+
2 rows in set (0.00 sec)

mysql> SELECT 1 FROM users u INNER JOIN rxdb_v1.zip_100 z ON LEFT(u.zip,5)=z.toz AND z.fromz='46804' WHERE u.first_name LIKE 'Lisa%' AND last_name LIKE 'Gu%' AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') AND u.status!=0 GROUP BY u.user_id;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.05 sec)
Same result, is the GROUP BY + LIMIT the Problem? Lets now add the ORDER BY but exclude the LIMIT clause:
mysql> SELECT 1 FROM users u INNER JOIN rxdb_v1.zip_100 z ON LEFT(u.zip,5)=z.toz AND z.fromz='46804' WHERE u.first_name LIKE 'Lisa%' AND last_name LIKE 'Gu%' AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') AND u.status!=0 GROUP BY u.user_id ORDER BY z.distance ASC, u.last_name ASC, u.first_name, u.user_id ASC;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.05 sec
Same result! - must be the LIMIT.

So this is very interesting, LIMIT is causing some bad performance problems here why? I search around, and Peter Zaitsev blogged about ORDER BY ... LIMIT Performance Optimization

Rather than using a UNION like Peter suggest, lets rewrite this query as a derived table. What I'll do first is get a list of users base on the autocomplete search criteria. Note - we want to make the derived table as small as possible to reduce the required amount of memory needed for an in memory tmp table. I do this by only selecting the user_id and zip code. Then, I'll join to the zip_100 to limit the result and then left join to the users table again to get all of the column data.

The new and improved query:
mysql> flush status;
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT u.user_id,u.revision_number,u.universal_id,u.dea_number,u.nat_pro_id,u.license_number,u.tax_id_number,u.status,u.username,u.alias,u.pin,u.password,u.pincode,u.realm,u.organization,u.last_name,u.last_name_phone,u.first_name,u.first_name_phone,u.middle_name,u.title,u.suffix,u.degree,u.address1,u.address2,u.city,u.state,u.zip,u.tz_id,u.home_phone,u.work_phone,u.cell_phone,u.cellco_id,u.fax_number,u.pager,u.email,u.preferred_alert_method,u.edited_by,u.edit_date,u.create_date,u.pwd_expire,u.login_expire,u.login_failcount,u.login_lastfailure,u.security_role_id,u.preferred_route,u.route_comment,u.preferred_route_detail,u.sig_storage_id,u.pic_storage_id,u.securityquestion,u.securityanswer,u.termschecked,u.terms_version,u.terms_dt,u.user_role_id,u.spi 
FROM
(SELECT u.user_id,LEFT(u.zip,5) AS zip FROM users u 
 WHERE 
 u.first_name LIKE 'Lisa%'
 AND last_name LIKE 'G%' 
 AND u.realm IN ('Fax-MD/Clinics','Fax-Pharmacy (All)','Fax-Pharmacy (Local)','Fax-Hospitals','Fax-Locations','Fax-Dentists','Fax-Schools') 
 AND u.status!=0
 ORDER BY u.last_name, u.first_name
) AS ud
INNER JOIN rxdb_v1.zip_100 z ON z.toz=ud.zip AND z.fromz='46804'
LEFT JOIN users u ON u.user_id=ud.user_id
GROUP BY u.user_id ORDER BY z.distance LIMIT 50;

...

10 rows in set (0.07 sec)

mysql>  show status like 'Handler%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Handler_commit             | 1     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 0     |
| Handler_read_key           | 636   |
| Handler_read_next          | 14909 |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 10    |
| Handler_read_rnd_next      | 592   |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 590   |
+----------------------------+-------+
15 rows in set (0.00 sec)

Much better, only 7/100 of a sec.

Conclusion

In my case, to fix the problem in the application we simply removed the GROUP BY. However - there are cases were the GROUP BY is needed and the only real fix is to 1) do the sub select or 2) change the application to do two queries.

No comments:

Post a Comment