通过 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解析执行过程中每个步骤对应的源码的文件、 函数名以及具体的源文件行数。


上一篇:变量存放指定段


下一篇:keras实现textcnn