MySQL使用profile分析语句性能消耗
--查看profile是否开启
mysql> show variables like '%profil%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| profiling | OFF | --开启SQL语句剖析功能
| profiling_history_size | 15 | --设置保留profiling的数目，缺省为15，范围为0至100，为0时将禁用profiling
+------------------------+-------+
2 rows in set (0.00 sec)
--基于会话级别开启
mysql> set profiling = 1; --关闭则用set profiling = off
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like '%profil%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| profiling | ON |
| profiling_history_size | 15 |
+------------------------+-------+
2 rows in set (0.00 sec)
mysql> select distinct d.account,a.server_id from tab_appserver_user a
-> inner join tab_department_parent b on a.key_id = b.parent_id
-> inner join tab_department_member c on b.department_id = c.department_id and c.state=1
-> and c.isdefault=1 inner join tab_user_info d on c.user_id = d.user_id and d.state=1
-> where a.type=1
-> union
-> select distinct b.account,a.server_id from tab_appserver_user a
-> inner join tab_user_info b on a.key_id = b.user_id and b.state=1
-> where a.type=0;
--显示缓存的profile
mysql> show profiles;
+----------+------------+-------------------------------------------------------+
| Query_ID | Duration | Query
1 | 0.86754250 | select distinct d.account,a.server_id from tab_appserver_user a
+----------+------------+-------------------------------------------------------+
4 rows in set (0.00 sec)
从上面可以看到时间的消耗为0.8秒
以下是具体的消耗，进行详细的列出
mysql> show profile for query 1; --1是query_id
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000018 |
| checking query cache for query | 0.000099 |
| Opening tables | 0.000963 |
| System lock | 0.000015 |
| Table lock | 0.000169 |
| optimizing | 0.000020 |
| statistics | 0.000027 |
| preparing | 0.000018 |
| Creating tmp table | 0.000055 |
| executing | 0.000003 |
| Copying to tmp table | 0.704845 | --最主要的消耗点
| Sending data | 0.130039 |
| optimizing | 0.000029 |
| statistics | 0.000029 |
| preparing | 0.000020 |
| Creating tmp table | 0.000142 |
| executing | 0.000003 |
| Copying to tmp table | 0.000086 |
| Sending data | 0.000067 |
| optimizing | 0.000004 |
| statistics | 0.000005 |
| preparing | 0.000005 |
| executing | 0.000002 |
| Sending data | 0.023963 |
| removing tmp table | 0.003420 |
| Sending data | 0.000005 |
| removing tmp table | 0.003308 |
| Sending data | 0.000006 |
| removing tmp table | 0.000007 |
| Sending data | 0.000009 |
| query end | 0.000003 |
| freeing items | 0.000144 |
| storing result in query cache | 0.000011 |
| logging slow query | 0.000003 |
| cleaning up | 0.000006 |
+--------------------------------+----------+
35 rows in set (0.00 sec)
--查看cpu的消耗情况
mysql> show profile cpu for query 1;
+--------------------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+--------------------------------+----------+----------+------------+
| starting | 0.000018 | NULL | NULL |
| checking query cache for query | 0.000099 | NULL | NULL |
| Opening tables | 0.000963 | NULL | NULL |
| System lock | 0.000015 | NULL | NULL |
| Table lock | 0.000169 | NULL | NULL |
| optimizing | 0.000020 | NULL | NULL |
| statistics | 0.000027 | NULL | NULL |
| preparing | 0.000018 | NULL | NULL |
| Creating tmp table | 0.000055 | NULL | NULL |
| executing | 0.000003 | NULL | NULL |
| Copying to tmp table | 0.704845 | NULL | NULL | --此项消耗cpu最多
| Sending data | 0.130039 | NULL | NULL |
| optimizing | 0.000029 | NULL | NULL |
| statistics | 0.000029 | NULL | NULL |
| preparing | 0.000020 | NULL | NULL |
| Creating tmp table | 0.000142 | NULL | NULL |
| executing | 0.000003 | NULL | NULL |
| Copying to tmp table | 0.000086 | NULL | NULL |
| Sending data | 0.000067 | NULL | NULL |
| optimizing | 0.000004 | NULL | NULL |
| statistics | 0.000005 | NULL | NULL |
| preparing | 0.000005 | NULL | NULL |
| executing | 0.000002 | NULL | NULL |
| Sending data | 0.023963 | NULL | NULL |
| removing tmp table | 0.003420 | NULL | NULL |
| Sending data | 0.000005 | NULL | NULL |
| removing tmp table | 0.003308 | NULL | NULL |
| Sending data | 0.000006 | NULL | NULL |
| removing tmp table | 0.000007 | NULL | NULL |
| Sending data | 0.000009 | NULL | NULL |
| query end | 0.000003 | NULL | NULL |
| freeing items | 0.000144 | NULL | NULL |
| storing result in query cache | 0.000011 | NULL | NULL |
| logging slow query | 0.000003 | NULL | NULL |
| cleaning up | 0.000006 | NULL | NULL |
+--------------------------------+----------+----------+------------+
35 rows in set (0.00 sec)
--查看内存消耗
mysql> show profile memory for query 1;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000018 |
| checking query cache for query | 0.000099 |
| Opening tables | 0.000963 |
| System lock | 0.000015 |
| Table lock | 0.000169 |
| optimizing | 0.000020 |
| statistics | 0.000027 |
| preparing | 0.000018 |
| Creating tmp table | 0.000055 |
| executing | 0.000003 |
| Copying to tmp table | 0.704845 |
| Sending data | 0.130039 |
| optimizing | 0.000029 |
| statistics | 0.000029 |
| preparing | 0.000020 |
| Creating tmp table | 0.000142 |
| executing | 0.000003 |
| Copying to tmp table | 0.000086 |
| Sending data | 0.000067 |
| optimizing | 0.000004 |
| statistics | 0.000005 |
| preparing | 0.000005 |
| executing | 0.000002 |
| Sending data | 0.023963 |
| removing tmp table | 0.003420 |
| Sending data | 0.000005 |
| removing tmp table | 0.003308 |
| Sending data | 0.000006 |
| removing tmp table | 0.000007 |
| Sending data | 0.000009 |
| query end | 0.000003 |
| freeing items | 0.000144 |
| storing result in query cache | 0.000011 |
| logging slow query | 0.000003 |
| cleaning up | 0.000006 |
+--------------------------------+----------+
--查看io及cpu的消耗
mysql> show profile block io,cpu for query 1;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| starting | 0.000018 | NULL | NULL | NULL | NULL |
| checking query cache for query | 0.000099 | NULL | NULL | NULL | NULL |
| Opening tables | 0.000963 | NULL | NULL | NULL | NULL |
| System lock | 0.000015 | NULL | NULL | NULL | NULL |
| Table lock | 0.000169 | NULL | NULL | NULL | NULL |
| optimizing | 0.000020 | NULL | NULL | NULL | NULL |
| statistics | 0.000027 | NULL | NULL | NULL | NULL |
| preparing | 0.000018 | NULL | NULL | NULL | NULL |
| Creating tmp table | 0.000055 | NULL | NULL | NULL | NULL |
| executing | 0.000003 | NULL | NULL | NULL | NULL |
| Copying to tmp table | 0.704845 | NULL | NULL | NULL | NULL |
| Sending data | 0.130039 | NULL | NULL | NULL | NULL |
| optimizing | 0.000029 | NULL | NULL | NULL | NULL |
| statistics | 0.000029 | NULL | NULL | NULL | NULL |
| preparing | 0.000020 | NULL | NULL | NULL | NULL |
| Creating tmp table | 0.000142 | NULL | NULL | NULL | NULL |
| executing | 0.000003 | NULL | NULL | NULL | NULL |
| Copying to tmp table | 0.000086 | NULL | NULL | NULL | NULL |
| Sending data | 0.000067 | NULL | NULL | NULL | NULL |
| optimizing | 0.000004 | NULL | NULL | NULL | NULL |
| statistics | 0.000005 | NULL | NULL | NULL | NULL |
| preparing | 0.000005 | NULL | NULL | NULL | NULL |
| executing | 0.000002 | NULL | NULL | NULL | NULL |
| Sending data | 0.023963 | NULL | NULL | NULL | NULL |
| removing tmp table | 0.003420 | NULL | NULL | NULL | NULL |
| Sending data | 0.000005 | NULL | NULL | NULL | NULL |
| removing tmp table | 0.003308 | NULL | NULL | NULL | NULL |
| Sending data | 0.000006 | NULL | NULL | NULL | NULL |
| removing tmp table | 0.000007 | NULL | NULL | NULL | NULL |
| Sending data | 0.000009 | NULL | NULL | NULL | NULL |
| query end | 0.000003 | NULL | NULL | NULL | NULL |
| freeing items | 0.000144 | NULL | NULL | NULL | NULL |
| storing result in query cache | 0.000011 | NULL | NULL | NULL | NULL |
| logging slow query | 0.000003 | NULL | NULL | NULL | NULL |
| cleaning up | 0.000006 | NULL | NULL | NULL | NULL |
+--------------------------------+----------+----------+------------+--------------+---------------+
35 rows in set (0.00 sec)
--使用查询语句对消耗进行排序
mysql> SELECT STATE,
-> SUM(DURATION) AS TOTAL_R,
-> ROUND(100 * SUM(DURATION) /
-> (SELECT SUM(DURATION)
-> FROM INFORMATION_SCHEMA.PROFILING
-> WHERE QUERY_ID = 1),
-> 2) AS PCT_R,
-> COUNT(*) AS CALLS,
-> SUM(DURATION) / COUNT(*) AS "R/Call"
-> FROM INFORMATION_SCHEMA.PROFILING
-> WHERE QUERY_ID = 1
-> GROUP BY STATE
-> ORDER BY TOTAL_R DESC;
+--------------------------------+----------+-------+-------+--------------+
| STATE | Total_R | Pct_R | Calls | R/Call |
+--------------------------------+----------+-------+-------+--------------+
| Copying to tmp table | 0.704931 | 81.26 | 2 | 0.3524655000 |
| Sending data | 0.154089 | 17.76 | 6 | 0.0256815000 |
| removing tmp table | 0.006735 | 0.78 | 3 | 0.0022450000 |
| Opening tables | 0.000963 | 0.11 | 1 | 0.0009630000 |
| Creating tmp table | 0.000197 | 0.02 | 2 | 0.0000985000 |
| Table lock | 0.000169 | 0.02 | 1 | 0.0001690000 |
| freeing items | 0.000144 | 0.02 | 1 | 0.0001440000 |
| checking query cache for query | 0.000099 | 0.01 | 1 | 0.0000990000 |
| statistics | 0.000061 | 0.01 | 3 | 0.0000203333 |
| optimizing | 0.000053 | 0.01 | 3 | 0.0000176667 |
| preparing | 0.000043 | 0.00 | 3 | 0.0000143333 |
| starting | 0.000018 | 0.00 | 1 | 0.0000180000 |
| System lock | 0.000015 | 0.00 | 1 | 0.0000150000 |
| storing result in query cache | 0.000011 | 0.00 | 1 | 0.0000110000 |
| executing | 0.000008 | 0.00 | 3 | 0.0000026667 |
| cleaning up | 0.000006 | 0.00 | 1 | 0.0000060000 |
| logging slow query | 0.000003 | 0.00 | 1 | 0.0000030000 |
| query end | 0.000003 | 0.00 | 1 | 0.0000030000 |
+--------------------------------+----------+-------+-------+--------------+
18 rows in set (0.01 sec)
--最后说明：
profile是一个非常量化的
>
>
>
>
>
>
>
>
