环境说明：
版本' Ver 8.42 Distrib 5.5.27, for Linux on x86_64 Table 为 innodb 引擎
1.原始sql的执行计划
(这条sql导致了mysql的性能问题，当它并发多条执行的时候影响其它正常sql的执行，大量sending data以及copying to tmp table等待)mysql> set profiling=1;Query OK, 0 rows affected (0.00 sec)
mysql> show profiles;
Empty set (0.00 sec)
mysql> explain
-> SELECT a.tid, a.subject,a.dateline,a.fid,b.message
-> FROM forum_thread AS a
-> LEFT JOIN forum_post_8 AS b ON a.tid = b.tid
-> WHERE a.highlight!=0 AND b.first=1 AND a.fid=113 AND b.invisible=0
-> ORDER BY a.dateline DESC
-> LIMIT 0,5;
+----+-------------+-------+--------+------------------------------+-----------+---------+-------------+-------+----------------------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+-------+--------+------------------------------+-----------+---------+-------------+-------+----------------------------------------------+
| 1 | SIMPLE | b | ref | invisible,displayorder,first | invisible | 1 | const | 97042 | Using where; Using temporary; Using filesort |
| 1 | SIMPLE | a | eq_ref | PRIMARY,displayorder,typeid | PRIMARY | 8 | forum.b.tid | 1 | Using where |
+----+-------------+-------+--------+------------------------------+-----------+---------+-------------+-------+----------------------------------------------+
2 rows in set (1.29 sec)
mysql> SELECT a.tid, a.subject,a.dateline,a.fid,b.message
-> FROM forum_thread AS a
-> LEFT JOIN forum_post_8 AS b ON a.tid = b.tid
-> WHERE a.highlight!=0 AND b.first=1 AND a.fid=113 AND b.invisible=0
-> ORDER BY a.dateline DESC
-> LIMIT 0,5;
执行这条SQL后，总耗时为 52s 查看具体步骤的耗时
mysql> show profiles;
+----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 1 | 1.28875000 | explain
SELECT a.tid, a.subject,a.dateline,a.fid,b.message
FROM forum_thread AS a
LEFT JOIN forum_post_8 AS b ON a.tid = b.tid
WHERE a.highlight!=0 AND b.first=1 AND a.fid=113 AND b.invisible=0
ORDER BY a.dateline DESC
LIMIT 0,5 |
| 2 | 52.027014 | SELECT a.tid, a.subject,a.dateline,a.fid,b.message
FROM forum_thread AS a
LEFT JOIN forum_post_8 AS b ON a.tid = b.tid
WHERE a.highlight!=0 AND b.first=1 AND a.fid=113 AND b.invisible=0
ORDER BY a.dateline DESC
LIMIT 0,5 | |
+----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)
mysql> show profile cpu,block io,memory,swaps for query 2;
+--------------------------------+-----------+----------+------------+--------------+---------------+-------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | Swaps |
+--------------------------------+-----------+----------+------------+--------------+---------------+-------+
| starting | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking query cache for query | 0.000083 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking permissions | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking permissions | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Opening tables | 0.000020 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| System lock | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| init | 0.000038 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| optimizing | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| statistics | 0.000113 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| preparing | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Creating tmp table | 0.000162 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| executing | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Copying to tmp table | 52.027014 | 4.992241 | 1.324799 | 0 | 0 | 0 |
| Sorting result | 0.000066 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.000218 | 0.000000 | 0.000999 | 0 | 0 | 0 |
| end | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| removing tmp table | 0.000093 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| query end | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| storing result in query cache | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| logging slow query | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| logging slow query | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| cleaning up | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
+--------------------------------+-----------+----------+------------+--------------+---------------+-------+
31 rows in set (0.00 sec)
mysql> show profile cpu,CONTEXT SWITCHES,PAGE FAULTS for query 2;+--------------------------------+-----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Page_faults_major | Page_faults_minor |
+--------------------------------+-----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
| starting | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| checking query cache for query | 0.000083 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| checking permissions | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| checking permissions | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Opening tables | 0.000020 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| System lock | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| init | 0.000038 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| optimizing | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| statistics | 0.000113 | 0.000000 | 0.000000 | 0 | 0 | 0 | 1 |
| preparing | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Creating tmp table | 0.000162 | 0.000000 | 0.000000 | 0 | 0 | 0 | 5 |
| executing | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Copying to tmp table | 52.027014 | 4.992241 | 1.324799 | 17969 | 1828 | 1 | 251431 |
| Sorting result | 0.000066 | 0.000000 | 0.000000 | 0 | 0 | 0 | 14 |
| Sending data | 0.000218 | 0.000000 | 0.000999 | 0 | 1 | 0 | 1 |
| end | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| removing tmp table | 0.000093 | 0.000000 | 0.000000 | 0 | 0 | 0 | 1 |
| end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| query end | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| freeing items | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| freeing items | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | 0 | 4 |
| Waiting for query cache lock | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| freeing items | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| storing result in query cache | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| cleaning up | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
+--------------------------------+-----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
31 rows in set (0.00 sec)
同时可以用iostat看到硬盘的IO rkB/s 非常高
# iostat -x /dev/sda8 2 10
Linux 2.6.18-164.el5 (photo) 01/15/2013
avg-cpu: %user %nice %sys %iowait %idle
0.68 0.00 0.29 0.44 98.59
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 46.27 0.00 344.28 0.00 39323.38 0.00 19661.69 0.00 114.22 2.41 6.92 2.89 99.45
avg-cpu: %user %nice %sys %iowait %idle
1.12 0.00 0.94 11.18 86.76
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 31.84 1.00 327.86 1.00 32636.82 15.92 16318.41 7.96 99.29 2.30 7.02 3.02 99.45
avg-cpu: %user %nice %sys %iowait %idle
1.50 0.00 1.06 10.94 86.50
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 83.92 0.00 348.74 0.00 43907.54 0.00 21953.77 0.00 125.90 2.47 7.10 2.88 100.55
avg-cpu: %user %nice %sys %iowait %idle
1.62 0.00 1.12 11.62 85.63
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 64.18 0.00 365.17 0.00 49532.34 0.00 24766.17 0.00 135.64 2.42 6.63 2.72 99.45
avg-cpu: %user %nice %sys %iowait %idle
0.50 0.00 0.88 11.44 87.19
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 6.03 1.01 345.73 1.01 9543.72 16.08 4771.86 8.04 27.57 1.21 3.49 2.86 99.25
2.第一次改写SQL
mysql> explain select AA.*,b.message from (select a.tid, a.subject,a.dateline,a.fidfrom forum_thread AS a
where a.highlight!=0 AND a.fid =113) AA
LEFT JOIN
forum_post_8 AS b ON AA.tid = b.tid
where b.first=1 and b.invisible=0
order by AA.dateline desc ;
+----+-------------+------------+------+------------------------------+--------------+---------+--------------+--------+----------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+------------+------+------------------------------+--------------+---------+--------------+--------+----------------+
| 1 | PRIMARY | <derived2> | ALL | NULL | NULL | NULL | NULL | 99 | Using filesort |
| 1 | PRIMARY | b | ref | invisible,displayorder,first | displayorder | 9 | AA.tid,const | 1 | Using where |
| 2 | DERIVED | a | ref | displayorder,typeid | typeid | 8 | | 108440 | Using where |
+----+-------------+------------+------+------------------------------+--------------+---------+--------------+--------+----------------+
typeid的索引是(fid+typeid)的组合索引
执行改写后的SQL后查看执行耗时情况
mysql> show profiles;
+----------+-------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 1 | 20.36569700 | select * from (select a.tid, a.subject,a.dateline,a.fid
from forum_thread AS a
where a.highlight!=0 AND a.fid =113) AA
LEFT JOIN
forum_post_8 AS b ON AA.tid = b.tid
where b.first=1 and b.invisible=0
order by AA.dateline desc |
+----------+-------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
mysql> show profile for query 1;
mysql> show profile cpu,block io,memory,swaps for query 1;
+--------------------------------+-----------+----------+------------+--------------+---------------+-------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | Swaps |
+--------------------------------+-----------+----------+------------+--------------+---------------+-------+
| starting | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking query cache for query | 0.000127 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Opening tables | 4.817902 | 0.045993 | 0.010998 | 0 | 0 | 0 |
| System lock | 0.021866 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| optimizing | 0.000024 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| statistics | 0.507939 | 0.004000 | 0.002000 | 0 | 0 | 0 |
| preparing | 0.000038 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 25.623515 | 1.406786 | 0.519921 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| init | 0.000049 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| optimizing | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| statistics | 0.198725 | 0.001000 | 0.000000 | 0 | 0 | 0 |
| preparing | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| executing | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sorting result | 0.000062 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.998911 | 0.003999 | 0.004999 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 1.061145 | 0.001000 | 0.003000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.008693 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| query end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| closing tables | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| removing tmp table | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| storing result in query cache | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| logging slow query | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| logging slow query | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| cleaning up | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
+--------------------------------+-----------+----------+------------+--------------+---------------+-------+
39 rows in set (0.00 sec)
mysql> show profile cpu,CONTEXT SWITCHES,PAGE FAULTS for query 1;
+--------------------------------+-----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Page_faults_major | Page_faults_minor |
+--------------------------------+-----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
| starting | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | 0 | 1 |
| Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| checking query cache for query | 0.000127 | 0.000000 | 0.000000 | 0 | 0 | 0 | 30 |
| checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Opening tables | 4.817902 | 0.045993 | 0.010998 | 374 | 3 | 1 | 998 |
| System lock | 0.021866 | 0.000000 | 0.000000 | 1 | 0 | 1 | 33 |
| optimizing | 0.000024 | 0.000000 | 0.000000 | 0 | 0 | 0 | 10 |
| statistics | 0.507939 | 0.004000 | 0.002000 | 37 | 0 | 1 | 120 |
| preparing | 0.000038 | 0.000000 | 0.000000 | 0 | 0 | 0 | 10 |
| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 1 |
| Sending data | 25.623515 | 1.406786 | 0.519921 | 13625 | 158 | 0 | 74911 |
| Waiting for query cache lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sending data | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| init | 0.000049 | 0.000000 | 0.000000 | 0 | 0 | 0 | 1 |
| optimizing | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | 0 | 1 |
| statistics | 0.198725 | 0.001000 | 0.000000 | 11 | 0 | 0 | 45 |
| preparing | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| executing | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sorting result | 0.000062 | 0.000000 | 0.000000 | 0 | 0 | 0 | 4 |
| Sending data | 0.998911 | 0.003999 | 0.004999 | 46 | 0 | 0 | 131 |
| Waiting for query cache lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sending data | 1.061145 | 0.001000 | 0.003000 | 36 | 0 | 0 | 119 |
| Waiting for query cache lock | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sending data | 0.008693 | 0.000000 | 0.000000 | 2 | 3 | 0 | 8 |
| end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| query end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| closing tables | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| removing tmp table | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| freeing items | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | 0 | 2 |
| Waiting for query cache lock | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| freeing items | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| freeing items | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| storing result in query cache | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| cleaning up | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
+--------------------------------+-----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
39 rows in set (0.00 sec)
同样在iostat看到 磁盘IO read 仍然比较高，但队列长度avgrq-sz比之前小。Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 48.50 7.00 879.00 6.00 48036.00 104.00 24018.00 52.00 54.40 4.39 4.82 1.13 100.05
avg-cpu: %user %nice %sys %iowait %idle
0.50 0.00 0.94 11.06 87.50
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 15.00 0.00 524.00 0.00 20740.00 0.00 10370.00 0.00 39.58 3.41 6.69 1.91 100.05
avg-cpu: %user %nice %sys %iowait %idle
0.12 0.00 0.75 11.62 87.51
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 3.50 0.00 328.00 0.00 8108.00 0.00 4054.00 0.00 24.72 2.99 9.18 3.05 100.05
avg-cpu: %user %nice %sys %iowait %idle
0.25 0.00 0.81 11.44 87.50
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda8 3.00 4.00 432.50 1.00 13496.00 40.00 6748.00 20.00 31.22 3.13 7.22 2.31 100.05
3.第二次改写SQL
对sql进行进一步分析
子查询的执行时间其实还有优化的余地，首先看了下子查询中的数据分别情况mysql> select a.highlight,count(*) from forum_thread AS a group by a.highlight;
+-----------+----------+
| highlight | count(*) |
+-----------+----------+
| 0 | 1522463 |
| 1 | 5576 |
| 2 | 13 |
| 3 | 1 |
| 4 | 9 |
| 5 | 9 |
| 6 | 1 |
| 7 | 7 |
| 8 | 5 |
| 40 | 2 |
| 41 | 55 |
| 42 | 31 |
| 43 | 7 |
| 44 | 34 |
| 45 | 25 |
| 46 | 1 |
| 47 | 2 |
| 48 | 5 |
| 63 | 1 |
| 70 | 1 |
| 127 | 6 |
+-----------+----------+
21 rows in set (18.71 sec)
mysql> select fid,count(*) from forum_thread group by fid order by 2 desc;
+------+----------+
| fid | count(*) |
+------+----------+
| 1233 | 370531 |
| 273 | 165592 |
| 268 | 69730 |
| 266 | 62790 |
| 255 | 49992 |
| 1118 | 47293 |
| 113 | 44690 |
| 147 | 44318 |
| 252 | 43084 |
| 253 | 35864 |
| 114 | 33344 |
| 1170 | 24051 |
| 1230 | 23133 |
| 269 | 21613 |
| 254 | 20629 |
| 256 | 19073 |
| 1182 | 17588 |
可以看到其实 highlight !=0 这个结果集是非常小的，如果有fid+highlight 的组合索引的话，子查询select a.tid, a.subject,a.dateline,a.fid
from forum_thread AS a
where a.highlight!=0 AND a.fid =113 的索引范围扫描的结果集会非常小，比起原来只有fid的索引，需要回表过滤highlight=0的rows效率要高不少。于是建立索引ALTER TABLE `forum_thread` ADD INDEX `fid_high` (`fid`, `highlight`);
----这时第2步改写的sql的执行计划变为了：mysql> explain select AA.*,b.message from (select a.tid, a.subject,a.dateline,a.fid
-> from forum_thread AS a
-> where a.highlight!=0 AND a.fid =113) AA
-> LEFT JOIN
-> forum_post_8 AS b ON AA.tid = b.tid
-> where b.first=1 and b.invisible=0
-> order by AA.dateline desc ;
+----+-------------+------------+-------+------------------------------+--------------+---------+--------------+------+----------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+------------+-------+------------------------------+--------------+---------+--------------+------+----------------+
| 1 | PRIMARY | <derived2> | ALL | NULL | NULL | NULL | NULL | 99 | Using filesort |
| 1 | PRIMARY | b | ref | invisible,displayorder,first | displayorder | 9 | AA.tid,const | 1 | Using where |
| 2 | DERIVED | a | range | displayorder,typeid,fid_high | fid_high | 9 | NULL | 100 | Using where |
+----+-------------+------------+-------+------------------------------+--------------+---------+--------------+------+----------------+
3 rows in set (0.00 sec)
--执行一次这条sql后查看执行的具体时间耗时情况mysql> show profiles;
+----------+------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 1 | 2.07984400 | select * from (select a.tid, a.subject,a.dateline,a.fid
from forum_thread AS a
where a.highlight>0 AND a.fid =113) AA
LEFT JOIN
forum_post_8 AS b ON AA.tid = b.tid
where b.first=1 and b.invisible=0
order by AA.dateline desc |
+----------+------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
执行时间是2smysql> show profile cpu,block io,memory,swaps for query 1;
+--------------------------------+----------+----------+------------+--------------+---------------+-------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | Swaps |
+--------------------------------+----------+----------+------------+--------------+---------------+-------+
| starting | 0.000022 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking query cache for query | 0.000105 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| checking permissions | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Opening tables | 1.222125 | 0.027996 | 0.007999 | 0 | 0 | 0 |
| System lock | 0.000240 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| optimizing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| statistics | 0.124458 | 0.001000 | 0.002000 | 0 | 0 | 0 |
| preparing | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| executing | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.450222 | 0.007999 | 0.009998 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.000034 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| init | 0.000220 | 0.000999 | 0.000000 | 0 | 0 | 0 |
| optimizing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| statistics | 0.025380 | 0.000000 | 0.001000 | 0 | 0 | 0 |
| preparing | 0.000024 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| executing | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sorting result | 0.000054 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.154623 | 0.003000 | 0.001000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.101302 | 0.003999 | 0.002000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Sending data | 0.000834 | 0.001000 | 0.000000 | 0 | 0 | 0 |
| end | 0.000063 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| query end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| closing tables | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| removing tmp table | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000014 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| freeing items | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| storing result in query cache | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| logging slow query | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 |
| cleaning up | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 |
+--------------------------------+----------+----------+------------+--------------+---------------+-------+
38 rows in set (0.00 sec)mysql> show profile cpu,CONTEXT SWITCHES,PAGE FAULTS for query 1;
+--------------------------------+----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Page_faults_major | Page_faults_minor |
+--------------------------------+----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
| starting | 0.000022 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| checking query cache for query | 0.000105 | 0.000000 | 0.000000 | 0 | 0 | 0 | 4 |
| checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| checking permissions | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Opening tables | 1.222125 | 0.027996 | 0.007999 | 378 | 0 | 0 | 986 |
| System lock | 0.000240 | 0.000000 | 0.000000 | 0 | 0 | 0 | 4 |
| optimizing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| statistics | 0.124458 | 0.001000 | 0.002000 | 36 | 0 | 0 | 102 |
| preparing | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | 0 | 1 |
| executing | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sending data | 0.450222 | 0.007999 | 0.009998 | 158 | 0 | 0 | 480 |
| Waiting for query cache lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sending data | 0.000034 | 0.000000 | 0.000000 | 0 | 0 | 0 | 2 |
| init | 0.000220 | 0.000999 | 0.000000 | 0 | 0 | 0 | 3 |
| optimizing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| statistics | 0.025380 | 0.000000 | 0.001000 | 9 | 0 | 0 | 37 |
| preparing | 0.000024 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| executing | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sorting result | 0.000054 | 0.000000 | 0.000000 | 0 | 0 | 0 | 3 |
| Sending data | 0.154623 | 0.003000 | 0.001000 | 46 | 0 | 0 | 136 |
| Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sending data | 0.101302 | 0.003999 | 0.002000 | 31 | 0 | 0 | 115 |
| Waiting for query cache lock | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Sending data | 0.000834 | 0.001000 | 0.000000 | 1 | 0 | 0 | 8 |
| end | 0.000063 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| query end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| closing tables | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| removing tmp table | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| closing tables | 0.000010 | 0.000000 | 0.000000 | 1 | 0 | 0 | 0 |
| freeing items | 0.000014 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| Waiting for query cache lock | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| freeing items | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 | 1 |
| Waiting for query cache lock | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| freeing items | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| storing result in query cache | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000001 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
| cleaning up | 0.000002 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 |
+--------------------------------+----------+----------+------------+-------------------+---------------------+-------------------+-------------------+
38 rows in set (0.00 sec)
最终这条sql的执行时间由最初的50s 优化到2s
4.结论
处理Copying to tmp table除了调整mysql的参数tmp_table_size，（这个参数的意思具体见http://dev.mysql.com/doc/refman/5.5/en/server-system-variables.html#sysvar_tmp_table_size）更重要的是优化sql，减少IO读写。其实调整tmp_table_size的意义也仅仅在于调整后尽量不写on-disk table，对于很高的read I/O 导致的性能问题帮助并不大。根据mysql手册上面所说的http://dev.mysql.com/doc/refman/5.5/en/general-thread-states.html
Copying to tmp tableThe server is copying to a temporary table in memory.当mysql出现Copying to tmp table的事件的时候首先mysql引擎将数据写入内存里的临时表，这个临时表的大小由参数tmp_table_size决定，事实上另外一个参数max_heap_table_size 也会对实际的临时表的大小有影响，实际值会取这2个参数中最小的那个。如果需要的的临时表大小超过了tmp_table_size，则写到硬盘上的"on-disk
MyISAM table"上,这个时候iostat会出现比较高的wkB/s当有多条sql都同时出现Copying to tmp table的时候，服务器的IO带来非常大的压力，这时基本上其它正常的sql都会由于IO的竞争变得非常慢，阻塞了其它sql执行，表现到应用层面上就是相关的页面打不开，数据查询显示不出来。大量的sending data以及copying to tmp table等待
关于Copying to tmp table的介绍的一篇文章http://www.dbtuna.com/article/55/Copying_to_tmp_table_-_MySQL_thread_states
备注1：show profile 参数
ALL - displays all informationBLOCK IO - displays counts for block input and output operations
CONTEXT SWITCHES - displays counts for voluntary and involuntary context switches
IPC - displays counts for messages sent and received
MEMORY - is not currently implemented
PAGE FAULTS - displays counts for major and minor page faults
SOURCE - displays the names of functions from the source code, together with the name and line number of the file in which the function occurs
SWAPS - displays swap counts
mysql> show variables like 'profiling_history_size'
-> ;
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| profiling_history_size | 15 |
+------------------------+-------+
1 row in set (0.00 sec)
mysql> show variables like '%profiling%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES |
| profiling | OFF |
| profiling_history_size | 15 |
+------------------------+-------+
3 rows in set (0.00 sec)
mysql> set profiling=1; #开启
备注2. mysql profile 相关介绍
A voluntary context switch occurs when a thread gives up the CPU it is running on voluntarily, either by a specialized call (sched_yield() or similar) or by starting waiting (e.g. a blocking I/O call).
Contrast with the involuntary context switch.An involuntary context switch means that the kernel takes away the CPU from a running process to assign it to another process. This can occur because:
- The process was already running for too long.
- A process with higher priority needs the CPU right now.
Technically this is done by a hardware interrupt that passes control to the kernel which then passes the control to another chosen process.----------------------------------------------page_fault
Minor
If the page is loaded in memory at the time the fault is generated, but is not marked in the memory management unit as being loaded in memory, then it is called a minor or soft page fault. The page fault handler in the operating system merely needs to make the entry for that page in the memory management unit point to the page in memory and indicate that the page is loaded in memory; it does not need to read the page into memory. This could happen if the memory is shared by different programs and the page is already brought into memory for other programs. The page could also have been removed from a process's Working Set, but not yet written to disk or erased, such as in operating systems that use Secondary Page Caching. For example, HP OpenVMS may remove a page that does not need to be written to disk (if it has remained unchanged since it was last read from disk, for example) and place it on a Free Page List if the working set is deemed too large. However, the page contents are not overwritten until the page is assigned elsewhere, meaning it is still available if it is referenced by the original process before being allocated. Since these faults do not involve disk latency, they are faster and less expensive than major page faults.
Major
If the page is not loaded in memory at the time the fault is generated, then it is called a major or hard page fault. The page fault handler in the operating system needs to find a free page in memory, or choose another non-free page in memory to be used for this page's data, which might be used by another process. In this latter case, the OS first needs to write out the data in that page if it hasn't already been written out since it was last modified, and mark that page as not being loaded into memory in its process page table. Once the page has thus been made available, the OS can read the data for the new page into the physical page, and then make the entry for that page in the memory management unit point to the page in memory and indicate that the page is loaded in memory.[clarification needed] Major faults are more expensive than minor page faults and add disk latency to the interrupted program's execution. This is the mechanism used by an operating system to increase the amount of program memory available on demand. The operating system delays loading parts of the program from disk until the program attempts to use it and the page fault is generated.
备注3.清理mysql缓存方法
（不停库没法完全清理mysql的缓存）
service mysqld stop;sync;echo 3 > /proc/sys/vm/drop_caches ;
service mysqld start;