当生了病的query来就诊时,如果身为医生的我们"胡庸医乱用虎狼药"
不仅于事无补,还浪费了大量的人力和时间成本,甚至会拖垮服务器
所以,我们在接受优化一条SQL,第一件事情便是要明白query病在哪里?
是IO?是CPU?只有明白瓶颈在哪里,方可对症下药,也才能药到病除
而MySQL QUERY Profiler是一个使用非常方便的QUERY诊断工具,5.0引入。5.1GA版嵌入
这个工具详细呈现了SQL在整个生命周期的每个动作,这和Oracle开启1046事件类似
我们可以很清晰地明白该SQL是在数据存取还是运算(排序或分组等)上花费得多
那么我们就不会很盲目地看到order by就去tuning sort buffer而忽略sorting result时间是如此之少
注解:
默认输出结果只会展示Status和Duration,我们可以指定type来扩展输出
我比较常用的是外加CPU和BLOCK IO来输出CPU和IO的负载,其实这些已经够了
默认profile是关闭的,通过profiling参数控制,为session级
开启:SET profiling=1
关闭:set profiling=0
查询:select @@profiling
show profiles保存的query条数由参数profiling_history_size控制,默认是15,超过了会把前面的剔掉
相同的信息我们还可以从information_schema里面输出,并且我们还可以对时间进行排序
因为Profile默认是按执行顺序排序的,而实际上我们更关心的是花费了多少时间,这才能方便知道哪些开销较大
参考文章:
http://dev.mysql.com/doc/refman/5.5/en/show-profile.html
By 迦夜
2013-10-3
Good Luck
不仅于事无补,还浪费了大量的人力和时间成本,甚至会拖垮服务器
所以,我们在接受优化一条SQL,第一件事情便是要明白query病在哪里?
是IO?是CPU?只有明白瓶颈在哪里,方可对症下药,也才能药到病除
而MySQL QUERY Profiler是一个使用非常方便的QUERY诊断工具,5.0引入。5.1GA版嵌入
这个工具详细呈现了SQL在整个生命周期的每个动作,这和Oracle开启1046事件类似
我们可以很清晰地明白该SQL是在数据存取还是运算(排序或分组等)上花费得多
那么我们就不会很盲目地看到order by就去tuning sort buffer而忽略sorting result时间是如此之少
Profile语法:
SHOW PROFILE [type [, type] ... ]
[FOR QUERY n]
[LIMIT row_count [OFFSET offset]]
type:
ALL
| BLOCK IO
| CONTEXT SWITCHES
| CPU
| IPC
| MEMORY
| PAGE FAULTS
| SOURCE
| SWAPS
注解:
默认输出结果只会展示Status和Duration,我们可以指定type来扩展输出
我比较常用的是外加CPU和BLOCK IO来输出CPU和IO的负载,其实这些已经够了
默认profile是关闭的,通过profiling参数控制,为session级
开启:SET profiling=1
关闭:set profiling=0
查询:select @@profiling
show profiles保存的query条数由参数profiling_history_size控制,默认是15,超过了会把前面的剔掉
mysql> set profiling=1;
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
mysql> select * from employees.t order by first_name;
mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+-----------------------------------------------+
| 1 | 0.21138800 | show create table employees.t |
| 2 | 8.21691600 | select * from employees.t order by first_name |
+----------+------------+-----------------------------------------------+
2 rows in set (0.00 sec)
mysql> show profile cpu,block io for query 2;
+----------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting | 0.000160 | 0.000000 | 0.000000 | 0 | 0 |
| checking permissions | 0.000026 | 0.000000 | 0.000000 | 0 | 0 |
| Opening tables | 0.000055 | 0.000000 | 0.000000 | 0 | 0 |
| System lock | 0.000033 | 0.000000 | 0.000000 | 0 | 0 |
| init | 0.000050 | 0.000000 | 0.000000 | 0 | 0 |
| optimizing | 0.000026 | 0.000000 | 0.000000 | 0 | 0 |
| statistics | 0.000145 | 0.000000 | 0.000000 | 0 | 0 |
| preparing | 0.000118 | 0.000000 | 0.000000 | 0 | 0 |
| executing | 0.000011 | 0.000000 | 0.000000 | 0 | 0 |
| Sorting result | 2.838465 | 1.396087 | 1.140071 | 0 | 0 |
| Sending data | 0.928078 | 0.544034 | 0.056003 | 0 | 0 |
| end | 0.000026 | 0.000000 | 0.000000 | 0 | 0 |
| query end | 0.000011 | 0.000000 | 0.000000 | 0 | 0 |
| closing tables | 0.000021 | 0.000000 | 0.000000 | 0 | 0 |
| freeing items | 4.449672 | 0.000000 | 0.000000 | 0 | 0 |
| logging slow query | 0.000014 | 0.000000 | 0.000000 | 0 | 0 |
| cleaning up | 0.000005 | 0.000000 | 0.000000 | 0 | 0 |
+----------------------+----------+----------+------------+--------------+---------------+
17 rows in set (0.00 sec)
相同的信息我们还可以从information_schema里面输出,并且我们还可以对时间进行排序
因为Profile默认是按执行顺序排序的,而实际上我们更关心的是花费了多少时间,这才能方便知道哪些开销较大
mysql> SELECT STATE, FORMAT(DURATION, 6) AS DURATION
-> FROM INFORMATION_SCHEMA.PROFILING
-> WHERE QUERY_ID = 2 ORDER BY DURATION DESC;
+----------------------+----------+
| STATE | DURATION |
+----------------------+----------+
| freeing items | 4.449672 |
| Sorting result | 2.838465 |
| Sending data | 0.928078 |
| starting | 0.000160 |
| statistics | 0.000145 |
| preparing | 0.000118 |
| Opening tables | 0.000055 |
| init | 0.000050 |
| System lock | 0.000033 |
| end | 0.000026 |
| optimizing | 0.000026 |
| checking permissions | 0.000026 |
| closing tables | 0.000021 |
| logging slow query | 0.000014 |
| query end | 0.000011 |
| executing | 0.000011 |
| cleaning up | 0.000005 |
+----------------------+----------+
17 rows in set (0.00 sec)
参考文章:
http://dev.mysql.com/doc/refman/5.5/en/show-profile.html
By 迦夜
2013-10-3
Good Luck