Mysql Show Profile

逆流者 2021年04月04日 35次浏览

简介

mysql提供可以用来分析当前会话中语句执行的资源消耗情况,可以用于SQL的调优的测量。

官网:https://dev.mysql.com/doc/refman/8.0/en/show-profile.html

默认情况下,参数处于关闭状态,并保存最近15次的运行结果。

分析步骤

  1. 是否支持,看看当前的mysql版本是否支持
mysql> Show  variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | OFF   |
+---------------+-------+
1 row in set (0.04 sec)
# 默认是关闭,使用前需要开启
  1. 开启功能,默认是关闭,使用前需要开启
mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql> Show  variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | ON    |
+---------------+-------+
1 row in set (0.05 sec)
  1. 运行SQL
mysql> select * from emp group by id%20  order by 2;
+----+-------+--------+----------+-----+------------+---------+--------+--------+
| id | empno | ename  | job      | mgr | hiredate   | sal     | comm   | deptno |
+----+-------+--------+----------+-----+------------+---------+--------+--------+
|  1 |  1002 | Oobqzz | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    100 |
|  2 |  1003 | ESDoGs | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    108 |
|  3 |  1004 | qZXPfi | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    104 |
|  4 |  1005 | ZxrpzB | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    101 |
|  5 |  1006 | tpqNQQ | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    106 |
|  6 |  1007 | JCHGkg | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    100 |
|  7 |  1008 | QVjinQ | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    102 |
|  8 |  1009 | cqwnXX | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    109 |
|  9 |  1010 | YVLQWn | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    104 |
| 10 |  1011 | uKopHs | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    108 |
| 11 |  1012 | mEknMS | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    101 |
| 12 |  1013 | XyzdPR | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    107 |
| 13 |  1014 | kRBijz | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    108 |
| 14 |  1015 | RGFiZA | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    105 |
| 15 |  1016 | bEVOht | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    104 |
| 16 |  1017 | qdwVnE | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    101 |
| 17 |  1018 | YvhAdQ | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    108 |
| 18 |  1019 | asPVhZ | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    105 |
| 19 |  1020 | KTpTzR | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    106 |
| 20 |  1021 | SnOcYH | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    103 |
+----+-------+--------+----------+-----+------------+---------+--------+--------+
20 rows in set (2.12 sec)

mysql> select * from emp group by id%10 limit 150000;
+----+-------+--------+----------+-----+------------+---------+--------+--------+
| id | empno | ename  | job      | mgr | hiredate   | sal     | comm   | deptno |
+----+-------+--------+----------+-----+------------+---------+--------+--------+
| 10 |  1011 | uKopHs | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    108 |
|  1 |  1002 | Oobqzz | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    100 |
|  2 |  1003 | ESDoGs | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    108 |
|  3 |  1004 | qZXPfi | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    104 |
|  4 |  1005 | ZxrpzB | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    101 |
|  5 |  1006 | tpqNQQ | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    106 |
|  6 |  1007 | JCHGkg | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    100 |
|  7 |  1008 | QVjinQ | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    102 |
|  8 |  1009 | cqwnXX | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    109 |
|  9 |  1010 | YVLQWn | salesman |   1 | 2021-04-04 | 2000.00 | 400.00 |    104 |
+----+-------+--------+----------+-----+------------+---------+--------+--------+
10 rows in set (1.91 sec)
  1. 查看结果
mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query                                         |
+----------+------------+-----------------------------------------------+
|        1 | 0.00059150 | Show  variables like 'profiling'              |
|        2 | 1.82311475 | select * from emp group by id%10 limit 150000 |
|        3 | 1.92254050 | select * from emp group by id%20  order by 5  |
|        4 | 1.91409800 | select * from emp group by id%20  order by 2  |
|        5 | 1.81238075 | select * from emp group by id%10 limit 150000 |
+----------+------------+-----------------------------------------------+
5 rows in set (0.14 sec)
  1. 诊断SQL
    show profile cpu,block io for query n (n为上一步前面的问题SQL数字号码);
