6.4 查看SQL语句执行阶段和进度信息_千金良方：MySQL性能优化金字塔法则-QQ阅读男生科幻网

上QQ阅读APP看本书，新人免费读10天

设备和账号都新为新人

6.4 查看SQL语句执行阶段和进度信息

MariaDB分支支持一个不依赖于performance_schema性能数据的进度展示功能，通过show processlist；语句返回结果的最后一列就是进度信息。

mysql>show processlist;
+----+------+-----------+-----------+---------+------+------------+---------+----------+
| Id | User | Host      | db      | Command | Time | State    | Info         | Progress |
+----+------+-----------+-----------+---------+------+------------+---------+----------+
| 4 | root | localhost | employees | Query |   6 | altering table | alter table salaries add index i_salary（salary）| 93.939 |
| 5 | root | localhost | NULL | Query | 0 | init  | show processlist     |   0.000 |
+----+------+-----------+-----------+---------+------+------------+---------+----------+
2 rows in set（0.00 sec）

在MySQL中也提供了类似的功能，通过具有可预估工作量的阶段事件进行记录与计算，就可以得到一条语句执行的阶段信息和进度信息。下面分别举例介绍如何查看相应的信息。

6.4.1 查看SQL语句执行阶段信息

首先需要进行配置启用，阶段事件默认并未启用，开启一个会话（会话1）。

mysql> use performance_schema
Database changed
mysql> update setup_instruments set enabled='yes', timed='yes' where name like 'stage/%';
Query OK, 120 rows affected（0.00 sec）
Rows matched: 129 Changed: 120 Warnings: 0
mysql> update setup_consumers set enabled='yes' where name like '%stage%';
Query OK, 3 rows affected（0.00 sec）
Rows matched: 3 Changed: 3 Warnings: 0

然后开启第二个会话（会话2），查询thread_id。

mysql> select sys.ps_thread_id（connection_id（））;
+-----------------------------------+
| sys.ps_thread_id（connection_id（））|
+-----------------------------------+
| 119                                |
+-----------------------------------+
1 row in set（0.00 sec）

先对之前旧的信息进行清理，避免干扰（会话1）。

# 先关闭其他线程的事件记录功能，使用前面步骤查询到的thread_id
mysql> update performance_schema.threads set INSTRUMENTED='NO' where THREAD_ID! =119;
Query OK, 101 rows affected（0.00 sec）
Rows matched: 101 Changed: 101 Warnings: 0
# 清空阶段事件的三个表
mysql> truncate events_stages_current; truncate events_stages_history; truncate events_stages_history_long;
Query OK, 0 rows affected（0.00 sec）
......

现在，回到会话2中执行DML语句。

root@localhost : sbtest 06:06:37> select count（＊）from sbtest.sbtest4 where id between 100 and 200;
+----------+
| count（＊）|
+----------+
| 50       |
+----------+
1 row in set（0.00 sec）

在会话1中查询events_stages_history_long表。

mysql> select THREAD_ID, EVENT_NAME, SOURCE, sys.format_time（TIMER_WAIT）as exec_time, WORK_COMPLETED, WORK_ESTIMATED from events_stages_history_long;
+-----------+-----------------+-----------------+-----------+--------------+-------------+
| THREAD_ID | EVENT_NAME | SOURCE | exec_time | WORK_COMPLETED | WORK_ESTIMATED |
+-----------+-----------------+-----------------+-----------+--------------+-------------+
| 119 | stage/sql/starting | socket_connection.cc:107 | 54.19 us | NULL | NULL |
| 119 | stage/sql/checking permissions | sql_authorization.cc:810 | 3.62 us | NULL | NULL |
| 119 | stage/sql/Opening tables | sql_base.cc:5650 | 10.54 us | NULL | NULL |
| 119 | stage/sql/init | sql_select.cc:121 | 16.73 us | NULL | NULL |
| 119 | stage/sql/System lock | lock.cc:323 | 4.77 us | NULL | NULL |
| 119 | stage/sql/optimizing | sql_optimizer.cc:151 | 4.78 us | NULL | NULL |
| 119 | stage/sql/statistics | sql_optimizer.cc:367 | 50.54 us | NULL | NULL |
| 119 | stage/sql/preparing | sql_optimizer.cc:475 | 7.79 us | NULL | NULL |
| 119 | stage/sql/executing | sql_executor.cc:119 | 381.00 ns | NULL | NULL |
| 119 | stage/sql/Sending data | sql_executor.cc:195 | 36.75 us | NULL | NULL |
| 119 | stage/sql/end | sql_select.cc:199 | 931.00 ns | NULL | NULL |
| 119 | stage/sql/query end | sql_parse.cc:4968 | 5.31 us | NULL | NULL |
| 119 | stage/sql/closing tables | sql_parse.cc:5020 | 2.26 us | NULL | NULL |
| 119 | stage/sql/freeing items | sql_parse.cc:5596 | 8.71 us | NULL | NULL |
| 119 | stage/sql/cleaning up | sql_parse.cc:1902 | 449.00 ns | NULL | NULL |
+-----------+-----------------+-----------------+-----------+--------------+-------------+
15 rows in set（0.01 sec）

通过以上查询数据可以清晰地看到一条select语句的执行全过程，以及每一个过程的时间开销等信息，那DDL语句的执行阶段又是怎样的呢？

先对之前旧的信息进行清理，避免干扰（会话1）。

