通过 show profile 分析 SQL
2022/1/18 2:05:50
本文主要是介绍通过 show profile 分析 SQL，对大家解决编程问题具有一定的参考价值，需要的程序猿们随着小编来一起学习吧！
MySQL学习系列
通过上面的描述可知， 当我们通过应用程序访问 MySQL 服务时， 有时候性能不一定全部卡在语句的执行上。 当然通过慢查询日志定位那些执行效率较低的SQL 语句时候我们常用的手段， 但是：
一、 慢查询日志在查询结束以后才记录， 在应用反映执行效率出现问题的时候查询未必执行完成；
二、 有时候问题的产生不一定是语句的执行， 有可能是其他原因导致的。 慢查询日志并不能定位问题。
show processlist
mysql> show processlist; +----+------+-----------+------+---------+------+-------------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+------+-----------+------+---------+------+-------------+------------------+ | 63 | root | localhost | NULL | Query | 0 | System lock | show processlist | +----+------+-----------+------+---------+------+-------------+------------------+ 1 row in set (0.00 sec)
这个时候通过 show processlist;查看线程状态非常有用,这可以让我们很快地了解当前 MySQL 在进行的线程,包括线程的状态、 是否锁表等， 可以实时地查看SQL 的执行情况， 同时对一些锁表操作进行优化。 在一个繁忙的服务器上， 可能会看到大量的不正常的状态， 例如 statistics 正占用大量的时间。 这通常表示， 某个地方有异常了。 线程常见的状态有很多， 比如
- statistics
The server is calculating statistics to develop a query execution plan. If a threadis in this state for a long time, the server is probably disk-bound performing otherwork.
服务器正在计算统计信息以研究一个查询执行计划。 如果线程长时间处于此状态， 则服务器可能是磁盘绑定执行其他工作。 - Creating tmp table
The thread is creating a temporary table in memory or on disk. If the table is created in memory but later is converted to an on-disk table, the state during that operation is Copying to tmp table on disk.
该线程正在内存或磁盘上创建临时表。 如果表在内存中创建但稍后转换为磁盘表， 则该操作期间的状态将为 Copying to tmp table on disk - Sending data
The thread is reading and processing rows for a SELECT statement, and sending data to the client. Because operations occurring during this state tend to perform large amounts of disk access (reads), it is often the longest-running state over the lifetime of a given query.
线程正在读取和处理 SELECT 语句的行 ， 并将数据发送到客户端。 由于在此状态期间发生的操作往往会执行大量磁盘访问（读取） ， 因此它通常是给定查询生命周期中运行时间最长的状态
参考官方文档：https://dev.mysql.com/doc/refman/5.7/en/general-thread-states.html
show profile
对于每个线程到底时间花在哪里， 可以通过 show profile 来分析。
1、 首先检查当前 MySQL 是否支持 profile
mysql> select @@have_profiling; +------------------+ | @@have_profiling | +------------------+ | YES | +------------------+ 1 row in set, 1 warning (0.00 sec)
2、 默认 profiling 是关闭的， 可以通过 set 语句在 Session 级别开启 profiling:
select @@profiling; set profiling=1;
mysql> select @@profiling; +-------------+ | @@profiling | +-------------+ | 0 | +-------------+ 1 row in set, 1 warning (0.00 sec) mysql> set profiling=1; Query OK, 0 rows affected, 1 warning (0.00 sec) mysql> select @@profiling; +-------------+ | @@profiling | +-------------+ | 1 | +-------------+ 1 row in set, 1 warning (0.00 sec)
3、 执行一个 SQL 查询
select count(*) from order_exp;
4、 通过 show profiles 语句， 看到当前 SQL 的 Query ID
show profiles;
mysql> use test; Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed mysql> select count(*) from order_exp; +----------+ | count(*) | +----------+ | 10567 | +----------+ 1 row in set (0.01 sec) mysql> show profiles; +----------+------------+--------------------------------+ | Query_ID | Duration | Query | +----------+------------+--------------------------------+ | 1 | 0.00034400 | select @@profiling | | 2 | 0.00023950 | select count(*) from order_exp | | 3 | 0.00050475 | SELECT DATABASE() | | 4 | 0.00095700 | show databases | | 5 | 0.00055825 | show tables | | 6 | 0.00665250 | select count(*) from order_exp | +----------+------------+--------------------------------+ 6 rows in set, 1 warning (0.00 sec)
5、 通过 show profile for query 语句能够看到执行过程中线程的每个状态和消
耗的时间
show profile for query 6;
mysql> show profile for query 6; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000171 | | Opening tables | 0.000030 | | System lock | 0.000112 | | checking permissions | 0.000016 | | Opening tables | 0.000029 | | init | 0.000067 | | System lock | 0.000025 | | optimizing | 0.000077 | | statistics | 0.000031 | | preparing | 0.000023 | | executing | 0.000009 | | Sending data | 0.005908 | | end | 0.000025 | | query end | 0.000032 | | closing tables | 0.000019 | | freeing items | 0.000049 | | cleaning up | 0.000031 | +----------------------+----------+ 17 rows in set, 1 warning (0.02 sec)
通过仔细检查 show profile for query 的输出， 能够发现在执行 COUNT(*)的过程中， 时间主要消耗在 Sending data 这个状态上。
6、 在获取到最消耗时间的线程状态后， MySQL 支持进一步选择 all、 cpu、block io、 contextswitch、 page faults 等明细类型来查看 MySQL 在使用什么资源上耗费了过高的时间:
show profile all for query 6\G
mysql> show profile all for query 6\G
*************************** 1. row ***************************
Status: starting
Duration: 0.000171
CPU_user: 0.000000
CPU_system: 0.000164
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: NULL
Source_file: NULL
Source_line: NULL
*************************** 2. row ***************************
Status: Opening tables
Duration: 0.000030
CPU_user: 0.000000
CPU_system: 0.000030
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: open_ltable
Source_file: sql_base.cc
Source_line: 6490
*************************** 3. row ***************************
Status: System lock
Duration: 0.000112
CPU_user: 0.000013
CPU_system: 0.000099
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_lock_tables
Source_file: lock.cc
Source_line: 330
*************************** 4. row ***************************
Status: checking permissions
Duration: 0.000016
CPU_user: 0.000007
CPU_system: 0.000009
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: check_access
Source_file: sql_authorization.cc
Source_line: 809
*************************** 5. row ***************************
Status: Opening tables
Duration: 0.000029
CPU_user: 0.000012
CPU_system: 0.000017
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: open_tables
Source_file: sql_base.cc
Source_line: 5815
*************************** 6. row ***************************
Status: init
Duration: 0.000067
CPU_user: 0.000028
CPU_system: 0.000039
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: handle_query
Source_file: sql_select.cc
Source_line: 128
*************************** 7. row ***************************
Status: System lock
Duration: 0.000025
CPU_user: 0.000000
CPU_system: 0.000084
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_lock_tables
Source_file: lock.cc
Source_line: 330
*************************** 8. row ***************************
Status: optimizing
Duration: 0.000077
CPU_user: 0.000000
CPU_system: 0.000018
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: optimize
Source_file: sql_optimizer.cc
Source_line: 158
*************************** 9. row ***************************
Status: statistics
Duration: 0.000031
CPU_user: 0.000000
CPU_system: 0.000030
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: optimize
Source_file: sql_optimizer.cc
Source_line: 374
*************************** 10. row ***************************
Status: preparing
Duration: 0.000023
CPU_user: 0.000000
CPU_system: 0.000023
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: optimize
Source_file: sql_optimizer.cc
Source_line: 482
*************************** 11. row ***************************
Status: executing
Duration: 0.000009
CPU_user: 0.000000
CPU_system: 0.000010
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: exec
Source_file: sql_executor.cc
Source_line: 126
*************************** 12. row ***************************
Status: Sending data
Duration: 0.005908
CPU_user: 0.005915
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 1
Swaps: 0
Source_function: exec
Source_file: sql_executor.cc
Source_line: 202
*************************** 13. row ***************************
Status: end
Duration: 0.000025
CPU_user: 0.000018
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: handle_query
Source_file: sql_select.cc
Source_line: 206
*************************** 14. row ***************************
Status: query end
Duration: 0.000032
CPU_user: 0.000031
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_execute_command
Source_file: sql_parse.cc
Source_line: 4959
*************************** 15. row ***************************
Status: closing tables
Duration: 0.000019
CPU_user: 0.000018
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_execute_command
Source_file: sql_parse.cc
Source_line: 5018
*************************** 16. row ***************************
Status: freeing items
Duration: 0.000049
CPU_user: 0.000050
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_parse
Source_file: sql_parse.cc
Source_line: 5637
*************************** 17. row ***************************
Status: cleaning up
Duration: 0.000031
CPU_user: 0.000030
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: dispatch_command
Source_file: sql_parse.cc
Source_line: 1933
17 rows in set, 1 warning (0.00 sec)
其中
*************************** 12. row ***************************
Status: Sending data
Duration: 0.005908
CPU_user: 0.005915
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 1
Swaps: 0
Source_function: exec
Source_file: sql_executor.cc
Source_line: 202
能够发现 Sending data 状态下， 时间主要消耗在 CPU 上了。所以show profile能够在做SQL优化时帮助我们了解时间都耗费到哪里去了，同时如果 MySQL 源码感兴趣， 还可以通过 show profile source for query 查看 SQL解析执行过程中每个步骤对应的源码的文件、 函数名以及具体的源文件行数。
这篇关于通过 show profile 分析 SQL的文章就介绍到这儿，希望我们推荐的文章对大家有所帮助，也希望大家多多支持为之网！
- 2025-01-04百万架构师第六课：设计模式：策略模式及模板模式
- 2025-01-04百万架构师第七课：设计模式：装饰器模式及观察者模式
- 2025-01-04适用于企业管理的协作工具API推荐
- 2025-01-04挑战16：被限流的CPU
- 2025-01-03企业在选择工具时，如何评估其背后的技术团队
- 2025-01-03Angular中打造动态多彩标签组件的方法
- 2025-01-03Flask过时了吗？FastAPI才是未来？
- 2025-01-0311个每位开发者都应知道的免费实用网站
- 2025-01-03从REST到GraphQL：为什么以及我是如何完成转型的
- 2025-01-03掌握RAG：从单次问答到连续对话
