show profile是由Jeremy Cole捐献给MySQL社区版本的。默认的是关闭的,但是会话级别可以开启这个功能。开启它可以让MySQL收集在执行语句的时候所使用的资源。为了统计报表,把profiling设为1
之后在运行一个查询
这个执行语句的剖析信息存储在这个会话中。使用SHOW PROFILES进行查看。
你可以使用SHOW PROFILE语句来获取已经存储的剖析数据。如果不加参数,会显示状态以及它们持续的时间。
每行都是状态变化的过程以及它们持续的时间。Status那一列和SHOW FULL PROCESSLIST的State应该是一致的。
这个值是来自于thd->proc_info变量。因此你所查看的这个值是直接来自MySQL内部的。尽管这些数值是比较直接易懂的,你也可以查看MySQL手册。
你可以给SHOW PROFILES指定一个Query_ID来查看指定的语句,还可以给输出添加新的列。如,查看用户和CPU使用。可以用如下命令。
SHOW PROFILE可以深入的查看服务器执行语句的工作情况。以及也能帮助你理解执行语句消耗时间的情况。一些限制是它没有实现的功能,不能查看和剖析其他连接的语句,以及剖析时所引起的消耗。
SHOW PROFILES显示最近发给服务器的多条语句,条数根据会话变量profiling_history_size定义,默认是15,最大值为100。设为0等价于关闭分析功能。
SHOW PROFILE FOR QUERY n,这里的n就是对应SHOW PROFILES输出中的Query_ID。
例如:
如果没有指定FOR QUERY,那么输出最近一条语句的信息。
LIMIT部分的用法与SELECT中LIMIT子句一致,不赘述。
type是可选的,取值范围可以如下:
- ALL 显示所有性能信息
- BLOCK IO 显示块IO操作的次数
- CONTEXT SWITCHES 显示上下文切换次数,不管是主动还是被动
- CPU 显示用户CPU时间、系统CPU时间
- IPC 显示发送和接收的消息数量
- MEMORY [暂未实现]
- PAGE FAULTS 显示页错误数量
- SOURCE 显示源码中的函数名称与位置
- SWAPS 显示SWAP的次数
例:
mysql> show profile cpu for query 2;+------------------------------+-----------+----------+------------+| Status | Duration | CPU_user | CPU_system |+------------------------------+-----------+----------+------------+| starting | 0.000183 | 0.000000 | 0.000000 || checking permissions | 0.000057 | 0.000000 | 0.000000 || checking permissions | 0.000059 | 0.000000 | 0.000000 || init | 0.000060 | 0.000000 | 0.000000 || Opening tables | 0.000071 | 0.000000 | 0.000000 || System lock | 0.000062 | 0.000000 | 0.000000 || setup | 0.000080 | 0.000000 | 0.001000 || creating table | 0.005052 | 0.003000 | 0.001000 || After create | 0.000220 | 0.000000 | 0.000000 || copy to tmp table | 0.000244 | 0.000000 | 0.000000 || rename result table | 70.364027 | 7.470864 | 41.612674 || end | 0.000575 | 0.000000 | 0.001000 || Waiting for query cache lock | 0.000062 | 0.000000 | 0.000000 || end | 0.000075 | 0.000000 | 0.000000 || query end | 0.000057 | 0.000000 | 0.000000 || closing tables | 0.000061 | 0.000000 | 0.000000 || freeing items | 0.000080 | 0.000000 | 0.000000 || logging slow query | 0.000056 | 0.000000 | 0.000000 || logging slow query | 0.000098 | 0.000000 | 0.000000 || cleaning up | 0.000059 | 0.000000 | 0.000000 |+------------------------------+-----------+----------+------------+20 rows in set (0.00 sec)ps:
SHOW PROFILE ALL FOR QUERY 2;的信息还可以通过SELECT * FROM information_schema.profiling WHERE query_id = 2 ORDER BY seq;获取。
作用范围
这个命令只是在本会话内起作用,即无法分析本会话外的语句。
开启分析功能后,所有本会话中的语句都被分析(甚至包括执行错误的语句),除了SHOW PROFILE和SHOW PROFILES两句本身。
应用示例:使用SHOW PROFILE分析查询缓存命中的性能优势。
mysql> set profiling=1;Query OK, 0 rows affected (0.00 sec)mysql> select count(1) as cnt from tran_excution;+-------+| cnt |+-------+| 14225 |+-------+1 row in set (0.00 sec)由于已经启用了查询缓存,相同查询(非分区表)可以直接在查询缓存中命中。
mysql> select count(1) as cnt from tran_excution;我们仔细看下两个同样的语句的分析。
mysql> show profile source for query 1;+--------------------------------+----------+-----------------------+---------------+-------------+| Status | Duration | Source_function | Source_file | Source_line |+--------------------------------+----------+-----------------------+---------------+-------------+| starting | 0.000048 | NULL | NULL | NULL || Waiting for query cache lock | 0.000013 | try_lock | sql_cache.cc | 454 || checking query cache for query | 0.000040 | send_result_to_client | sql_cache.cc | 1561 || checking permissions | 0.000023 | check_access | sql_parse.cc | 4751 || Opening tables | 0.000040 | open_tables | sql_base.cc | 4831 || System lock | 0.000020 | mysql_lock_tables | lock.cc | 299 || Waiting for query cache lock | 0.000037 | try_lock | sql_cache.cc | 454 || init | 0.000020 | mysql_select | sql_select.cc | 2579 || optimizing | 0.000015 | optimize | sql_select.cc | 865 || statistics | 0.000017 | optimize | sql_select.cc | 1056 || preparing | 0.000016 | optimize | sql_select.cc | 1078 || executing | 0.000015 | exec | sql_select.cc | 1836 || Sending data | 0.003875 | exec | sql_select.cc | 2380 || end | 0.000018 | mysql_select | sql_select.cc | 2615 || query end | 0.000015 | mysql_execute_command | sql_parse.cc | 4440 || closing tables | 0.000016 | mysql_execute_command | sql_parse.cc | 4492 || freeing items | 0.000016 | mysql_parse | sql_parse.cc | 5640 || Waiting for query cache lock | 0.000012 | try_lock | sql_cache.cc | 454 || freeing items | 0.000032 | NULL | NULL | NULL || Waiting for query cache lock | 0.000017 | try_lock | sql_cache.cc | 454 || freeing items | 0.000016 | NULL | NULL | NULL || storing result in query cache | 0.000017 | end_of_result | sql_cache.cc | 1020 || logging slow query | 0.000018 | log_slow_statement | sql_parse.cc | 1461 || logging slow query | 0.000050 | log_slow_statement | sql_parse.cc | 1470 || cleaning up | 0.000018 | dispatch_command | sql_parse.cc | 1417 |+--------------------------------+----------+-----------------------+---------------+-------------+25 rows in set (0.00 sec)mysql> show profile source for query 2;+--------------------------------+----------+-----------------------+--------------+-------------+| Status | Duration | Source_function | Source_file | Source_line |+--------------------------------+----------+-----------------------+--------------+-------------+| starting | 0.000051 | NULL | NULL | NULL || Waiting for query cache lock | 0.000014 | try_lock | sql_cache.cc | 454 || checking query cache for query | 0.000016 | send_result_to_client | sql_cache.cc | 1561 || checking privileges on cached | 0.000013 | send_result_to_client | sql_cache.cc | 1652 || checking permissions | 0.000015 | check_access | sql_parse.cc | 4751 || sending cached result to clien | 0.000036 | send_result_to_client | sql_cache.cc | 1749 || logging slow query | 0.000017 | log_slow_statement | sql_parse.cc | 1461 || cleaning up | 0.000018 | dispatch_command | sql_parse.cc | 1417 |+--------------------------------+----------+-----------------------+--------------+-------------+8 rows in set (0.00 sec)可以清晰地看到缓存中命中时,大大节省了后台的开销。当然缓存的使用也需要根据各种场景(表的数据规模,更新频率等)考察使用,并不是启用缓存就一定能够提高查询效率。这里仅仅作为SHOW PROFILE的一个应用示例。