mysql> truncate events_stages_current; truncate events_stages_history; truncate events_stages_history_long;
Query OK, 0 rows affected（0.00 sec）
......

然后执行DDL语句（会话2）。

mysql> alter table sbtest1 add index i_c（c）;

现在，在会话1中查询阶段事件信息（此时DDL语句并未执行完成，从最后一行记录信息中可以看到，WORK_COMPLETED和WORK_ESTIMATED字段值不为NULL，表示该阶段事件是一个可以度量的事件）。

mysql> select THREAD_ID, EVENT_NAME, SOURCE, sys.format_time（TIMER_WAIT）as exec_time, WORK_COMPLETED, WORK_ESTIMATED from events_stages_history_long;
+-----------+--------------------+------------------+-----------+------------+-----------+
| THREAD_ID | EVENT_NAME | SOURCE | exec_time | WORK_COMPLETED | WORK_ESTIMATED |
+-----------+--------------------+------------------+-----------+------------+-----------+
| 119 | stage/sql/starting | socket_connection.cc:107 | 44.17 us | NULL | NULL |
| 119 | stage/sql/checking permissions | sql_authorization.cc:810 | 1.46 us | NULL | NULL |
| 119 | stage/sql/checking permissions | sql_authorization.cc:810 | 2.29 us | NULL | NULL |
| 119 | stage/sql/init | sql_table.cc:9031 | 2.16 us | NULL | NULL |
| 119 | stage/sql/Opening tables | sql_base.cc:5650 | 107.57 us | NULL | NULL |
| 119 | stage/sql/setup | sql_table.cc:9271 | 19.19 us | NULL | NULL |
| 119 | stage/sql/creating table | sql_table.cc:5222 | 1.06 ms | NULL | NULL |
| 119 | stage/sql/After create | sql_table.cc:5355 | 76.22 us | NULL | NULL |
| 119 | stage/sql/System lock | lock.cc:323 | 4.38 us | NULL | NULL |
| 119 | stage/sql/preparing for alter table | sql_table.cc:7454 | 28.63 ms | NULL | NULL |
| 119 | stage/sql/altering table | sql_table.cc:7508 | 3.91 us | NULL | NULL |
|119|stage/innodb/alter table（read PK and internal sort）|ut0stage.h:241|27.09 s|230040|470155 |
+-----------+--------------------+------------------+-----------+------------+-----------+
12 rows in set（0.01 sec）

等到DDL语句执行完成之后，我们再次查看阶段事件信息（会话1）。

mysql> select THREAD_ID, EVENT_NAME, SOURCE, sys.format_time（TIMER_WAIT）as exec_time, WORK_COMPLETED, WORK_ESTIMATED from events_stages_history_long;
+-----------+--------------------+------------------+-----------+------------+-------------+
| THREAD_ID | EVENT_NAME | SOURCE | exec_time | WORK_COMPLETED | WORK_ESTIMATED |
+-----------+--------------------+------------------+-----------+------------+-------------+
......
|119|stage/innodb/alter table（read PK and internal sort）|ut0stage.h:241|27.09 s|230040|470155 |
| 119 | stage/innodb/alter table（merge sort）| ut0stage.h:501 | 1.15 m | 345060 | 512319 |
| 119 | stage/innodb/alter table（insert）| ut0stage.h:501 | 11.83 s | 460146 | 523733 |
| 119 | stage/innodb/alter table（flush）| ut0stage.h:501 | 18.35 s | 523658 | 523733 |
| 119 | stage/innodb/alter table（log apply index）| ut0stage.h:501 | 54.63 ms | 524042 | 524042 |
| 119 | stage/innodb/alter table（flush）| ut0stage.h:501 | 21.18 us | 524042 | 524042 |
|119|stage/sql/committing alter table to storage engine|sql_table.cc:7535 | 5.12 us |NULL |NULL |
| 119 | stage/innodb/alter table（end）| ut0stage.h:501 | 233.52 ms | 524042 | 524042 |
......
+-----------+--------------------+------------------+-----------+------------+-------------+
24 rows in set（0.01 sec）

通过以上查询数据可以清晰地看到一条alter语句添加索引的执行全过程，以及每一个过程的时间开销等信息，执行时间最长的是stage/innodb/alter table（merge sort），其次是stage/innodb/alter table（read PK and internal sort），说明本示例中创建索引的主要时间开销在内部的排序合并操作和数据排序上。

提示：阶段事件长历史记录表中的数据生成得较快，默认的10000行配额可能很快就被打满了，可以在配置文件中把配额调整为一个较大值，以便完整地查看DDL语句的执行阶段（例如：performance_schema_events_stages_history_long_size=1000000，同时要关掉其他不相干的任务）。

6.4.2 查看SQL语句执行进度信息

在官方的MySQL版本中，在performance_schema下并没有可以很直观地查询整个语句执行进度的方法，但是可以借助后续章节中介绍的sys.session视图进行查看。

mysql> select ＊ from sys.session where conn_id! =connection_id（）\G
＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊ 1. row ＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊
              thd_id: 45
            conn_id: 4
......
              state: alter table（merge sort）
                time: 30
    current_statement: alter table sbtest1 add index i_c（c）
    statement_latency: 29.42 s
            progress: 46.40   # 进度百分比
        lock_latency: 2.19 ms
      rows_examined: 0
          rows_sent: 0
      rows_affected: 0
          tmp_tables: 0
      tmp_disk_tables: 0
          full_scan: NO
......
        program_name: mysql
1 row in set（0.33 sec）