profiling – MySQL资源使用情况剖析工具
2,294 total views, 1 views today
profiling 用于剖析当前session执行SQL语句的资源使用情况。
如何使用profileing
1、开启profiling
set profiling = 1;
profiling变量默认是0（off），且一般开启session级别。
2、执行需要诊断剖析SQL语句
show tables like ‘sbtest%’;
3、查看性能剖析
先明确两个命令：
show prfiles ：查看最近执行的SQL命令的信息（包含 QUERY_ID，持续时间，命令），展现的条数由 profiling_history_size 变量确定，默认是15，如果想保留更多请调大该变量的值，最大值100。最小值是0，表示禁用profiling。
show profile ：展现单个SQL命令剖析的细节。根据 show profiles的输出结果中的 QUERY_ID，带入到 show profile for query n中，那么展示的就是这个QUERY_ID的性能剖析信息。不写 for query n ，展示的则是最后一次执行的SQL命令的剖析信息。
|
1 2 3 4 5 6 7 8 9 10 |
mysql> show profiles; +----------+------------+----------------------------+ | Query_ID | Duration | Query | +----------+------------+----------------------------+ | 1 | 0.00037000 | SELECT DATABASE() | | 2 | 0.00081050 | show databases | | 3 | 0.01929200 | show tables | | 4 | 0.01827725 | show tables like 'sbtest%' | +----------+------------+----------------------------+ 4 rows in set, 1 warning (0.00 sec) |
我们想看 QUERY_ID 为4的SQL命令剖析内容。可以看到“checking permissions”占据了最多的时间消耗。
|
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 |
mysql> show profile for query 4; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000133 | | checking permissions | 0.000020 | | checking permissions | 0.000013 | | Opening tables | 0.000107 | | init | 0.000030 | | System lock | 0.000022 | | optimizing | 0.000015 | | statistics | 0.000038 | | preparing | 0.000034 | | executing | 0.000019 | | checking permissions | 0.015576 | | Sending data | 0.001280 | | end | 0.000021 | | query end | 0.000019 | | closing tables | 0.000011 | | removing tmp table | 0.000844 | | closing tables | 0.000023 | | freeing items | 0.000037 | | cleaning up | 0.000036 | +----------------------+----------+ 19 rows in set, 1 warning (0.00 sec) |
可以扩展看到更多的详细资料类型占用，比如CPU、内存、上下文切换等等。
- ALL displays all information
- BLOCK IO displays counts for block input and output operations
- CONTEXT SWITCHES displays counts for voluntary and involuntary context switches
- CPU displays user and system CPU usage times
- IPC displays counts for messages sent and received
- MEMORY is not currently implemented
- PAGE FAULTS displays counts for major and minor page faults
- SOURCE displays the names of functions from the source code, together with the name and line number of the file in which the function occurs
- SWAPS displays swap counts
查看用户和系统CPU使用时间
|
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 |
mysql> show profile CPU for query 4; +----------------------+----------+----------+------------+ | Status | Duration | CPU_user | CPU_system | +----------------------+----------+----------+------------+ | starting | 0.000133 | 0.000000 | 0.000000 | | checking permissions | 0.000020 | 0.000000 | 0.000000 | | checking permissions | 0.000013 | 0.000000 | 0.000000 | | Opening tables | 0.000107 | 0.000000 | 0.000000 | | init | 0.000030 | 0.000000 | 0.000000 | | System lock | 0.000022 | 0.000000 | 0.000000 | | optimizing | 0.000015 | 0.000000 | 0.000000 | | statistics | 0.000038 | 0.000000 | 0.000000 | | preparing | 0.000034 | 0.000000 | 0.000000 | | executing | 0.000019 | 0.000000 | 0.000000 | | checking permissions | 0.015576 | 0.008000 | 0.008000 | | Sending data | 0.001280 | 0.001000 | 0.000000 | | end | 0.000021 | 0.000000 | 0.000000 | | query end | 0.000019 | 0.000000 | 0.000000 | | closing tables | 0.000011 | 0.000000 | 0.000000 | | removing tmp table | 0.000844 | 0.000000 | 0.001000 | | closing tables | 0.000023 | 0.000000 | 0.000000 | | freeing items | 0.000037 | 0.000000 | 0.000000 | | cleaning up | 0.000036 | 0.000000 | 0.000000 | +----------------------+----------+----------+------------+ 19 rows in set, 1 warning (0.00 sec) |
查看IO输入、输出的次数
|
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 |
mysql> show profile BLOCK IO for query 4; +----------------------+----------+--------------+---------------+ | Status | Duration | Block_ops_in | Block_ops_out | +----------------------+----------+--------------+---------------+ | starting | 0.000133 | 0 | 0 | | checking permissions | 0.000020 | 0 | 0 | | checking permissions | 0.000013 | 0 | 0 | | Opening tables | 0.000107 | 0 | 0 | | init | 0.000030 | 0 | 0 | | System lock | 0.000022 | 0 | 0 | | optimizing | 0.000015 | 0 | 0 | | statistics | 0.000038 | 0 | 0 | | preparing | 0.000034 | 0 | 0 | | executing | 0.000019 | 0 | 0 | | checking permissions | 0.015576 | 0 | 0 | | Sending data | 0.001280 | 0 | 0 | | end | 0.000021 | 0 | 0 | | query end | 0.000019 | 0 | 0 | | closing tables | 0.000011 | 0 | 0 | | removing tmp table | 0.000844 | 0 | 0 | | closing tables | 0.000023 | 0 | 0 | | freeing items | 0.000037 | 0 | 0 | | cleaning up | 0.000036 | 0 | 0 | +----------------------+----------+--------------+---------------+ 19 rows in set, 1 warning (0.00 sec) |
也可以通过 INFORMATION_SCHEMA.PROFILING 表查询profiling信息。这两种方式的结果相同。
|
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 |
show profile CPU for query 4; mysql> SELECT STATE, FORMAT(DURATION, 6) AS DURATION FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID = 4 ORDER BY SEQ; +----------------------+----------+ | STATE | DURATION | +----------------------+----------+ | starting | 0.000133 | | checking permissions | 0.000020 | | checking permissions | 0.000013 | | Opening tables | 0.000107 | | init | 0.000030 | | System lock | 0.000022 | | optimizing | 0.000015 | | statistics | 0.000038 | | preparing | 0.000034 | | executing | 0.000019 | | checking permissions | 0.015576 | | Sending data | 0.001280 | | end | 0.000021 | | query end | 0.000019 | | closing tables | 0.000011 | | removing tmp table | 0.000844 | | closing tables | 0.000023 | | freeing items | 0.000037 | | cleaning up | 0.000036 | +----------------------+----------+ 19 rows in set, 1 warning (0.00 sec) |
参考：https://dev.mysql.com/doc/refman/5.7/en/show-profile.html