mysql 中可利用 show profile 进行性能分析
show profile 功能默认状态下为关闭， 因消耗一定资源
查询方法
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 | 0 = 关闭 1 = 启用
+-------------+
1 row in set (0.00 sec)
打开方法
mysql> set profiling = 1;
Query OK, 0 rows affected (0.00 sec)
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
1 row in set (0.00 sec)
启用 profiling 功能后就可以对 SQL 进行分析。
为避免之前已经把 SQL 存放在 QCACHE 中， 建议在执行 SQL 时， 强制 SELECT 语句不进行 QCACHE 检测
如下面 SQL
mysql> select sql_no_cache distinct prewarebro0_.ID as ID471_, prewarebro0_.SPECIFICATION_ID as SPECIFIC2_471_, prewarebro0_.SPECIES_ID as SPECIES3_471_, prewarebro0_.SPECIES_CODE as SPECIES4_471_, prewarebro0_.DETAIL_URL as DETAIL5_471_, prewarebro0_.SALEPRICE as SALEPRICE471_, prewarebro0_.TYPE as TYPE471_, prewarebro0_.CREATE_TIME as CREATE8_471_, prewarebro0_.PICTUREURL as PICTUREURL471_, prewarebro0_.USER_KO as USER10_471_ from PRE_WARE_BROSWERS prewarebro0_ cross join WARE_DIRECTORY_SUMA waredirect1_ cross join WARE_CON_DIECTORY warecondir2_ cross join WARE_MOUNTED waremounte3_ cross join WARE_CATALOG specificat4_ where waredirect1_.ID=warecondir2_.SUMA_ID and warecondir2_.ID=waremounte3_.CON_CODE and prewarebro0_.SPECIFICATION_ID=waremounte3_.MOUNT_CODE and prewarebro0_.SPECIFICATION_ID=specificat4_.ID and waredirect1_.STATUS='1' and waremounte3_.STATUS='1' and specificat4_.STATUS=1 and prewarebro0_.USER_KO='38a89ba4e0595ff0d06ab0744f64344f' order by prewarebro0_.CREATE_TIME desc limit 3 ;
Empty set (0.51 sec)
当执行完 SQL 之后，可以对该 SQL 进行分析， 如
mysql> show profile;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000793 |
| checking permissions | 0.000012 |
| checking permissions | 0.000006 |
| checking permissions | 0.000005 |
| checking permissions | 0.000005 |
| checking permissions | 0.000010 |
| Opening tables | 0.000132 |
| System lock | 0.000047 |
| init | 0.000160 |
| optimizing | 0.000084 |
| statistics | 0.000264 |
| preparing | 0.000146 |
| Creating tmp table | 0.000100 |
| executing | 0.000008 |
| Copying to tmp table | 0.515277 |
| Sorting result | 0.000045 |
| Sending data | 0.000039 |
| end | 0.000012 |
| removing tmp table | 0.000019 |
| end | 0.000008 |
| query end | 0.000014 |
| closing tables | 0.000055 |
| freeing items | 0.000087 |
| logging slow query | 0.000005 |
| cleaning up | 0.000014 |
+----------------------+----------+
25 rows in set (0.00 sec)
我们看到了， 明显就是 copying to tmp table 值比较不正常，不进行字面解释了
看看当前我们电脑缓存了多少可以进行分析的 SQL
mysql> show profiles;
+----------+------------+------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+------------------------------------------+
| 1 | 0.00026925 | select * from ware_stocks where id < 15 |
| 2 | 0.00032250 | SELECT DATABASE() |
| 3 | 0.00102075 | show databases |
| 4 | 0.00388575 | show tables |
| 5 | 0.00021200 | select * from ware_stocks where id < 15 |
| 6 | 0.01826000 | select * from ware_stocks where id < 55 |
| 7 | 0.02039825 | select * from ware_stocks where id < 155 |
| 8 | 0.03401675 | select * from ware_stocks where id > 3 |
+----------+------------+------------------------------------------+
8 rows in set (0.00 sec)
上面记录了一共 8 条 SQL 分析， 假如要分析某一条， 那么可以执行 (参考上表中 ID 值进行分析)
mysql> show profile for query 8;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000164 |
| Waiting for query cache lock | 0.000010 |
| checking query cache for query | 0.000197 |
| checking permissions | 0.000026 |
| Opening tables | 0.000094 |
| System lock | 0.000038 |
| Waiting for query cache lock | 0.000095 |
| init | 0.000122 |
| optimizing | 0.000025 |
| statistics | 0.000073 |
| preparing | 0.000032 |
| executing | 0.000008 |
| Sending data | 0.010331 |
| Waiting for query cache lock | 0.000020 |
| Sending data | 0.005885 |
| Waiting for query cache lock | 0.000011 |
| Sending data | 0.005877 |
| Waiting for query cache lock | 0.000010 |
| Sending data | 0.005998 |
| Waiting for query cache lock | 0.000011 |
| Sending data | 0.004589 |
| end | 0.000022 |
| query end | 0.000031 |
| closing tables | 0.000050 |
| freeing items | 0.000038 |
| Waiting for query cache lock | 0.000010 |
| freeing items | 0.000213 |
| Waiting for query cache lock | 0.000009 |
| freeing items | 0.000005 |
| storing result in query cache | 0.000009 |
| logging slow query | 0.000006 |
| cleaning up | 0.000010 |
+--------------------------------+----------+
32 rows in set (0.01 sec)
另外，还可以独立地分析某项资源，方便参考
o ALL displays all information
o BLOCK IO displays counts for block input and output operations
o CONTEXT SWITCHESdisplays counts for voluntary and involuntary
context switches
o CPU displays user and system CPU usage times
o IPC displays counts for messages sent and received
o MEMORY is not currently implemented
o PAGE FAULTS displays counts for major and minor page faults
o 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
o SWAPS displays swap counts
参考之前信息，我们看看 Copying to tmp table的IO情况
mysql> show profile block io for query 9;
+----------------------+----------+--------------+---------------+
| Status | Duration | Block_ops_in | Block_ops_out |
+----------------------+----------+--------------+---------------+
| starting | 0.000483 | 0 | 0 |
| checking permissions | 0.000012 | 0 | 0 |
| checking permissions | 0.000006 | 0 | 0 |
| checking permissions | 0.000006 | 0 | 0 |
| checking permissions | 0.000006 | 0 | 0 |
| checking permissions | 0.000010 | 0 | 0 |
| Opening tables | 0.000162 | 0 | 0 |
| System lock | 0.000056 | 0 | 0 |
| init | 0.000179 | 0 | 0 |
| optimizing | 0.000074 | 0 | 0 |
| statistics | 0.000225 | 0 | 0 |
| preparing | 0.000173 | 0 | 0 |
| Creating tmp table | 0.000127 | 0 | 0 |
| executing | 0.000008 | 0 | 0 |
| Copying to tmp table | 0.837154 | 0 | 8 | 产生 8 次的 IO 了用于创建 TMP TABLE 了
| Sorting result | 0.000059 | 0 | 0 |
| Sending data | 0.000050 | 0 | 0 |
| end | 0.000017 | 0 | 0 |
| removing tmp table | 0.000025 | 0 | 0 |
| end | 0.000012 | 0 | 0 |
| query end | 0.000018 | 0 | 0 |
| closing tables | 0.000071 | 0 | 0 |
| freeing items | 0.000097 | 0 | 0 |
| logging slow query | 0.000006 | 0 | 0 |
| cleaning up | 0.000012 | 0 | 0 |
+----------------------+----------+--------------+---------------+
25 rows in set (0.00 sec)
参考 CPU
mysql> show profile CPU for query 9;
+----------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting | 0.000483 | 0.000000 | 0.000000 |
| checking permissions | 0.000012 | 0.000000 | 0.000000 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 |
| checking permissions | 0.000010 | 0.000000 | 0.000000 |
| Opening tables | 0.000162 | 0.002000 | 0.000000 |
| System lock | 0.000056 | 0.000000 | 0.000000 |
| init | 0.000179 | 0.000000 | 0.000000 |
| optimizing | 0.000074 | 0.000000 | 0.000000 |
| statistics | 0.000225 | 0.000000 | 0.000000 |
| preparing | 0.000173 | 0.000000 | 0.000000 |
| Creating tmp table | 0.000127 | 0.000000 | 0.000000 |
| executing | 0.000008 | 0.000000 | 0.000000 |
| Copying to tmp table | 0.837154 | 1.166823 | 0.001000| 也严重消耗了 CPU
| Sorting result | 0.000059 | 0.000000 | 0.000000 |
| Sending data | 0.000050 | 0.000000 | 0.000000 |
| end | 0.000017 | 0.000000 | 0.000000 |
| removing tmp table | 0.000025 | 0.000000 | 0.000000 |
| end | 0.000012 | 0.000000 | 0.000000 |
| query end | 0.000018 | 0.000000 | 0.000000 |
| closing tables | 0.000071 | 0.000000 | 0.000000 |
| freeing items | 0.000097 | 0.000000 | 0.000000 |
| logging slow query | 0.000006 | 0.000000 | 0.000000 |
| cleaning up | 0.000012 | 0.000000 | 0.000000 |
+----------------------+----------+----------+------------+
25 rows in set (0.01 sec)
总结, 分析后，切记 set profiling = 0 , 另外可以配合 explain 更方便地对执行计划进行分析。
