通过 show profile 分析 SQL

2022/1/18 2:05:50

编程Tag： SQL show messages block cpu source profile ops faults

本文主要是介绍通过 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的文章就介绍到这儿，希望我们推荐的文章对大家有所帮助，也希望大家多多支持为之网！

通过 show profile 分析 SQL

show processlist

show profile

相关编程文章