Home > Database > Mysql Tutorial > MySQL中使用SHOW PROFILE命令分析性能的用法整理_MySQL

MySQL中使用SHOW PROFILE命令分析性能的用法整理_MySQL

WBOY
Release: 2016-05-30 17:10:37
Original
1032 people have browsed it

show profile是由Jeremy Cole捐献给MySQL社区版本的。默认的是关闭的,但是会话级别可以开启这个功能。开启它可以让MySQL收集在执行语句的时候所使用的资源。为了统计报表,把profiling设为1
 

mysql> SET profiling = 1;
Copy after login


之后在运行一个查询

mysql> SELECT COUNT(DISTINCT actor.first_name) AS cnt_name, COUNT(*) AS cnt
-> FROM sakila.film_actor
-> INNER JOIN sakila.actor USING(actor_id)
-> GROUP BY sakila.film_actor.film_id
-> ORDER BY cnt_name DESC;
...
997 rows in set (0.03 sec)
Copy after login


这个执行语句的剖析信息存储在这个会话中。使用SHOW PROFILES进行查看。

mysql> SHOW PROFILES\G
Copy after login

*************************** 1. row ***************************
Query_ID: 1
Duration: 0.02596900
Query: SELECT COUNT(DISTINCT actor.first_name) AS cnt_name,...
Copy after login


你可以使用SHOW PROFILE语句来获取已经存储的剖析数据。如果不加参数,会显示状态以及它们持续的时间。

mysql> SHOW PROFILE;
Copy after login

+------------------------+-----------+
| Status | Duration |
+------------------------+-----------+
| (initialization) | 0.000005 |
| Opening tables | 0.000033 |
| System lock | 0.000037 |
| Table lock | 0.000024 |
| init | 0.000079 |
| optimizing | 0.000024 |
| statistics | 0.000079 |
| preparing | 0.00003 |
| Creating tmp table | 0.000124 |
| executing | 0.000008 |
| Copying to tmp table | 0.010048 |
| Creating sort index | 0.004769 |
| Copying to group table | 0.0084880 |
| Sorting result | 0.001136 |
| Sending data | 0.000925 |
| end | 0.00001 |
| removing tmp table | 0.00004 |
| end | 0.000005 |
| removing tmp table | 0.00001 |
| end | 0.000011 |
| query end | 0.00001 |
| freeing items | 0.000025 |
| removing tmp table | 0.00001 |
| freeing items | 0.000016 |
| closing tables | 0.000017 |
| logging slow query | 0.000006 |
+------------------------+-----------+
Copy after login


每行都是状态变化的过程以及它们持续的时间。Status那一列和SHOW FULL PROCESSLIST的State应该是一致的。
这个值是来自于thd->proc_info变量。因此你所查看的这个值是直接来自MySQL内部的。尽管这些数值是比较直接易懂的,你也可以查看MySQL手册。

你可以给SHOW PROFILES指定一个Query_ID来查看指定的语句,还可以给输出添加新的列。如,查看用户和CPU使用。可以用如下命令。

mysql> SHOW PROFILE CPU FOR QUERY 1;
Copy after login


SHOW PROFILE可以深入的查看服务器执行语句的工作情况。以及也能帮助你理解执行语句消耗时间的情况。一些限制是它没有实现的功能,不能查看和剖析其他连接的语句,以及剖析时所引起的消耗。

SHOW PROFILES显示最近发给服务器的多条语句,条数根据会话变量profiling_history_size定义,默认是15,最大值为100。设为0等价于关闭分析功能。

SHOW PROFILE FOR QUERY n,这里的n就是对应SHOW PROFILES输出中的Query_ID。


例如:

mysql> show profiles;
Copy after login

+----------+-------------+---------------------------------------+
| Query_ID | Duration | Query     |
+----------+-------------+---------------------------------------+
| 1 | 0.00037700 | alter table table1 drop column c3 int |
| 2 | 70.37123800 | alter table table1 drop column c3 |
| 3 | 0.00124500 | show tables    |
| 4 | 0.00569800 | select * from table1 where id=2 |
| 5 | 0.00068500 | select count(1) from tables1  |
| 6 | 0.00197900 | select count(1) from table1  |
| 7 | 0.00105900 | alter table tables1 drop c1  |
| 8 | 0.00800200 | alter table table1 drop c1  |
+----------+-------------+---------------------------------------+
8 rows in set (0.00 sec)
Copy after login


mysql> SHOW PROFILE FOR QUERY 2; #查看alter table table1 drop column c3的分析
Copy after login

+------------------------------+-----------+
| Status   | Duration |
+------------------------------+-----------+
| starting   | 0.000183 |
| checking permissions  | 0.000057 |
| checking permissions  | 0.000059 |
| init    | 0.000060 |
| Opening tables  | 0.000071 |
| System lock   | 0.000062 |
| setup   | 0.000080 |
| creating table  | 0.005052 |
| After create   | 0.000220 |
| copy to tmp table  | 0.000244 |
| rename result table  | 70.364027 |
| end    | 0.000575 |
| Waiting for query cache lock | 0.000062 |
| end    | 0.000075 |
| query end   | 0.000057 |
| closing tables  | 0.000061 |
| freeing items  | 0.000080 |
| logging slow query  | 0.000056 |
| logging slow query  | 0.000098 |
| cleaning up   | 0.000059 |
+------------------------------+-----------+
20 rows in set (0.00 sec)
Copy after login

如果没有指定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;
Copy after login

+------------------------------+-----------+----------+------------+
| 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)
Copy after login

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;
Copy after login

Query OK, 0 rows affected (0.00 sec)
Copy after login


mysql> select count(1) as cnt from tran_excution;
Copy after login
Copy after login

+-------+
| cnt |
+-------+
| 14225 |
+-------+
1 row in set (0.00 sec)
Copy after login

由于已经启用了查询缓存,相同查询(非分区表)可以直接在查询缓存中命中。

mysql> select count(1) as cnt from tran_excution;
Copy after login
Copy after login

我们仔细看下两个同样的语句的分析。

mysql> show profile source for query 1;
Copy after login

+--------------------------------+----------+-----------------------+---------------+-------------+
| 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)
Copy after login


mysql> show profile source for query 2;
Copy after login

+--------------------------------+----------+-----------------------+--------------+-------------+
| 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)
Copy after login

可以清晰地看到缓存中命中时,大大节省了后台的开销。当然缓存的使用也需要根据各种场景(表的数据规模,更新频率等)考察使用,并不是启用缓存就一定能够提高查询效率。这里仅仅作为SHOW PROFILE的一个应用示例。

Related labels:
source:php.cn
Statement of this Website
The content of this article is voluntarily contributed by netizens, and the copyright belongs to the original author. This site does not assume corresponding legal responsibility. If you find any content suspected of plagiarism or infringement, please contact admin@php.cn
Popular Tutorials
More>
Latest Downloads
More>
Web Effects
Website Source Code
Website Materials
Front End Template