MySQL中show profile详解
1.SHOW PROFILE 官网
参考文档链接：https://dev.mysql.com/doc/refman/8.0/en/show-profile.html
SHOW PROFILE [type [, type] ... ]
[FOR QUERY n]
[LIMIT row_count [OFFSET offset]]
type: {
ALL
| BLOCK IO
| CONTEXT SWITCHES
| CPU
| IPC
| MEMORY
| PAGE FAULTS
| SOURCE
| SWAPS
}
2.开启show profile功能
#1.默认为：关闭，To control profiling, use theprofilingsession variable, which has a default value of 0 (OFF).
Enable profiling by settingprofilingto 1 orON:1表示开启，0表示关闭
mysql> show variables like "profiling";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling | OFF |
+---------------+-------+
1 row in set (0.01 sec)
#2，在线开启
mysql> SET profiling = 1;
mysql> show variables like "profiling";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling | ON |
+---------------+-------+
1 row in set (0.00 sec)
3.show profile参数解析：
#1.参数
①ALL：显示所有的开销信息。
②BLOCK IO：显示块IO开销。
③CONTEXT SWITCHES：上下文切换开销。
④CPU：显示CPU开销信息。
⑤IPC：显示发送和接收开销信息。
⑥MEMORY：显示内存开销信息。
⑦PAGE FAULTS：显示页面错误开销信息。
⑧SOURCE：显示和Source_function，Source_file，Source_line相关的开销信息。
⑨SWAPS：显示交换次数开销信息。
#2:日常开发需注意的结论
①Converting HEAP to MyISAM：查询结果太大，内存不够，数据往磁盘上搬了。
②Creating tmp table：创建临时表。先拷贝数据到临时表，用完后再删除临时表。
③Copying to tmp table on disk：把内存中临时表复制到磁盘上，危险！！！
④locked。
-
ALLdisplays all information -
BLOCK IOdisplays counts for block input and output operations -
CONTEXT SWITCHESdisplays counts for voluntary and involuntary context switches -
CPUdisplays user and system CPU usage times -
IPCdisplays counts for messages sent and received -
MEMORYis not currently impPAGE FAULTSdisplays counts for majSOURCEdisplays the names of functions from the source code, together with the name and line number of the file in which the funSWAPSdisplamysql> SELECT @@profiling+------------| @@profiling | +-------------+ | 0 mysql> SET profiling
4.举例说明
mysql> show variables like "profiling"; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | profiling | OFF | +---------------+-------+ 1 row in set (0.01 sec) mysql> SET profiling = 1; Query OK, 0 rows affected, 1 warning (0.00 sec) mysql> show variables like "profiling"; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | profiling | ON | +---------------+-------+ 1 row in set (0.00 sec) mysql> show profile for query 1; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000082 | | checking permissions | 0.000022 | | Opening tables | 0.000106 | | init | 0.000011 | | System lock | 0.000010 | | optimizing | 0.000007 | | optimizing | 0.000010 | | statistics | 0.000029 | | preparing | 0.000021 | | statistics | 0.000010 | | preparing | 0.000013 | | executing | 0.001263 | | end | 0.000015 | | query end | 0.000016 | | closing tables | 0.000011 | | freeing items | 0.000022 | | cleaning up | 0.000013 | +----------------------+----------+ 17 rows in set, 1 warning (0.00 sec) mysql> show profile for query 2; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000076 | | checking permissions | 0.000014 | | Opening tables | 0.000042 | | init | 0.000014 | | optimizing | 0.000012 | | executing | 0.000014 | | end | 0.000006 | | query end | 0.000008 | | closing tables | 0.000007 | | freeing items | 0.000015 | | cleaning up | 0.000024 | +----------------------+----------+ 11 rows in set, 1 warning (0.00 sec) mysql> show profile for query 3; +----------------------------+----------+ | Status | Duration | +----------------------------+----------+ | starting | 0.000120 | | checking permissions | 0.000013 | | Opening tables | 0.000803 | | init | 0.000014 | | System lock | 0.000009 | | optimizing | 0.000018 | | statistics | 0.000044 | | preparing | 0.000028 | | Creating tmp table | 0.000367 | | executing | 0.000275 | | end | 0.000010 | | query end | 0.000005 | | waiting for handler commit | 0.000014 | | closing tables | 0.000012 | | freeing items | 0.000020 | | cleaning up | 0.000022 | +----------------------------+----------+ 16 rows in set, 1 warning (0.00 sec) mysql> show profile cpu for query 3; +----------------------------+----------+----------+------------+ | Status | Duration | CPU_user | CPU_system | +----------------------------+----------+----------+------------+ | starting | 0.000120 | 0.000117 | 0.000000 | | checking permissions | 0.000013 | 0.000012 | 0.000000 | | Opening tables | 0.000803 | 0.000807 | 0.000000 | | init | 0.000014 | 0.000009 | 0.000000 | | System lock | 0.000009 | 0.000009 | 0.000000 | | optimizing | 0.000018 | 0.000017 | 0.000000 | | statistics | 0.000044 | 0.000045 | 0.000000 | | preparing | 0.000028 | 0.000028 | 0.000000 | | Creating tmp table | 0.000367 | 0.000369 | 0.000000 | | executing | 0.000275 | 0.000275 | 0.000000 | | end | 0.000010 | 0.000007 | 0.000000 | | query end | 0.000005 | 0.000005 | 0.000000 | | waiting for handler commit | 0.000014 | 0.000013 | 0.000000 | | closing tables | 0.000012 | 0.000012 | 0.000000 | | freeing items | 0.000020 | 0.000020 | 0.000000 | | cleaning up | 0.000022 | 0.000021 | 0.000000 | +----------------------------+----------+----------+------------+ 16 rows in set, 1 warning (0.00 sec)
mysql> show profile all for query 1; +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+ | 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.000082 | 0.000027 | 0.000052 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL | | checking permissions | 0.000022 | 0.000008 | 0.000014 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 2200 | | Opening tables | 0.000106 | 0.000036 | 0.000069 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 5761 | | init | 0.000011 | 0.000003 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | execute | sql_select.cc | 552 | | System lock | 0.000010 | 0.000004 | 0.000007 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 331 | | optimizing | 0.000007 | 0.000002 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 277 | | optimizing | 0.000010 | 0.000004 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 277 | | statistics | 0.000029 | 0.000010 | 0.000020 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 590 | | preparing | 0.000021 | 0.000007 | 0.000013 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 674 | | statistics | 0.000010 | 0.000003 | 0.000007 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 590 | | preparing | 0.000013 | 0.000005 | 0.000008 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 674 | | executing | 0.001263 | 0.001267 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 7 | 0 | ExecuteIteratorQuery | sql_union.cc | 1127 | | end | 0.000015 | 0.000011 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | execute | sql_select.cc | 585 | | query end | 0.000016 | 0.000016 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4566 | | closing tables | 0.000011 | 0.000011 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4624 | | freeing items | 0.000022 | 0.000021 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_sql_command | sql_parse.cc | 5075 | | cleaning up | 0.000013 | 0.000013 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 2276 | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+ 17 rows in set, 1 warning (0.00 sec)
5.注意
1.Show Profile默认是关闭的，并且开启后只存活于当前会话，也就说每次使用前都需要开启。也可修改MYSQL配置文件来修改。 2.通过Show Profiles查看sql语句的耗时时间，然后通过Show Profile命令对耗时时间长的sql语句进行诊断。 3.注意Show Profile诊断结果中出现相关字段的含义，判断是否需要优化SQL语句。
mysql>SELECT@@profiling;+-------------+| @@profiling |+-------------+| 0 |+-------------+1 row in set (0.00 sec)mysql>SET profiling =1;Query OK, 0 rows affected (0.00 sec)mysql>DROPTABLEIFEXISTS t1;Query OK, 0 rows affected, 1 warning (0.00 sec)mysql>CREATETABLE T1 (id INT);Query OK, 0 rows affected (0.01 sec)mysql>SHOWPROFILES;+----------+----------+--------------------------+| Query_ID | Duration | Query |+----------+----------+--------------------------+| 0 | 0.000088 | SET PROFILING = 1 || 1 | 0.000136 | DROP TABLE IF EXISTS t1 || 2 | 0.011947 | CREATE TABLE t1 (id INT) |+----------+----------+--------------------------+3 rows in set (0.00 sec)mysql>SHOWPROFILE;+----------------------+----------+| Status | Duration |+----------------------+----------+| checking permissions | 0.000040 || creating table | 0.000056 || After create | 0.011363 || query end | 0.000375 || freeing items | 0.000089 || logging slow query | 0.000019 || cleaning up | 0.000005 |+----------------------+----------+7 rows in set (0.00 sec)mysql>SHOWPROFILEFORQUERY1;+--------------------+----------+| Status | Duration |+--------------------+----------+| query end | 0.000107 || freeing items | 0.000008 || logging slow query | 0.000015 || cleaning up | 0.000006 |+--------------------+----------+4 rows in set (0.00 sec)mysql>SHOWPROFILECPUFORQUERY2;+----------------------+----------+----------+------------+| Status | Duration | CPU_user | CPU_system |+----------------------+----------+----------+------------+| checking permissions | 0.000040 | 0.000038 | 0.000002 || creating table | 0.000056 | 0.000028 | 0.000028 || After create | 0.011363 | 0.000217 | 0.001571 || query end | 0.000375 | 0.000013 | 0.000028 || freeing items | 0.000089 | 0.000010 | 0.000014 || logging slow query | 0.000019 | 0.000009 | 0.000010 || cleaning up | 0.000005 | 0.000003 | 0.000002 |+----------------------+----------+----------+------------+7 rows in set (0.00 sec)
Do everything well
