1.开启profiling
#是否支持profiling
mysql> select @@have_profiling;
+------------------+
| @@have_profiling |
+------------------+
| YES |
+------------------+
#默认profiling是关闭的
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 |
+-------------+
#开启profiling
mysql> set profiling=1;
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
- 通过profile 了解SQL的执行过程
# 例如 MyISAM 表有表元数缓存，而InnoDB表则没有，这样同样count(*) 查询 MyISAM 表要快于InnoDB
mysql> select count(1) from country;
+----------+
| count(1) |
+----------+
| 1 |
+----------+
root@127.0.0.1 : testdb【09:19:30】17 SQL->show profiles;
+----------+------------+------------------------------+
| Query_ID | Duration | Query |
+----------+------------+------------------------------+
| 1 | 0.00023200 | select @@profiling |
| 2 | 0.01504200 | select count(1) from country |
| 3 | 0.00012725 | SELECT DATABASE() |
| 4 | 0.00018575 | select @@profiling |
| 5 | 0.00084025 | select count(1) from country |
+----------+------------+------------------------------+
root@127.0.0.1 : testdb【09:19:42】18 SQL->show profile for query 5;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000054 |
| Executing hook on transaction | 0.000005 |
| starting | 0.000008 |
| checking permissions | 0.000006 |
| Opening tables | 0.000096 |
| init | 0.000006 |
| System lock | 0.000007 |
| optimizing | 0.000008 |
| statistics | 0.000010 |
| preparing | 0.000017 |
| executing | 0.000003 |
| Sending data | 0.000516 |
| end | 0.000010 |
| query end | 0.000005 |
| waiting for handler commit | 0.000009 |
| closing tables | 0.000007 |
| freeing items | 0.000045 |
| cleaning up | 0.000031 |
+--------------------------------+----------+
#由上可知 主要消耗在 Sending data 上
#为了更加清晰看到资源消耗排序情况，可以查询information_schema.profiling 表
mysql> set @query_id:=5;
mysql>
select state,sum(duration) as total_r
,round(100*sum(duration)/(select sum(duration) from information_schema.profiling where query_id=@query_id),2) as pct_r
,count(*) as calls
,sum(duration)/count(*) as "r/call"
from information_schema.profiling where query_id=@query_id group by state order by total_r desc;
+--------------------------------+----------+-------+-------+--------------+
| state | total_r | pct_r | calls | r/call |
+--------------------------------+----------+-------+-------+--------------+
| Sending data | 0.000516 | 61.21 | 1 | 0.0005160000 |
| Opening tables | 0.000096 | 11.39 | 1 | 0.0000960000 |
| starting | 0.000062 | 7.35 | 2 | 0.0000310000 |
| freeing items | 0.000045 | 5.34 | 1 | 0.0000450000 |
| cleaning up | 0.000031 | 3.68 | 1 | 0.0000310000 |
| preparing | 0.000017 | 2.02 | 1 | 0.0000170000 |
| end | 0.000010 | 1.19 | 1 | 0.0000100000 |
| statistics | 0.000010 | 1.19 | 1 | 0.0000100000 |
| waiting for handler commit | 0.000009 | 1.07 | 1 | 0.0000090000 |
| optimizing | 0.000008 | 0.95 | 1 | 0.0000080000 |
| System lock | 0.000007 | 0.83 | 1 | 0.0000070000 |
| closing tables | 0.000007 | 0.83 | 1 | 0.0000070000 |
| init | 0.000006 | 0.71 | 1 | 0.0000060000 |
| checking permissions | 0.000006 | 0.71 | 1 | 0.0000060000 |
| query end | 0.000005 | 0.59 | 1 | 0.0000050000 |
| Executing hook on transaction | 0.000005 | 0.59 | 1 | 0.0000050000 |
| executing | 0.000003 | 0.36 | 1 | 0.0000030000 |
+--------------------------------+----------+-------+-------+--------------+
root@127.0.0.1 : testdb【09:21:25】23 SQL->show profile cpu for query 5;
+--------------------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+--------------------------------+----------+----------+------------+
| starting | 0.000054 | 0.000005 | 0.000044 |
| Executing hook on transaction | 0.000005 | 0.000000 | 0.000004 |
| starting | 0.000008 | 0.000001 | 0.000007 |
| checking permissions | 0.000006 | 0.000000 | 0.000005 |
| Opening tables | 0.000096 | 0.000009 | 0.000088 |
| init | 0.000006 | 0.000000 | 0.000005 |
| System lock | 0.000007 | 0.000001 | 0.000006 |
| optimizing | 0.000008 | 0.000001 | 0.000008 |
| statistics | 0.000010 | 0.000001 | 0.000008 |
| preparing | 0.000017 | 0.000001 | 0.000016 |
| executing | 0.000003 | 0.000000 | 0.000002 |
| Sending data | 0.000516 | 0.000552 | 0.000000 |
| end | 0.000010 | 0.000006 | 0.000000 |
| query end | 0.000005 | 0.000005 | 0.000000 |
| waiting for handler commit | 0.000009 | 0.000009 | 0.000000 |
| closing tables | 0.000007 | 0.000007 | 0.000000 |
| freeing items | 0.000045 | 0.000046 | 0.000000 |
| cleaning up | 0.000031 | 0.000031 | 0.000000 |
+--------------------------------+----------+----------+------------+
#创建MYISAM 表
root@127.0.0.1 : testdb【09:23:18】24 SQL->create table country_myisam like country;
root@127.0.0.1 : testdb【09:25:56】25 SQL->alter table country_myisam engine=myisam;
root@127.0.0.1 : testdb【09:26:20】26 SQL->insert into country_myisam select * from country;
#MYISAM 表分析
root@127.0.0.1 : testdb【09:29:00】33 SQL->show profiles;
13 | 0.00019275 | select count(*) from country_myisam
#myisam 表查询count(*) 没有消耗在 Sending data 上
root@127.0.0.1 : testdb【09:29:32】34 SQL->show profile for query 13;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000075 |
| Executing hook on transaction | 0.000005 |
| starting | 0.000008 |
| checking permissions | 0.000006 |
| Opening tables | 0.000021 |
| init | 0.000004 |
| System lock | 0.000008 |
| optimizing | 0.000005 |
| executing | 0.000007 |
| end | 0.000003 |
| query end | 0.000005 |
| closing tables | 0.000007 |
| freeing items | 0.000022 |
| cleaning up | 0.000018 |
+--------------------------------+----------+
网友评论