您的位置：首页 > 数据库 > MySQL

show profile使用方法查看mysql性能

2017-11-25 00:13 483 查看

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

?

1	mysql> SET profiling = 1;

之后在运行一个查询

?

1
2
3
4
5
6
7

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

...

rows

in

set

(0.03
sec)

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

?

1	mysql> SHOW PROFILES\G

1
2
3
4

*************************** 1. row ***************************

Query_ID: 1

Duration: 0.02596900

Query: SELECT COUNT(DISTINCT actor.first_name) AS cnt_name,...

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

?

1	mysql> SHOW PROFILE;

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30

+------------------------+-----------+

| 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
1717a
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 |

+------------------------+-----------+

每行都是状态变化的过程以及它们持续的时间。Status那一列和SHOW FULL PROCESSLIST的State应该是一致的。

这个值是来自于thd->proc_info变量。因此你所查看的这个值是直接来自MySQL内部的。尽管这些数值是比较直接易懂的，你也可以查看MySQL手册。

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

?

1	mysql> SHOW PROFILE CPU FOR QUERY 1;

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

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

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

例如：

?

1	mysql> show profiles;

1
2
3
4
5
6
7
8
9
10
11
12
13

+----------+-------------+---------------------------------------+

| 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)

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25

+------------------------------+-----------+

| 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)

如果没有指定FOR QUERY，那么输出最近一条语句的信息。

LIMIT部分的用法与SELECT中LIMIT子句一致，不赘述。

type是可选的，取值范围可以如下：
ALL 显示所有性能信息
BLOCK IO 显示块IO操作的次数
CONTEXT SWITCHES 显示上下文切换次数，不管是主动还是被动
CPU 显示用户CPU时间、系统CPU时间
IPC 显示发送和接收的消息数量
MEMORY [暂未实现]
PAGE FAULTS 显示页错误数量
SOURCE 显示源码中的函数名称与位置
SWAPS 显示SWAP的次数

例：

?

1	mysql> show profile cpu for query 2;

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25

+------------------------------+-----------+----------+------------+

| 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分析查询缓存命中的性能优势。

?

1	mysql> set profiling=1;

1	Query OK, 0 rows affected (0.00 sec)

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

1
2
3
4
5
6

+-------+

| cnt |

+-------+

| 14225 |

+-------+

1 row in set (0.00 sec)

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

?

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

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

?

1	mysql> show profile source for query 1;

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30

+--------------------------------+----------+-----------------------+---------------+-------------+

| 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)

1	mysql> show profile source for query 2;

1
2
3
4
5
6
7
8
9
10
11
12
13

+--------------------------------+----------+-----------------------+--------------+-------------+

| 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)

内容来自用户分享和网络整理，不保证内容的准确性，如有侵权内容，可联系管理员处理

标签：

相关文章推荐

新的分享

章节导航