mysql> show profile cpu,block io for query 4;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000037 | 0.000000 | 0.000000   | NULL         | NULL          |
| checking permissions | 0.000005 | 0.000000 | 0.000000   | NULL         | NULL          |
| Opening tables       | 0.000016 | 0.000000 | 0.000000   | NULL         | NULL          |
| System lock          | 0.000008 | 0.000000 | 0.000000   | NULL         | NULL          |
| init                 | 0.000018 | 0.000000 | 0.000000   | NULL         | NULL          |
| optimizing           | 0.000003 | 0.000000 | 0.000000   | NULL         | NULL          |
| statistics           | 0.000017 | 0.000000 | 0.000000   | NULL         | NULL          |
| preparing            | 0.000006 | 0.000000 | 0.000000   | NULL         | NULL          |
| Creating tmp table   | 0.000308 | 0.000000 | 0.000000   | NULL         | NULL          |
| executing            | 0.000003 | 0.000000 | 0.000000   | NULL         | NULL          |
| Copying to tmp table | 1.913459 | 1.921875 | 0.000000   | NULL         | NULL          |
| Sorting result       | 0.000025 | 0.000000 | 0.000000   | NULL         | NULL          |
| Sending data         | 0.000044 | 0.000000 | 0.000000   | NULL         | NULL          |
| end                  | 0.000004 | 0.000000 | 0.000000   | NULL         | NULL          |
| removing tmp table   | 0.000007 | 0.000000 | 0.000000   | NULL         | NULL          |
| end                  | 0.000002 | 0.000000 | 0.000000   | NULL         | NULL          |
| query end            | 0.000003 | 0.000000 | 0.000000   | NULL         | NULL          |
| closing tables       | 0.000010 | 0.000000 | 0.000000   | NULL         | NULL          |
| freeing items        | 0.000124 | 0.000000 | 0.000000   | NULL         | NULL          |
| logging slow query   | 0.000002 | 0.000000 | 0.000000   | NULL         | NULL          |
| cleaning up          | 0.000001 | 0.000000 | 0.000000   | NULL         | NULL          |
+----------------------+----------+----------+------------+--------------+---------------+
21 rows in set (0.19 sec)

参数:

类型含义
ALL显示所有的开销信息
BLOCK IO显示块IO相关开销
CONTEXT SWITCHES上下文切换相关开销
CPU显示CPU相关开销信息
IPC显示发送和接收相关开销信息
MEMORY显示内存相关开销信息
PAGE FAULTS显示页面错误相关开销信息
SOURCE显示和Source_function,Source_file,Source_line相关的开销信息
SWAPS显示交换次数相关开销的信息

展示个最全的:

mysql> show profile all for query 4;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+---------------+-------------+
| Status               | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file   | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+---------------+-------------+
| starting             | 0.000037 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | NULL            | NULL          | NULL        |
| checking permissions | 0.000005 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_parse.cc  |        4833 |
| Opening tables       | 0.000016 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_base.cc   |        4888 |
| System lock          | 0.000008 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | lock.cc       |         299 |
| init                 | 0.000018 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        2594 |
| optimizing           | 0.000003 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |         865 |
| statistics           | 0.000017 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        1071 |
| preparing            | 0.000006 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        1093 |
| Creating tmp table   | 0.000308 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        1616 |
| executing            | 0.000003 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        1851 |
| Copying to tmp table | 1.913459 | 1.921875 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        1998 |
| Sorting result       | 0.000025 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        2282 |
| Sending data         | 0.000044 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        2395 |
| end                  | 0.000004 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |        2630 |
| removing tmp table   | 0.000007 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |       11304 |
| end                  | 0.000002 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_select.cc |       11329 |
| query end            | 0.000003 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_parse.cc  |        4512 |
| closing tables       | 0.000010 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_parse.cc  |        4564 |
| freeing items        | 0.000124 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_parse.cc  |        5840 |
| logging slow query   | 0.000002 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_parse.cc  |        1512 |
| cleaning up          | 0.000001 | 0.000000 | 0.000000   | NULL              | NULL                | NULL         | NULL          | NULL          | NULL              | NULL              | NULL              | NULL  | <unknown>       | sql_parse.cc  |        1468 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+---------------+-------------+
21 rows in set (0.23 sec)
  1. 特别需要注意的结论
  • converting HEAP to MyISAM 查询结果太大,内存都不够用了往磁盘上搬了。
  • Creating tmp table 创建临时表,拷贝数据到临时表,用完再删除。
  • Copying to tmp table on disk 把内存中临时表复制到磁盘,很危险!
  • locked 锁了都